RFR: 8079408: Reimplement TraceClassLoading, TraceClassUnloading, and TraceClassLoaderData with Unified Logging.

[Ioi Lam]

On 1/26/16 11:23 AM, Coleen Phillimore wrote:
>
> Thanks for recapping the decision.  I didn't remember it from all our 
> discussions, etc.
>
> As the one who looks at these logs and is parsing these for CDS, thank 
> you for confirming that this is intentional.  Do you really have two 
> different output files for info and debug info?

Here's an example:

$ *java -Xlog:gc=trace:file=trace.log -Xlog:gc=info:file=info.log -version*
java version "9-internal"
Java(TM) SE Runtime Environment (build 
9-internal+0-2016-01-20-150959.iklam.jdk9rt)
Java HotSpot(TM) 64-Bit Server VM (build 
9-internal+0-2016-01-20-150959.iklam.jdk9rt, mixed mode)

$*cat trace.log*
[0.002s][trace  ][gc] MarkStackSize: 4096k  MarkStackSizeMax: 16384k
[0.002s][trace  ][gc] ConcGCThreads: 0
[0.122s][info   ][gc] Using G1
[0.001s][trace  ][gc] MarkStackSize: 4096k  MarkStackSizeMax: 16384k
[0.001s][trace  ][gc] ConcGCThreads: 0
[0.102s][info   ][gc] Using G1

$ *cat info.log*
[0.102s][info   ][gc] Using G1

(There's a bug that trace.log has duplicated entries but I think that 
might be already fixed).

>
> Max/Ioi can you add a comment to the code.  This looks easily like 
> someone would "fix" because it looks funny.
>

Since we have 2 blocks of these two statements in two separate files,

if (log_is_enabled(Info, classload)) {
   ik->print_loading_log(LogLevel::Info, _loader_data, _stream);
}
if (log_is_enabled(Debug, classload)) {
   ik->print_loading_log(LogLevel::Debug, _loader_data, _stream);
}

I think it's better to consolidate them into a function inside 
instanceKlass.cpp, like:

InstanceKlass::print_loading_log(loader, stream) {
   if (log_is_enabled(Info, classload)) {
     print_loading_log(LogLevel::Info, loader_data, stream);
   }
   // Do NOT put an 'else' here, so that the following command would
   // work as expected.
   //
   // java -Xlog:classload=info:file=info.log \
   //      -Xlog:classload=debug:file=debug.log MainClass
   if (log_is_enabled(Debug, classload)) {
     print_loading_log(LogLevel::Debug, loader_data, stream);
   }
}

Thanks
- Ioi

> Thanks,
> Coleen
>
> On 1/26/16 12:31 AM, Ioi Lam wrote:
>> On 1/25/16 11:58 AM, Coleen Phillimore wrote:
>>>
>>> Hi Max,
>>>
>>> This looks pretty good.  It's a large change!  A couple of comments:
>>>
>>> http://cr.openjdk.java.net/~mockner/classload.03/src/share/vm/classfile/classFileParser.cpp.udiff.html 
>>>
>>>
>>> As Harold pointed out earlier this change should check for 'else'.
>>>
>>> *!if (_log_is_enabled(Info, classload)_) {*
>>> *!_ik->print_loading_log(LogLevel::Info, _loader_data, _stream)_;*
>>> }  else
>>> *+ if (log_is_enabled(Debug, classload)) {*
>>> *+ ik->print_loading_log(LogLevel::Debug, _loader_data, _stream);*
>>> }
>>>
>>
>> Hi Coleen,
>>
>> The case for the 'else' has been discussed before. Please refer to
>>
>> http://mail.openjdk.java.net/pipermail/hotspot-runtime-dev/2015-November/016460.html 
>>
>> http://mail.openjdk.java.net/pipermail/hotspot-runtime-dev/2015-November/016904.html 
>>
>>
>> To recap: the reason for NOT having the 'else' is for:
>>
>> java -cp ~/tmp -Xlog:classload=info:file=info.log 
>> -Xlog:classload=debug:file=debug.log Foo
>>
>> If you add the 'else' there,  the debug-level output intended for 
>> debug.log will be missing.
>>
>> OK, you may say, let's switch the order of the Info and Debug checks. 
>> But if you do that, the info.log file will have no content.
>>
>> The 'info' level looks like this
>>
>>   java.lang.Object source: /jdk/lib/modules/bootmodules.jimage
>>
>> The 'debug' level looks like this (in a single line):
>>
>>   java.lang.Object source: /jdk/lib/modules/bootmodules.jimage
>>   klass: 0x00000007c0000fb0 super: 0x0000000000000000
>>   loader: [NULL class_loader] bytes: 1640 checksum: ddb8a6f3
>>
>> Because UL buffers at the line level, I cannot split the output into 
>> two parts like this:
>>
>>   [info ][classload] java.lang.Object source: ...
>>   [debug][classload] klass: 0x00000007c0000fb0 super: ...
>>
>> Otherwise some unrelated output may be interleaved between the two 
>> lines, making the output impossible to parse. The ability to parse 
>> the output is very important to tools that analyze the class loading 
>> behavior (e.g., tools related to CDS).
>>
>> Due to this limitation of UL, I think our only choice is to repeat 
>> the class name and 'source' in both info and debug levels, hence NO 
>> 'else' in the code you quoted:
>>
>>   [info ][classload] java.lang.Object source: ..
>>   [debug][classload] java.lang.Object source: .. klass: .. super: ..
>>
>> Thanks
>> - Ioi
>>
>>
>>
>