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

[David Holmes]

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.

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
>>>>>
>>>>>
>>>
>