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

[Max Ockner]

David,

The changes that were puzzling you have been removed. I think setting 
all of the output to debug level would be the best solution, but I want 
to see what others have to say.

Thanks,
Max

Webrev: http://cr.openjdk.java.net/~mockner/8146551.03/
On 3/1/2016 6:50 PM, David Holmes wrote:
> 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
>>
>>