[prev in list] [next in list] [prev in thread] [next in thread]
List: openjdk-serviceability-dev
Subject: Re: RFR: 8141211: Convert TraceExceptions to Unified Logging
From: Rachel Protacio <rachel.protacio () oracle ! com>
Date: 2015-12-23 16:08:16
Message-ID: 567AC6F0.5030803 () oracle ! com
[Download RAW message or body]
Thank you, David!
Rachel
On 12/22/2015 11:26 PM, David Holmes wrote:
> 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
>>>>>>>>>
>>>>>>>>
>>>>>>
>>>>
>>
[prev in list] [next in list] [prev in thread] [next in thread]
Configure |
About |
News |
Add a list |
Sponsored by KoreLogic