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

[Ioi Lam]

> On Jan 26, 2016, at 4:26 PM, David Holmes <david.holmes at oracle.com> wrote:
> 
>> On 27/01/2016 10:20 AM, Ioi Lam wrote:
>> 
>> 
>>>> 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.
> 
> Yes that is what I said "logging levels are not mutually exclusive". Hence it isn't either/or, and so not if/else.
> 

Oh I missed the 'not'. Need a bigger iPhone!


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