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 printthe entire line at once to the log streamI 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, DavidThanks! RachelThanks, DavidRetested 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 toprint 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.01src/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! RachelThanks, DavidThanks, 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:I assumed that UL worked as-is for these instances, but I will checkHi 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 ofmulti-line logging blocks that are going to be completely messed upwithout locking!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 +20852087 logstream->print("Async. exception installed at runtimeexit (" 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!That was a vestige from code before a new changeset at the same line,2092 logstream->print_cr(" of type: %s",InstanceKlass::cast(_pending_async_exception->klass())->external_name());Why did the InstanceKlass::cast need to be introduced ??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 intothe 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.cppand .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 itshould disable exception logging - which may have been turned on by-Xlog:all. Which leads to: how does the position of -XX:+/-TraceExceptionsinteract with the position of -Xlog:xxx on the command-line (or theother 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, RachelThanks, David -----Open webrev: http://cr.openjdk.java.net/~rprotacio/8141211/ Bug: https://bugs.openjdk.java.net/browse/JDK-8141211Testing: jtreg, JPRT, jck vm tests, refworkload performance tests,rbt quick & non-colo tests Thank you! Rachel
