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

[Bengt Rutisson]

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.

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