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

[Ioi Lam]

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

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