RFR (S) 8079408 - Improve class loading log (with unified logging) (original) (raw)

Ioi Lam ioi.lam at oracle.com
Mon Nov 30 10:44:39 UTC 2015

I've update the patch:

http://cr.openjdk.java.net/~iklam/8079408-improve-class-load-log.v2/

[1] No longer do the "log->print_cr("[Opened %s]", path);" in the "classload" traces, as these aren't related to class loading. If we really want to support them in uL we need a different tag.

[2] Cleaned up the code as Coleen suggested below.

[3] I decided to keep the duplicated data between the "debug" and "trace" levels, as that's probably the easiest way for people to parse the output.

BTW, maybe this patch should be combined with Max's classunload patch in a single changeset for consistency and ease of tracking?

Thanks

On 11/12/15 2:41 AM, Marcus Larsson wrote:

On 2015-11-12 03:12, Ioi Lam wrote:

On Nov 11, 2015, at 6:36 PM, Marcus Larsson <marcus.larsson at oracle.com> wrote:

Hi,

On 2015-11-11 02:30, Ioi Lam wrote: Thanks Coleen. I will integrate all of your comments and send a new webrev. Only one point below:

On 11/10/15 3:39 PM, Coleen Phillimore wrote:

Ioi, Nice logging conversion. http://cr.openjdk.java.net/~iklam/8079408-improve-class-load-log/src/share/vm/classfile/classLoader.cpp.udiff.html

+ if (logisenabled(Debug, classload)) { + outputStream* log = LogHandle(classload)::debugstream(); + log->printcr("[Opened %s]", path); + } There's no reason to do this. You can replace simply with one line: logdebug(classload)("[Opened %s]", path); What you have is testing whether logisenabled for Debug/classload tag twice and it's 4 lines and a conditional rather than one line. http://cr.openjdk.java.net/~iklam/8079408-improve-class-load-log/src/share/vm/classfile/classLoaderData.cpp.udiff.html Same comment: + if (logisenabled(Trace, classloaderdata) && classloader() != NULL) { + outputStream* log = LogHandle(classloaderdata)::tracestream(); + log->printcr("isanonymous: %s", classloader()->klass()->internalname( I think this would be neater as: + if (classloader() != NULL) { + logtrace(classloaderdata)("isanonymous: %s", classloader()->klass()->internalname( For two of these. http://cr.openjdk.java.net/~iklam/8079408-improve-class-load-log/src/share/vm/classfile/classLoaderData.cpp.udiff.html Can you make the logging code a new function, rather than glomming it on the end of the function? In your function you can pause the nosafepoint verifier instead. PauseNoSafepointVerifier pnsv(&nsv); http://cr.openjdk.java.net/~iklam/8079408-improve-class-load-log/src/share/vm/prims/jvmtiEnv.cpp.udiff.html Same comment. http://cr.openjdk.java.net/~iklam/8079408-improve-class-load-log/src/share/vm/classfile/classFileParser.cpp.udiff.html + if (logisenabled(Debug, classload)) { + thisklass()->printloadinglog(LogLevel::Debug, loaderdata, cfs); + } + if (logisenabled(Trace, classload)) { + thisklass()->printloadinglog(LogLevel::Trace, loaderdata, cfs); + } + I think this should be + if (logisenabled(Debug, classload)) { + thisklass()->printloadinglog(loaderdata, cfs); and then check for trace level inside of printloadinglog (debug will include trace, I believe). Yes, logisenabled(Debug, ...) is also true if logging is configured on Trace level. The problem is someone may want "both" debug and trace logs, but in "separate" files. I am not sure if this is an intended feature of the UL design but it certainly looks valid to me: java -cp ~/tmp -Xlog:classload=trace:file=trace.log -Xlog:classload=debug:file=debug.log Foo So I have to do the test twice, and print out things twice. Or else debug.log will have no output in it. This is indeed a valid use case, but maybe it doesn't do what you think it does. trace.log will contain all logging up to trace level (error, warning, info, debug and trace). debug.log will contain all logging up to debug level (error, warning, info and debug). In other words, every line in debug.log will also be found in trace.log, but trace.log will in addition to this also contain log messages on trace level. It is not possible to configure only a specific level for an output (other than for Error, since it's the first level) - they are always aggregated. Of course, the problem with what I am doing now, is that if you are using a single log file, and you specify trace, then you get duplicated logs like this: java -cp ~/tmp -Xlog:classload=trace:file=trace.log Foo I.e., two lines for java.lang.Object [0.262s][debug ][classload] java.lang.Object source: /jdk/bld/ul/images/jdk/lib/modules/bootmodules.jimage [0.431s][trace ][classload] java.lang.Object source: /jdk/bld/ul/images/jdk/lib/modules/bootmodules.jimage klass: 0x00000007c0000fb0 super: 0x0000000000000000 loader: [NULL classloader] bytes: 1640 checksum: ddb8a6f3 Marcus, what's your take on this? The main problem seems to be that the function wants to log different amounts of information on a single line, depending on the log level. A log message on debug level shouldn't depend on whether or not logging is on trace level, it should really only include debug level stuff. I understand you want different amounts of information depending on the level, but this would ideally be achieved by having multiple log messages, one with the debug level information, and a different log message with the trace level information. Possibly the end result might have to look similar to your example above, where some identification information is duplicated between debug and trace levels, but I think that's OK. If the log is split into 2 separate lines, it's hard to correlate them since you can have other concurrent logs interspersed between them. In my particular case, the debug level doesn't have enough info to be unique. It has only class name and code source, but multiple loaders can load a class with the same name and code source. So I can't correlate it with a 'trace' line unless I add more info into the 'debug' line, which kind of defeats the purpose of a 'simpler' output. I feared this was the case here. Maybe I'll just get rid of the simpler output altogether, and always write the full details? It would be pretty easy for the reader of the log to trim out info that it doesn't need. The down side is slower speed and more lengthy output even if you don't need it. What do you think? Depends on if you really want to avoid the duplication, or if it would be acceptable that some logging is duplicated between the debug and trace level, just like in your example. Having some duplicated data in the trace level doesn't sound too bad to me really. Trace level logging is allowed to be noisy. I guess it also depends on the usefulness of the debug level information. If the common scenario is to just require the debug messages, then we should allow that without any added noise. Thanks, Marcus Ioi Thanks, Marcus - Ioi Coleen

