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

[Ioi Lam]

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.

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