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

Marcus Larsson marcus.larsson at oracle.com
Thu Nov 12 10:41:41 UTC 2015



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 (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.
> 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/: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



More information about the hotspot-runtime-dev mailing list