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

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
- Ioi



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 (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