RFR: 8154791: Xlog classload too redundant msgs info/debug
Rachel Protacio
rachel.protacio at oracle.com
Thu May 4 15:52:34 UTC 2017
If I'm using this incorrectly, please let me know, but I think
LogBufferMessage also doesn't do exactly what we want. With this
changeset: http://cr.openjdk.java.net/~rprotacio/8154791.01/ we get this
output:
[0.050s][info ][class,load] java.lang.CharSequence
[0.050s][info ][class,load] source: jrt:/java.base
[0.050s][info ][class,load] loader: [AllocatedObj(0x00000007c00015a0)]
[0.050s][debug][class,load] klass: 0x00000007c00015a0
[0.050s][debug][class,load] super: 0x00000007c0000fb0
[0.050s][info ][class,load] bytes: 2045 checksum: 5b97c8c1
[0.051s][info ][class,load] java.lang.String
[0.051s][info ][class,load] source: jrt:/java.base
[0.051s][info ][class,load] loader: [AllocatedObj(0x00000007c0001798)]
[0.051s][debug][class,load] klass: 0x00000007c0001798
[0.051s][debug][class,load] super: 0x00000007c0000fb0
[0.051s][debug][class,load] interfaces:
[0.051s][debug][class,load] 0x00000007c00011b0
[0.051s][debug][class,load] 0x00000007c00013a8
[0.051s][debug][class,load] 0x00000007c00015a0
[0.051s][info ][class,load] bytes: 24872 checksum: 564a9fc2
It comes out "together", but each call is a separate line. But to put it
all on one line would lead to messy code, something like adding each
part to two temporary strings and putting them in the buffer at the end,
I think.
So the other option is to do this:
http://cr.openjdk.java.net/~rprotacio/8154791.02 which is essentially
the original code, but slightly cleaner and without redundancy of the
info line inside the debug line. The only issue is it doesn't
necessarily guarantee the two lines will come out next to each other, so
we have to print the external name on each.
[0.051s][info ][class,load] java.lang.CharSequence source:
jrt:/java.basejava.lang.CharSequence loader: [NULL class_loader]
bytes: 2045 checksum: 5b97c8c1
[0.051s][debug][class,load] java.lang.CharSequence klass:
0x00000007c00015a0 super: 0x00000007c0000fb0
[0.052s][info ][class,load] java.lang.String source:
jrt:/java.basejava.lang.String loader: [NULL class_loader] bytes:
24872 checksum: 564a9fc2
[0.052s][debug][class,load] java.lang.String klass:
0x00000007c0001798 super: 0x00000007c0000fb0 interfaces:
0x00000007c00011b0 0x00000007c00013a8 0x00000007c00015a0
Or we can make the info output the same as debug, when debug is
specified. Which I have reservations about but will certainly do if
that's what makes the most sense.
Thanks,
Rachel
On 5/3/2017 2:23 AM, Thomas Stüfe wrote:
> Hi Ioi,
>
> On Tue, May 2, 2017 at 11:10 PM, Ioi Lam <ioi.lam at oracle.com> wrote:
>
>> 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.
>>
>>
> I thought that already exists:
>
> https://bugs.openjdk.java.net/browse/JDK-8145934
>
> see logMessage.hpp.
>
> Kind Regards, Thomas
>
>
>> 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