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

[David Holmes]

Hi Ioi,

I'm a bit confused ...

On 3/05/2017 4:48 AM, 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.

Right - that is how it works.

> 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

Okay, but you are only going to get that if you disable the info logging 
when debug is active - otherwise as you just noted the debug log 
contains debug+info. I'm unclear how you expect to produce the above 
output if you have enabled the two log files as above?? I don't think it 
can be done.

Cheers,
David

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