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

Max Ockner max.ockner at oracle.com
Tue Jan 26 21:04:43 UTC 2016


This changeset is a combination of two smaller changes:
1) Ioi's classload/classloaderdata changeset
2)My classunload changeset.

Ioi's changeset includes changes to the classload output. I have taken 
his advice during the review process and some output has been changed 
for classunload as well.

These changes are mixed because logging for class loading and class 
unloading can be triggered together by -verbose:class, and it was much 
easier to convert both at the same time than it would have been to come 
up with a temporary fix for -verbose:class.

I think Ioi can explain why the logs are changing better than I can, so 
hopefully he can offer his perspective on this.

-Max

On 1/26/2016 3: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?
>
> 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
>>>>>>
>>>>>>
>>>>>>
>>>>>
>>>>
>>



More information about the hotspot-runtime-dev mailing list