RFR: 8154791: Xlog classload too redundant msgs info/debug
David Holmes
david.holmes at oracle.com
Mon May 8 03:47:02 UTC 2017
Hi Rachel,
This looks okay to me too!
Thanks,
David
On 6/05/2017 4:34 AM, Rachel Protacio wrote:
> Thank you both for your help! Here's my latest webrev:
> http://cr.openjdk.java.net/~rprotacio/8154791.03
>
> Rachel
>
>
> On 5/5/2017 4:28 AM, Marcus Larsson wrote:
>> 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