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

[David Holmes]

On 27/01/2016 7:39 AM, Ioi Lam wrote:
>
>
> On 1/26/16 12:48 PM, David Holmes wrote:
>> On 27/01/2016 6:44 AM, Max Ockner wrote:
>>> David,
>>> In general, we want to keep logging messages the same as before. This
>>> fix contains changes to the logging output as well.
>>
>> Why are we changing the logging output? And why mix the two changes?
>>
>
> David,
>
> OLD:
>
> [Loaded xxx from yyyy]
>
> NEW:
>
> [info ][classload] xxx source: yyyy
>
> Keeping the "Loaded" there seems superfluous. It would look like
>
> [info ][classload] Loaded xxx source: yyyy
>
> The point of UL is to remove the need for ad-hoc tags such as "Loaded".
>
> Also, the original [] brackets are inconsistent with the UL style, so
> they are removed.
>
> I think it's better to change over to the new UL style rather than
> keeping the older odd style. Even if we don't, the addition of the
> [info][classload] characters would break some scripts anyway (e.g., my
> old scripts would grep for "*^\\[Loaded*" , so we can't get 100%
> backwards compatibility.
>
> The GC UL changes would also break existing scripts (such as those
> analyzing pause times, etc), so we are not the only one here.

Well I hope there will be a lot of documentation/release-note entries 
about the impact of UL.

Thanks,
David
-----

> - Ioi
>
>> Thanks,
>> David
>>
>>> Max
>>> On 1/26/2016 3:33 PM, David Holmes wrote:
>>>> On 27/01/2016 6:25 AM, Max Ockner wrote:
>>>>> I am working on changing the affected tests to look for the proper
>>>>> output.
>>>>
>>>> Late to the party but should we not be trying to maintain the existing
>>>> basic format of the log messages so that anyone who already regularly
>>>> uses -verbose:class and has scripts etc that check this, will still
>>>> see basic things like:
>>>>
>>>> [Loaded xxx from yyyy]
>>>>
>>>> ?
>>>>
>>>> David
>>>>
>>>>  -Max
>>>>>
>>>>> On 1/26/2016 2:23 PM, 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?
>>>>>>
>>>>>> Max/Ioi can you add a comment to the code.  This looks easily like
>>>>>> someone would "fix" because it looks funny.
>>>>>>
>>>>>> 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
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>
>>>>>
>>>
>