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

[David Holmes]

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.

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