RFR: 8146551: The output from -Xlog:classresolve=info has been shortened

Bengt Rutisson bengt.rutisson at oracle.com
Mon Mar 7 08:26:28 UTC 2016 

Hi again,

On 2016-03-07 01:22, David Holmes wrote:
> On 7/03/2016 7:09 AM, Bengt Rutisson wrote:
>> On 2016-03-04 18:37, Max Ockner wrote:
>>> We have tried to preserve some of the output exactly (or very close
>>> to) the way it was.  Some of the corresponding tags produce a ton of
>>> output. In the case of classresolve, you can not shrink the output
>>> anymore without changing its meaning, since there is no redundant
>>> info. I can't think of a good way to split the output across multiple
>>> levels since all of the output seems equally verbose and equally
>>> useful.  It originally seemed like the output from ConstantPool might
>>> be the most verbose, and would therefore deserve to live at the Debug
>>> level, but it only seemed that way because of a subtle flaw in the
>>> existing logging which exploded the output by a factor of 4. So I
>>> don't think it would be appropriate to split the output for
>>> classresolve over several levels.
>>
>> I don't know this logging in detail, but I think it makes sense to
>> change the output if it makes the logging more useful. I don't see a
>> need for us to preserve the exact same log output if another format
>> would be better. So much is changing anyway with the new logging
>> framework that this is a good opportunity to improve the logging.
>>
>>>
>>> Would you rather see ~1300 unique logging messages for classresolve on
>>> the Info level or on the Debug level?
>>
>> With that much logging my guess is that I would prefer it on trace 
>> level.
>
> But that leaves no further room for expansion with more detail. I may 
> want to see the full 1300 messages when I enable -Xlog::classresolve, 
> but not the 3900 messages that would be produced with the most verbose 
> logging.

Again, I don't know enough about this particular logging to be sure how 
to best design it, but there is also the possibility to use more tags. 
I'm actually a bit surprised that there is a "classresolve" tag instead 
of two tags "class, resolve". I would think that it would be interesting 
to do -Xlog:class and get relevant information about all parts of class 
loding, resolving and unloading etc.

I also didn't know about the 3900 messages, but if you really want to 
keep this design, what is the problem with having the 1300 messages at 
debug level and the 3900 messages at trace level?

>
>>>
>>> As a side thought, I wonder if Xlog:<tag> should default to the most
>>> course level which produces output for the specified tag.
>>
>> That sounds very strange to me.
>
> It sounds good to me: turn on the first level of logging that exists 
> for the given tag. But I'm unclear if this is readily detectable.

I think this will be very confusing to the users. I would be very 
surprised to get different level logging for different tags with the 
same configuration.

>
>>>
>>> That way, setting the classresolve output to Debug level would be OK.
>>> Logging  "-Xlog:all" could avoid printing 1300 lines for the
>>> "classresolve" tag, and "-Xlog:classresolve" would display the output
>>> for the classresolve tag even though it is debug level. Just a thought.
>>
>> But if you put the 1300 lines at debug level (or trace) we already don't
>> print them if you do -Xlog:all.
>
> Yes but we would like to see them when we use -Xlog:classresolve - 
> whether they are info or debug. If you force these to be debug or 
> lower then we're asking for a way to make debug (or lower) become the 
> default.

Why do you want so much logging when you do -Xlog:classresolve? The 
amount of logging really does not sound like anything you want as normal 
information but as something you want when you need to dig in to some 
details. Which is exactly when you want to use debug level logging. It 
seems very natural to me to do -Xlog:classresolve=debug to get these 
details. Or even better -Xlog:class+resolve=debug.

Bengt

