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

[Bengt Rutisson]

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.

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