RFR: 8154791: Xlog classload too redundant msgs info/debug
Rachel Protacio
rachel.protacio at oracle.com
Fri May 5 20:31:31 UTC 2017
Thank you, Ioi!
Rachel
On 5/5/2017 3:57 PM, Ioi Lam wrote:
> Looks good!
>
> Thanks
> - Ioi
>
> On 5/5/17 11: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