>
> But I still advocate using "info" for this.
>
> Cheers,
> David
>
>> Thanks,
>> Bengt
>>
>>>
>>> Thanks,
>>> Max
>>>
>>> On 3/4/2016 7:02 AM, Bengt Rutisson wrote:
>>>>
>>>>
>>>> On 2016-03-04 11:25, David Holmes wrote:
>>>>> On 4/03/2016 7:47 PM, Bengt Rutisson wrote:
>>>>>>
>>>>>>
>>>>>> On 2016-03-04 03:54, David Holmes wrote:
>>>>>>> On 3/03/2016 7:45 PM, Bengt Rutisson wrote:
>>>>>>>>
>>>>>>>> Hi Max and Mikael,
>>>>>>>>
>>>>>>>> On 2016-03-03 10:40, Mikael Gerdin wrote:
>>>>>>>>> Hi Max,
>>>>>>>>>
>>>>>>>>> On 2016-03-01 23:30, Max Ockner wrote:
>>>>>>>>>> Hello,
>>>>>>>>>>
>>>>>>>>>> Please review this small fix which attempts to shorten the
>>>>>>>>>> output from
>>>>>>>>>> -Xlog:classresolve=info to an acceptable length.
>>>>>>>>>>
>>>>>>>>>> Bug: https://bugs.openjdk.java.net/browse/JDK-8146551
>>>>>>>>>> Webrev: http://cr.openjdk.java.net/~mockner/8146551.02/
>>>>>>>>>>
>>>>>>>>>> Summary: java '-Xlog:classresolve=info -version' used to
>>>>>>>>>> produce 3,683
>>>>>>>>>> lines of output. This is unacceptably verbose for info level
>>>>>>>>>> logging and
>>>>>>>>>> most of the output is not useful.
>>>>>>>>>>
>>>>>>>>>> "java -Xlog:classresolve=info -version" used to produce:
>>>>>>>>>>      -    3,683 total lines of output.
>>>>>>>>>>      -    3,121 total lines of output from
>>>>>>>>>> ConstantPool::trace_class_resolution().
>>>>>>>>>>      -    1,329 unique lines of output.
>>>>>>>>>>      -    767 unique lines of output from
>>>>>>>>>> ConstantPool::trace_class_resolution().
>>>>>>>>>>      -    562 total lines of output from all other sources, all
>>>>>>>>>> unique.
>>>>>>>>>>
>>>>>>>>>> The code in ConstantPool which called
>>>>>>>>>> ConstantPool::trace_class_resolution() was doing approximately
>>>>>>>>>> this:
>>>>>>>>>>
>>>>>>>>>> if (log_is_enabled(Info,classresolve)){
>>>>>>>>>> trace_class_resolution(...)}
>>>>>>>>>> else { resolve the class }
>>>>>>>>>>
>>>>>>>>>> So if logging was turned on, the class would not be resolved
>>>>>>>>>> properly,
>>>>>>>>>> but it would produce a log entry saying that the class was being
>>>>>>>>>> resolved. As a result, the constant pool entry would still
>>>>>>>>>> contain a
>>>>>>>>>> Symbol* the next time this piece of code was reached, and it 
>>>>>>>>>> would
>>>>>>>>>> produce yet another classresolve log entry.  In some cases,
>>>>>>>>>> this was
>>>>>>>>>> producing many consecutive identical log entries, taking up
>>>>>>>>>> full pages
>>>>>>>>>> at worst, and averaging a little over 4 duplicates per message.
>>>>>>>>>> Not
>>>>>>>>>> cool.
>>>>>>>>>>
>>>>>>>>>> The above duplication issue has been fixed, and the
>>>>>>>>>> ConstantPool::trace_class_resolution output has been moved to 
>>>>>>>>>> the
>>>>>>>>>> debug
>>>>>>>>>> leve. There are still 562 unique lines of output for "java
>>>>>>>>>> -Xlog:classresolve=info -version". There are now 767 additional
>>>>>>>>>> unique
>>>>>>>>>> lines of output when for the "java -Xlog:classresolve=debug
>>>>>>>>>> -version" .
>>>>>>>>>> This is better than before but still quite a lot. It seems like
>>>>>>>>>> all of
>>>>>>>>>> the info level output is equally important(or unimportant), as
>>>>>>>>>> you can
>>>>>>>>>> see in the sample below:
>>>>>>>>>>
>>>>>>>>>> [0.026s][info][classresolve] java.lang.reflect.Type
>>>>>>>>>> java.lang.Object
>>>>>>>>>> (super)
>>>>>>>>>> [0.026s][info][classresolve] java.lang.Class java.lang.Object
>>>>>>>>>> (super)
>>>>>>>>>> [0.026s][info][classresolve] java.lang.Class 
>>>>>>>>>> java.io.Serializable
>>>>>>>>>> (interface)
>>>>>>>>>> [0.026s][info][classresolve] java.lang.Class
>>>>>>>>>> java.lang.reflect.GenericDeclaration (interface)
>>>>>>>>>> [0.026s][info][classresolve] java.lang.Class
>>>>>>>>>> java.lang.reflect.Type
>>>>>>>>>> (interface)
>>>>>>>>>> [0.026s][info][classresolve] java.lang.Class
>>>>>>>>>> java.lang.reflect.AnnotatedElement (interface)
>>>>>>>>>> [0.026s][info][classresolve] java.lang.Cloneable 
>>>>>>>>>> java.lang.Object
>>>>>>>>>> (super)
>>>>>>>>>> [0.027s][info][classresolve] java.lang.ClassLoader
>>>>>>>>>> java.lang.Object
>>>>>>>>>> (super)
>>>>>>>>>> [0.027s][info][classresolve] java.lang.System java.lang.Object
>>>>>>>>>> (super)
>>>>>>>>>> [0.027s][info][classresolve] java.lang.Throwable 
>>>>>>>>>> java.lang.Object
>>>>>>>>>> (super)
>>>>>>>>>> [0.027s][info][classresolve] java.lang.Throwable
>>>>>>>>>> java.io.Serializable
>>>>>>>>>> (interface)
>>>>>>>>>> [0.027s][info][classresolve] java.lang.Error java.lang.Throwable
>>>>>>>>>> (super)
>>>>>>>>>> [0.027s][info][classresolve] java.lang.ThreadDeath 
>>>>>>>>>> java.lang.Error
>>>>>>>>>> (super)
>>>>>>>>>>
>>>>>>>>>> How do you feel about this? Possible solutions include 
>>>>>>>>>> setting all
>>>>>>>>>> output to debug level, or removing some of the logging messages.
>>>>>>>>>
>>>>>>>>> As I stated in the bug my personal opinion is that "info" level
>>>>>>>>> logging should be fairly limited in order to make "-Xlog:all" a
>>>>>>>>> useful
>>>>>>>>> flag to get a reasonable amount of output about what is
>>>>>>>>> happening in a
>>>>>>>>> JVM.
>>>>>>>>>
>>>>>>>>> One approach could be to move the most verbose output to
>>>>>>>>> classresolve=trace and keep the rest of classresolve output on 
>>>>>>>>> the
>>>>>>>>> debug level.
>>>>>>>>>
>>>>>>>>> The fact that the flag was called "TraceClassResolution" is in
>>>>>>>>> my mind
>>>>>>>>> a hint that if it produces large amounts of output then perhaps
>>>>>>>>> that
>>>>>>>>> output should be logged on the "trace" log level.
>>>>>>>>
>>>>>>>> +1 for this approach.
>>>>>>>
>>>>>>> As I wrote in the bug report there are philosophically quite
>>>>>>> different
>>>>>>> ways to view the the three logging levels - and this has been
>>>>>>> discussed before. I view "info", "debug" and "trace" as three 
>>>>>>> levels
>>>>>>> of logging applicable to any chosen tag. Others view them as some
>>>>>>> global indicator of priority/importance such that some "less
>>>>>>> important" tags will never use "info" because their output is not
>>>>>>> considered worthy - only in this world is "-Xlog:all" considered
>>>>>>> useful.
>>>>>>>
>>>>>>> If I say -Xlog:foo I expect to see some logging for foo.
>>>>>>
>>>>>> But even if you look at it as that the levels only are applicable
>>>>>> for a
>>>>>> particular tag, why would you want "info" on that tag to produce
>>>>>> extreme
>>>>>> amounts of data? I would expect -Xlog:foo to give me reasonable high
>>>>>> level info about foo. If I want more details I would use
>>>>>> -Xlog:foo=debug.
>>>>>
>>>>> It all depends on what you are logging. If it is a high frequency
>>>>> event then you will get a lot of data even at info levels.
>>>>
>>>> But that's my point. If it is a high frequency event you probably
>>>> don't want to log every event at the info level. That will be useless
>>>> information. What you probably want to do is aggregate and log useful
>>>> information less frequently. Then if someone needs to dig into the
>>>> detail they would enable more logging at debug or trace level to see
>>>> every individual event.
>>>>
>>>> Bengt
>>>>
>>>>>
>>>>> David
>>>>> -----
>>>>>
>>>>>> And if "info" for each individual tag logs a sensible amount of 
>>>>>> data,
>>>>>> then -Xlog:all will work pretty well for most cases.
>>>>>>
>>>>>> Bengt
>>>>>>
>>>>>>>
>>>>>>> David
>>>>>>> -----
>>>>>>>
>>>>>>>
>>>>>>>> I quite agree with Mikael that we should be a bit careful what we
>>>>>>>> log at
>>>>>>>> info level.
>>>>>>>>
>>>>>>>> Thanks,
>>>>>>>> Bengt
>>>>>>>>
>>>>>>>>>
>>>>>>>>> /Mikael
>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> Tested with jtreg runtime tests. ClassResolutionTest.java has 
>>>>>>>>>> been
>>>>>>>>>> modified to check for the new output.
>>>>>>>>>>
>>>>>>>>>> Thanks,
>>>>>>>>>> Max
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>
>>>>>>
>>>>
>>>
>>

More information about the hotspot-runtime-dev mailing list