RFR: 8154791: Xlog classload too redundant msgs info/debug

Wed May 3 06:23:09 UTC 2017

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