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

Tue May 2 20:56:40 UTC 2017

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