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

Wed Nov 11 10:36:01 UTC 2015

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 (log_is_enabled(Debug, classload)) {
>> +      outputStream* log = LogHandle(classload)::debug_stream();
>> +      log->print_cr("[Opened %s]", path);
>> +    }
>>
>>
>> There's no reason to do this.  You can replace simply with one line:
>>       log_debug(classload)("[Opened %s]", path);
>>
>> What you have is testing whether log_is_enabled 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 (log_is_enabled(Trace, classloaderdata) && class_loader() 
>> != NULL) {
>> +        outputStream* log = LogHandle(classloaderdata)::trace_stream();
>> +        log->print_cr("is_anonymous: %s", 
>> class_loader()->klass()->internal_name(
>>
>> I think this would be neater as:
>>
>> +      if (class_loader() != NULL) {
>> +        log_trace(classloaderdata)("is_anonymous: %s", 
>> class_loader()->klass()->internal_name(
>>
>> 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.
>>
>>     Pause_No_Safepoint_Verifier 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 (log_is_enabled(Debug, classload)) {
>> +      this_klass()->print_loading_log(LogLevel::Debug, loader_data, 
>> cfs);
>> +    }
>> +    if (log_is_enabled(Trace, classload)) {
>> +      this_klass()->print_loading_log(LogLevel::Trace, loader_data, 
>> cfs);
>> +    }
>> +
>>
>> I think this should be
>>
>> +    if (log_is_enabled(Debug, classload)) {
>> +      this_klass()->print_loading_log(loader_data, cfs);
>>
>> and then check for trace level inside of print_loading_log (debug 
>> will include trace, I believe).
>>

Yes, log_is_enabled(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 
> class_loader] 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.

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/:hotspot_all
>>>     vm.parallel_class_loading.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
>>
>