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

[Ioi Lam]

On 5/2/17 10:33 PM, David Holmes wrote:
> 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.
>
Sorry I wasn't very clear. What I meant was this:

For parsability, we need to atomically group together outputs that have 
different verbosity. Let's say you have this group of outputs:

      [info] A
      [debug] B

Today the only atomic unit is a single line, so the only way to 
atomically group A and B together is to repeat A in the [debug] level:

      [info] A
      [debug] A B

if we want to avoid the redundancy, we could potentially change the 
output format, so that in debug.log you have something like this:

     [info+debug] A B

But anyway, this is probably too messy to implement. That's why I 
proposed in another e-mail that UL should provide an atomic group of 
multiple lines.

Thanks
- Ioi


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