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

[Mikael Gerdin]

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.

/Mikael

>
> Tested with jtreg runtime tests. ClassResolutionTest.java has been
> modified to check for the new output.
>
> Thanks,
> Max
>
>