RFR: 8141211: Convert TraceExceptions to Unified Logging

Tue Dec 15 20:26:02 UTC 2015

Hi,

Thanks for the comments, David.

I had messed up my uploading before and had not actually updated the 
open html. So for real this time, the most recent webrev is at 
http://cr.openjdk.java.net/~rprotacio/8141211.01/ Of note:
- each incident of ttyLocker that involved separate logging lines for 
the same message have been consolidated to one line
- each incident of ttyLocker that involved separate print statements to 
one logging line has been changed to write to a buffer first, then print 
the entire line at once to the log stream

Retested with JPRT, and the buffer-to-logstream schema in particular 
works fine.

Replies inline.

On 12/13/2015 11:08 PM, David Holmes wrote:
> Hi Rachel,
>
> On 12/12/2015 7:38 AM, Rachel Protacio wrote:
>> Hello! An update and updated webrev.
>>
>> I've rewritten the two portions of code that had used ttyLockers to
>> print in one function-call, since there is no locker equivalent in UL,
>> plus the fact that it will be easier for users to look for one message's
>> contents without the decorators interrupting the lines. (And I
>> especially tested that the fix prints the whole line correctly.)
>
> Sorry I'm still seeing ttyLocker removal and use of multiple logging 
> statements in:
>
> src/share/vm/interpreter/bytecodeInterpreter.cpp
> src/share/vm/interpreter/interpreterRuntime.cpp
> src/share/vm/opto/runtime.cpp
>
> which "two portions of code" did you change?
I apologize for that! I messed up with uploading the changeset before. 
All fixed now in each of those files.
>
> I also note that src/share/vm/runtime/thread.cpp was not using 
> ttyLocker but does have multi-part trace output.
True. Since a locker was unnecessary in the first place, I think it 
makes sense to allow this (and other logging, both in UL and the 
existing tty frameworks) to be printed in multiple steps. What do you think?
>
>> As mentioned in the other thread, I will file a separate RFE to
>> deprecate this and other product flags being converted to logging.
>>
>> Since my last iteration was on hold/not reviewed yet, I've simply
>> updated it. http://cr.openjdk.java.net/~rprotacio/8141211.01
>
> src/share/vm/c1/c1_Runtime1.cpp
>
> Nit in original code:
>
> 556                            " for thread " INTPTR_FORMAT "",
>
> the "" before the comma seems superfluous.
Thanks for pointing that out!
Rachel
>
> Thanks,
> David
>
>> Thanks,
>> Rachel
>>
>> On 12/9/2015 1:12 PM, Rachel Protacio wrote:
>>> Hi,
>>>
>>> (Sorry if this sent twice. Thunderbird is acting up.)
>>>
>>> Thanks for the review. Replies inline.
>>> Updated webrev: http://cr.openjdk.java.net/~rprotacio/8141211.01/
>>>
>>> On 12/8/2015 10:53 PM, David Holmes wrote:
>>>> Hi Rachel,
>>>>
>>>> On 9/12/2015 1:42 AM, Rachel Protacio wrote:
>>>>> Hello,
>>>>>
>>>>> Please review my conversion of -XX:+TraceExceptions to
>>>>> -Xlog:exceptions=info. The existing (product) flag is aliased to the
>>>>> logging flag at the info level.
>>>>
>>>> Q: how does use of ttyLocker map into UL? I see an awful lot of
>>>> multi-line logging blocks that are going to be completely messed up
>>>> without locking!
>>> I assumed that UL worked as-is for these instances, but I will check
>>> in with Marcus.
>>>>
>>>> src/share/vm/opto/runtime.cpp
>>>>
>>>> 1239     ResourceMark rm;
>>>>
>>>> What requires the introduction of the ResourceMark?
>>> A ResourceMark is necessary before using LogHandle output streams.
>>>>
>>>> ---
>>>>
>>>> src/share/vm/runtime/thread.cpp
>>>>
>>>> 2084       if (log_is_enabled(Info, exceptions)) {
>>>> 2085          ResourceMark rm;
>>>>
>>>> An extra leading space has crept in at +2085
>>>>
>>>> 2087         logstream->print("Async. exception installed at runtime
>>>> exit (" INTPTR_FORMAT ")", p2i(this));
>>>> 2088          if (has_last_Java_frame()) {
>>>> 2089            frame f = last_frame();
>>>> 2090           logstream->print(" (pc: " INTPTR_FORMAT " sp: "
>>>> INTPTR_FORMAT " )", p2i(f.pc()), p2i(f.sp()));
>>>> 2091          }
>>>>
>>>> Indention of these lines is wrong at #2088 and #2089 - need an
>>>> additional space.
>>> Thanks for catching these!
>>>>
>>>> 2092         logstream->print_cr(" of type: %s",
>>>> InstanceKlass::cast(_pending_async_exception->klass())->external_name()); 
>>>>
>>>>
>>>>
>>>> Why did the InstanceKlass::cast need to be introduced ??
>>> That was a vestige from code before a new changeset at the same line,
>>> i.e. my merging the repo didn't catch this. I've gotten rid of the 
>>> cast.
>>>>
>>>> ---
>>>>
>>>> test/runtime/CommandLine/TraceExceptionsTest.java
>>>>
>>>> You improved the readability of the source code by breaking the
>>>> @summary over two lines, but IIRC jtreg will write the summary into
>>>> the test log with all the additional spaces you added, as the summary
>>>> extends until the next tag.
>>> Ok, I didn't realize that! I've undone that change.
>>>>
>>>> ---
>>>>
>>>> test/runtime/logging/ExceptionsTest.java
>>>>
>>>> Can you avoid the code duplication please.
>>>>
>>>> Also perhaps you could/should also check there are no logging
>>>> statements present when logging is supposed to be disabled. I'm
>>>> guessing the other logging tests haven't considered this. ??
>>> Good points. I've added a check.
>>>>
>>>>> If you have any questions on the alias table (in the arguments.cpp 
>>>>> and
>>>>> .hpp files), Max will chime in as he is the one who implemented that
>>>>> portion.
>>>>
>>>> Okay some general questions.
>>>>
>>>> First I would expect that aliased logging options are also marked
>>>> deprecated so that we can eventually make them obsolete and remove 
>>>> them.
>>> I'm not sure about this one. Coleen? Max?
>>>>
>>>> Secondly, arguably if someone specifies -XX:-TraceExceptions it
>>>> should disable exception logging - which may have been turned on by
>>>> -Xlog:all.
>>>>
>>>> Which leads to: how does the position of -XX:+/-TraceExceptions
>>>> interact with the position of -Xlog:xxx on the command-line (or the
>>>> other argument introducing mechanisms) ?
>>> Very true. I've added an entry in the alias table to that effect.
>>>>
>>>> src/share/vm/runtime/arguments.cpp
>>>>
>>>> 2743 if(lookup_logging_aliases(option->optionString,
>>>> aliased_logging_option)){
>>>>
>>>> Need space after "if", and before {
>>> Done.
>>>
>>> Thanks,
>>> Rachel
>>>>
>>>> Thanks,
>>>> David
>>>> -----
>>>>
>>>>
>>>>> Open webrev: http://cr.openjdk.java.net/~rprotacio/8141211/
>>>>> Bug: https://bugs.openjdk.java.net/browse/JDK-8141211
>>>>>
>>>>> Testing: jtreg, JPRT, jck vm tests, refworkload performance tests, 
>>>>> rbt
>>>>> quick & non-colo tests
>>>>>
>>>>> Thank you!
>>>>> Rachel
>>>
>>