RFR: 8154791: Xlog classload too redundant msgs info/debug
Rachel Protacio
rachel.protacio at oracle.com
Fri May 5 18:34:49 UTC 2017
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