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