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

[Rachel Protacio]

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

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
>