RFR: 8154791: Xlog classload too redundant msgs info/debug
Marcus Larsson
marcus.larsson at oracle.com
Fri May 5 08:28:56 UTC 2017
Hi,
On 2017-05-05 01:02, Ioi Lam wrote:
> 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/
Usage looks good to me, but it can be simplified by using LogMessage
instead of directly using the LogMessageBuffer.
With LogMessage you would change
3065 LogMessageBuffer msg;
into
3065 LogMessage(class, load) msg;
and remove the following lines:
3133 Log(class, load) _log;
3134 _log.write(msg);
(The message gets written when the LogMessage object goes out of scope.)
Thanks,
Marcus
>
> 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