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

[Ioi Lam]

> On Jan 26, 2016, at 3:53 PM, David Holmes <david.holmes at oracle.com> wrote:
> 
>> On 27/01/2016 8:58 AM, Ioi Lam wrote:
>> 
>> 
>>> 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);
>>   }
> 
> I don't think we need to be so explanatory here, a simple:
> 
>  // Not 'else' here as logging levels are not mutually exclusive
> 
> should suffice.
> 

Conciseness would be good, but I am not sure if the above is clear or correct. -Xlog:classload=debug implies outputs from the info level as well, so they are not mutually exclusive.

UL is nice in many ways, but it's just not as easy to explain as: here's a Boolean variable :-(



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