RFR: 8154791: Xlog classload too redundant msgs info/debug
Ioi Lam
ioi.lam at oracle.com
Tue May 2 21:10:44 UTC 2017
By the way, I think we should really fix this in the UL level -- have
multi-line buffering, so you can prevent other threads from interleaving
your input. Make it something like:
Log(class, load).start_buffering();
log_info(class, load)(class name and source);
log_debug(class, load)(other details);
Log(class, load).flush();
That way, the output will look like this:
[0.162s][debug ][class,load] java.lang.Comparable source: jrt:/java.base
[0.162s][debug ][class,load] [NULL class_loader] 0x00000007c00013a8
super: 0x00000007c0000fb0 bytes: 235 checksum: a75dadb6
So the output will be terse, and still parsable.
I think this will be useful for other types of logs as well, not just
the class loading logs.
Thanks
- Ioi
On 5/2/17 1:56 PM, Ioi Lam wrote:
>
>
> On 5/2/17 1:31 PM, Rachel Protacio wrote:
>> Hi Ioi,
>>
>> Thanks for your reply, comments inline.
>>
>>
>> On 5/2/2017 2:48 PM, Ioi Lam wrote:
>>> Hi Rachel,
>>>
>>> There are a few reasons why the current output has duplications. The
>>> "logging levels are not mutually exclusive" comment means this:
>>>
>>> java -Xlog:class+load=debug:file=debug.log
>>> -Xlog:class+load=info:file=info.log
>>>
>>> So info.log contains only the info level logs, but debug.log
>>> contains both info and debug level logs.
>>>
>>> Ideally I want info.log to contain this:
>>>
>>> [0.162s][info ][class,load] java.lang.Comparable source: jrt:/java.base
>>>
>>> .. and debug.log to contain this:
>>>
>>> [0.162s][debug ][class,load] java.lang.Comparable source:
>>> jrt:/java.base [NULL class_loader] 0x00000007c00013a8 super:
>>> 0x00000007c0000fb0 bytes: 235
>>> checksum: a75dadb6
>> I see what you want, but I think the problem is that logging doesn't
>> work that way. If debug is specified, both debug and info levels are
>> printed. So the command
>>
>> java -Xlog:class+load=debug:file=debug.log
>>
>> will print both info level logging and debug level logging to this
>> "debug.log" file. And then tacking on
>>
>> -Xlog:class+load=info:file=info.log
>>
>> in the command would print just the info level logging to the
>> "info.log" file. But since it's all the same java command, it will
>> always know that both debug and info levels are specified. I believe
>> what you want me to do is say "if debug is specified, print
>> everything to debug only" but then the info.log would be empty. You
>> would have to run a separate java command with just the info level
>> specified to get the smaller amount of information.
>
> No, that's not what I want. I am perfectly fine with how UL works
> today: info.log contains only the info level, and debug.info contains
> both debug and info level.
>
> All I want is everything related to the same class to be printed on
> the same line. For example, I don't want debug.log to contain this:
>
> [0.162s][info ][class,load] java.lang.Comparable source: jrt:/java.base
> [0.162s][debug ][class,load] [NULL class_loader] 0x00000007c00013a8
> super: 0x00000007c0000fb0 bytes: 235 checksum: a75dadb6
>
> That's because it's impossible to associated the second with the first
> line when you have parallel threads loading classes concurrently.
>
>> But I think that would violate user expectations - if they get
>> certain information with info logging, adding the extra level of
>> debug logging should not change what they see from the info logging.
>>>
>>> Your current patch splits out the debug log into several lines. This
>>> makes it difficult to analyze the log when classes are loaded
>>> concurrently on different threads:
>>>
>>> [0.162s][info ][class,load] java.lang.Comparable source: jrt:/java.base
>>> [0.162s][info ][class,load] java.lang.Comparable loader: [NULL
>>> class_loader]
>>> [0.162s][debug][class,load] java.lang.Comparable klass:
>>> 0x00000007c00013a8
>>> [0.163s][info ][class,load] java.lang.String source: jrt:/java.base
>>> <<< oops! from a different thread
>>> [0.164s][debug][class,load] java.lang.Comparable super:
>>> 0x00000007c0000fb0
>>> [0.164s][info ][class,load] java.lang.Comparable bytes: 235
>>> [0.164s][info ][class,load] java.lang.Comparable checksum: a75dadb6
>> That's fair. I was trying to make it more readable since it's hard to
>> visually parse one giant line. Maybe I could put some delimiter in
>> between each piece of info? But if no one else cares, I can just put
>> it back as one line, no delimiters.
>>>
>>> Because the leveling in UL is by lines, in JDK-8079408, where this
>>> was first implemented, I couldn't find a way to print
>>> "java.lang.Comparable source: jrt:/java.base" in "info" mode, and
>>> print the rest in "debug" mode, while keeping the whole thing on the
>>> same line (in both the info.log and debug.log files). That's why we
>>> have the 2 lines with duplicated info.
>>>
>>> I think it's really important to keep everything on the same line
>>> (the output needs to be processed automatically by scripts). With
>>> the current UL restrictions, I think the only way to do it is make
>>> the "info" logging more verbose when "debug" level is selected. E.g.,
>>>
>>> outputStream* info_log = Log(class, load)::info_stream();
>>> info_log->print("%s", ext_name);
>>> info_log->print_cr(" source: jrt:/%s", module_name); ....
>>>
>>> if (log_is_enabled(Debug, class, load)) { // always print to info
>>> log, even if debug is selected
>>> info_log->print(" klass: " INTPTR_FORMAT, p2i(this));
>>> ....
>>> }
>>>
>>> So now info.log and debug.log will have the same logs, but oh well
>>> .....
>> This sounds a little different. It sounds like
>>
>> When only info is specified, info log will contain: external name,
>> source, loader, bytes, checksum
>>
>> When debug is specified, info log will contain the same as above,
>> plus: klass, super, interfaces
>> When debug is specified, debug log will be an exact duplicate of
>> info log so it can print to an external file
>>
>> Did I understand that right? Please correct me. If this is what you
>> meant, I would again argue that this violates the expectation that
>> "info is info is info" regardless of what else is specified (not a
>> written rule, but how I think it should work). And it is redundant,
>> which is the original issue in the name of this RFE.
>>
>> I think the best bet would be
>>
>> Info log: external name, source, loader, bytes, checksum
>> Debug log: external name, klass, super, interfaces
>>
>> Or we get rid of the level distinction completely and put all the
>> information together in one line so it never gets broken up. Probably
>> under debug.
>>
>
> We need to keep the current debug output intact, on a single line, so
> that the information can be processed by scripts.
>
> So, it seems like our 3 choices are:
>
> (1) make the info output the same as debug, if -Xlog:class+load=debug
> is specified
> (2) remove the info output altogether
> (3) do nothing
>
> You don't like (1).
>
> I don't think (2) achieves what this RFE wants -- namely, make the
> output less redundant, because you will see all the details all the
> time, and you don't even get a choice for more terse output. It also
> makes the output of -verbose different (and much less useful) than in
> JDK 9.
>
> So I would vote for (3), keep the output as is. Yeah, with debug level
> you have a lot of output, but that's pretty easy to filter. I think we
> had a discussion about this when 8079408 was implemented, and that was
> the conclusion we had.
>
> Thanks
> - Ioi
>
>> Let me know what you think.
>>
>> Thanks,
>> Rachel
>>
>>>
>>> Thanks
>>> - Ioi
>>>
>>> On 5/2/17 10:32 AM, Rachel Protacio wrote:
>>>> Hello!
>>>>
>>>> Please review this enhancement correcting redundancies and
>>>> neatening up the -Xlog:class+load code. The redundancy in the code
>>>> before I believe stemmed from a misunderstanding about logging
>>>> levels (the comment saying they are not mutually exclusive was
>>>> misleading).
>>>>
>>>> Tested with JPRT and RBT.
>>>>
>>>> Bug: https://bugs.openjdk.java.net/browse/JDK-8154791
>>>> Webrev: http://cr.openjdk.java.net/~rprotacio/8154791.00
>>>>
>>>> Thanks,
>>>> Rachel
>>>
>>
>
More information about the hotspot-runtime-dev
mailing list