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

[David Holmes]

Hi Max,

On 2/03/2016 8:30 AM, 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.

But to be clear the TraceClassResolution version was doing the same thing.

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

I expect tracing class resolution to show me at least one line for every 
class that gets resolved, so the above seems fine. Only the extra 
detailed info should be deferred to debug-level. But I'm not a consumer 
of this data so ... :)

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

I'm puzzled by a couple of changes:

           public static class Thing1 {
+             static int number=5;
               public static int getThingNumber() {
!                 return number;
               }

Significance?

Also here:

!         o = new OutputAnalyzer(pb.start());
!         o.getOutput();
!         o.shouldContain("[classresolve] ...

o.getOutput() isn't doing anything.

Thanks,
David

> Thanks,
> Max
>
>