RFR: 8154791: Xlog classload too redundant msgs info/debug
Ioi Lam
ioi.lam at oracle.com
Thu May 4 23:02:00 UTC 2017
Hi Rachel,
On 5/4/17 8:52 AM, Rachel Protacio wrote:
> If I'm using this incorrectly, please let me know, but I think
> LogBufferMessage also doesn't do exactly what we want. With this
> changeset: http://cr.openjdk.java.net/~rprotacio/8154791.01/ we get
> this output:
>
> [0.050s][info ][class,load] java.lang.CharSequence
> [0.050s][info ][class,load] source: jrt:/java.base
> [0.050s][info ][class,load] loader:
> [AllocatedObj(0x00000007c00015a0)]
> [0.050s][debug][class,load] klass: 0x00000007c00015a0
> [0.050s][debug][class,load] super: 0x00000007c0000fb0
> [0.050s][info ][class,load] bytes: 2045 checksum: 5b97c8c1
> [0.051s][info ][class,load] java.lang.String
> [0.051s][info ][class,load] source: jrt:/java.base
> [0.051s][info ][class,load] loader:
> [AllocatedObj(0x00000007c0001798)]
> [0.051s][debug][class,load] klass: 0x00000007c0001798
> [0.051s][debug][class,load] super: 0x00000007c0000fb0
> [0.051s][debug][class,load] interfaces:
> [0.051s][debug][class,load] 0x00000007c00011b0
> [0.051s][debug][class,load] 0x00000007c00013a8
> [0.051s][debug][class,load] 0x00000007c00015a0
> [0.051s][info ][class,load] bytes: 24872 checksum: 564a9fc2
>
> It comes out "together", but each call is a separate line. But to put
> it all on one line would lead to messy code, something like adding
> each part to two temporary strings and putting them in the buffer at
> the end, I think.
>
I think we can use stringStream to collect the output together, and then
write the whole line at once. Here's what I tried on top of your patch
above:
http://cr.openjdk.java.net/~iklam/jdk10/8154791.01_log_class_load.delta/
I also moved the class loader info back into "debug" . JDK-8154791
suggested moving that into "info", but I think that should be considered
in a separate issue. Personally I that think would make the "info"
output too verbose.
> So the other option is to do this:
> http://cr.openjdk.java.net/~rprotacio/8154791.02 which is essentially
> the original code, but slightly cleaner and without redundancy of the
> info line inside the debug line. The only issue is it doesn't
> necessarily guarantee the two lines will come out next to each other,
> so we have to print the external name on each.
>
> [0.051s][info ][class,load] java.lang.CharSequence source:
> jrt:/java.basejava.lang.CharSequence loader: [NULL class_loader]
> bytes: 2045 checksum: 5b97c8c1
> [0.051s][debug][class,load] java.lang.CharSequence klass:
> 0x00000007c00015a0 super: 0x00000007c0000fb0
> [0.052s][info ][class,load] java.lang.String source:
> jrt:/java.basejava.lang.String loader: [NULL class_loader] bytes:
> 24872 checksum: 564a9fc2
> [0.052s][debug][class,load] java.lang.String klass:
> 0x00000007c0001798 super: 0x00000007c0000fb0 interfaces:
> 0x00000007c00011b0 0x00000007c00013a8 0x00000007c00015a0
>
>
When two classes of the same name are loaded at the same time, and the
output is interleaved, you can't find out which is which:
HelloWorld source: foo.jar
HelloWorld source: bar.jar
HelloWorld klass: 0x1234
HelloWorld klass: 0x5678
E.g., is the klass loaded from foo.jar 0x1234 or 0x5678?
Thanks
- Ioi
> Or we can make the info output the same as debug, when debug is
> specified. Which I have reservations about but will certainly do if
> that's what makes the most sense.
>
> Thanks,
> Rachel
>
> On 5/3/2017 2:23 AM, Thomas Stüfe wrote:
>> Hi Ioi,
>>
>> On Tue, May 2, 2017 at 11:10 PM, Ioi Lam <ioi.lam at oracle.com> wrote:
>>
>>> By the way, I think we should really fix this in the UL level -- have
>>> multi-line buffering, so you can prevent other threads from
>>> interleaving
>>> your input. Make it something like:
>>>
>>> Log(class, load).start_buffering();
>>> log_info(class, load)(class name and source);
>>> log_debug(class, load)(other details);
>>> Log(class, load).flush();
>>>
>>> That way, the output will look like this:
>>>
>>> [0.162s][debug ][class,load] java.lang.Comparable source:
>>> jrt:/java.base
>>> [0.162s][debug ][class,load] [NULL class_loader] 0x00000007c00013a8
>>> super:
>>> 0x00000007c0000fb0 bytes: 235 checksum: a75dadb6
>>>
>>> So the output will be terse, and still parsable.
>>>
>>> I think this will be useful for other types of logs as well, not
>>> just the
>>> class loading logs.
>>>
>>>
>> I thought that already exists:
>>
>> https://bugs.openjdk.java.net/browse/JDK-8145934
>>
>> see logMessage.hpp.
>>
>> Kind Regards, Thomas
>>
>>
>>> Thanks
>>> - Ioi
>>>
>>>
>>> On 5/2/17 1:56 PM, Ioi Lam wrote:
>>>
>>>>
>>>> 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
>>>>>>>
>>>>>>
>
More information about the hotspot-runtime-dev
mailing list