Re: RFR: 8141211: Convert TraceExceptions to Unified Logging

[David Holmes]

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.

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