On 11/9/15 6:49 PM, Ioi Lam wrote: Please review a small fix, related to unified logging: http://cr.openjdk.java.net/~iklam/8079408-improve-class-load-log/ Bug: 8079408 Improve class loading log (with unified logging) https://bugs.openjdk.java.net/browse/JDK-8079408 Summary of fix: This fix has 2 parts: [a] Reimplement TraceClassData and TraceClassLoading as -Xlog:classloaderdata and -Xlog:classload [b] Add more detailed info to -Xlog:classload so we can perform more analysis Example: _java -Xlog:classloaderdata=debug,classload=trace:file=log.txt _ -cp ~/tests Hello I have completely replaced TraceClassData with -Xlog:classloaderdata. The TraceClassData flag has been removed from globals.hpp. Since many existing tools use TraceClassLoading, I think it's better to deprecate it, but otherwise don't change how it works. Instead, we add a new -Xlog:classload flag that's independent of the old TraceClassLoading flag. (note: the deprecation of TraceClassLoading will be done in a separate bug). I have also not tied "-verbose:class" with the classload log, since I think "-verbose:class" is obsolete and should be replaced by -Xlog. Tests: RBT: I ran these testlists using RBT (more than 20000 total classes on Linux/Windows/MacOS/solaris) and saw no new failures. I think this means no existing tests depend on the removed -XX:+TraceClassLoaderData flag. hotspot/test/:hotspotall vm.parallelclassloading.testlist vm.regression.testlist vm.runtime.testlist vm.tmtools.testlist nsk.sajdi.testlist nsk.stress.testlist nsk.stress.jck.testlist vm.gc.testlist vm.metaspace.testlist Thanks - Ioi

More information about the hotspot-runtime-dev mailing list