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

Max Ockner max.ockner at oracle.com
Tue Mar 1 22:30:22 UTC 2016


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.

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

Thanks,
Max




More information about the hotspot-runtime-dev mailing list