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

[David Holmes]

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.

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