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

[Ioi Lam]

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).
>
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.

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?

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