RFR: 8141211: Convert TraceExceptions to Unified Logging
David Holmes
david.holmes at oracle.com
Wed Dec 23 04:26:55 UTC 2015
Thanks Rachel - looks good.
David
On 22/12/2015 7:46 AM, Rachel Protacio wrote:
> 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