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

David Holmes david.holmes at oracle.com
Tue Jan 26 23:53:04 UTC 2016


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.

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


More information about the hotspot-runtime-dev mailing list