RFR: 8141211: Convert TraceExceptions to Unified Logging
Max Ockner
max.ockner at oracle.com
Tue Dec 22 21:30:39 UTC 2015
Looks good!
Max
On 12/21/2015 5:14 PM, Rachel Protacio wrote:
> Thanks, Coleen!
> Rachel
>
> On 12/21/2015 5:03 PM, Coleen Phillimore wrote:
>>
>> People should add more of the discussion that we had in this thread
>> and more about the requirements for the ttyLocker replacement in the
>> bug that Rachel filed.
>>
>> I think this looks good for TraceExceptions conversion to UL.
>>
>> Thanks,
>> Coleen
>>
>>
>> On 12/21/15 4:46 PM, 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 hotspot-runtime-dev
mailing list