RFR: 8141211: Convert TraceExceptions to Unified Logging
Rachel Protacio
rachel.protacio at oracle.com
Mon Dec 21 21:46:02 UTC 2015
Hi,
Please take a look at my updated changeset! Webrev:
http://cr.openjdk.java.net/~rprotacio/8141211.02/
I've fixed the multi-line statements as requested, i.e. put newlines in
them to replicate the original format.
Since the UL framework atomically writes complete messages, these single
string messages do not need the discussed lockers to prevent
interleaving. So it's ready to be checked in as-is (once reviewed, of
course). I've opened a separate RFE for lockers, which will be necessary
for other logging https://bugs.openjdk.java.net/browse/JDK-8145934
Thank you,
Rachel
On 12/16/2015 6:39 PM, David Holmes wrote:
> Hi Rachel,
>
> On 17/12/2015 7:33 AM, Rachel Protacio wrote:
>> Hi,
>>
>> On 12/16/2015 3:52 PM, David Holmes wrote:
>>> Hi Rachel,
>>>
>>> On 16/12/2015 6:26 AM, Rachel Protacio wrote:
>>>> 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
>>>
>>> I think I may be missing something here, sorry. Taking
>>> src/share/vm/interpreter/bytecodeInterpreter.cpp as an example, three
>>> print_cr statements have been replaced with one log_info statement -
>>> but there are no newlines in-line in that one log_info statement. I
>>> was assuming that a single call to something like log_info would be
>>> 'atomic" and that we would manually place the \n as required in the
>>> output string.
>>>
>>> This won't show up well in email due to line wrapping but going from
>>> this:
>>>
>>> Exception <a 'java/lang/ClassNotFoundException':
>>> sun.launcher.resources.launcher_en_US> (0x0000000101c69b18)
>>> thrown in interpreter method <{method} {0x00007f55b63dbc18}
>>> 'loadClass' '(Ljava/lang/String;Z)Ljava/lang/Class;' in 'java/lang/Cl>
>>> at bci 70 for thread 0x00007f56d0019800
>>>
>>> to this:
>>>
>>> Exception <a 'java/lang/ClassNotFoundException':
>>> sun.launcher.resources.launcher_en_US> (0x0000000101c69b18) thrown in
>>> interpreter method <{method} {0x00007f55b63dbc18} 'loadClass'
>>> '(Ljava/lang/String;Z)Ljava/lang/Class;' in 'java/lang/Cl> at bci 70
>>> for thread 0x00007f56d0019800
>>>
>>> will not be anywhere as near as clear in the logs.
>> Yes, I changed that intentionally. The choices as I saw them were:
>> (a) multiple print_cr() calls, which could lead to unwanted interweaving
>> and which breaks up the logging message with decorators at the beginning
>> of every line, e.g.
>>
>> [0.225s][info ][exceptions] Exception <a
>> 'java/lang/ClassNotFoundException': NoClassFound>
>> (0x00000006d5f5ae28)
>> [0.225s][info ][exceptions] thrown in interpreter method <{method}
>> {0x00007fe231a04198} 'findClass'
>> '(Ljava/lang/String;)Ljava/lang/Class;' in 'java/net/URLC>
>> [0.225s][info ][exceptions] at bci 44 for thread
>> 0x00007fe330019000
>>
>> (b) adding newlines in the middle of the message, which would look like
>>
>> [0.225s][info ][exceptions] Exception <a
>> 'java/lang/ClassNotFoundException': NoClassFound>
>> (0x00000006d5f5ae28)
>> thrown in interpreter method <{method} {0x00007fe231a04198}
>> 'findClass' '(Ljava/lang/String;)Ljava/lang/Class;' in
>> 'java/net/URLC>
>> at bci 44 for thread 0x00007fe330019000
>>
>> and could easily end up wrapping mid-logging anyway depending on the
>> length of the exception message
>> (c) turning it all into one wrapped line that would be relatively easier
>> to programmatically parse since the decorators would be at the beginning
>> of the line, i.e.
>>
>> [0.225s][info ][exceptions] Exception <a
>> 'java/lang/ClassNotFoundException': NoClassFound>
>> (0x00000006d5f5ae28) thrown in interpreter method <{method}
>> {0x00007fe231a04198} 'findClass'
>> '(Ljava/lang/String;)Ljava/lang/Class;' in 'java/net/URLC>at bci 44
>> for thread 0x00007fe330019000
>>
>> which is also the most compact option.
>>
>> So I opted for (c). But if I should stick to the original approach, i.e.
>> (b), I can see it could be easier to visually parse. Do you think that
>> would be preferable?
>
> I definitely vote for (b) - I think a goal of the conversion effort
> should be that if you disable the UL decorators then the output before
> and after the conversion should be the same. Decorators can be useful
> but also clutter.
>
> But I'm also worried that the UL framework might not atomically
> process a line with embedded newlines. Though in that case the fix
> needs to be in the UL framework.
>
> Thanks,
> David
>
>> Thanks!
>> Rachel
>>
>>>
>>> Thanks,
>>> David
>>>
>>>> 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
>>>>>>>
>>>>>>
>>>>
>>
More information about the serviceability-dev
mailing list