RFR: 8141211: Convert TraceExceptions to Unified Logging
Rachel Protacio
rachel.protacio at oracle.com
Tue Dec 22 21:33:51 UTC 2015
Great, thanks! I'll check it in.
Rachel
On 12/22/2015 4:30 PM, Max Ockner wrote:
> 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