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

[Max Ockner]

Thanks for the additional feedback.
I have set all of the output to the debug level.
webrev: http://cr.openjdk.java.net/~mockner/8146551.04/

You can't really infer anything about the verbosity of a Trace* option 
from the face that it starts with "Trace", though I agree that it would 
make a lot more sense if that were the case...

I chose to put all of the output on debug after accounting for 2 things;
(1) The output is extremely verbose, even for java -version. Therefore, 
all output should be either debug or trace level.
(2) None of the output ever conditioned on Verbose or WizardMode. Based 
on the conventions we have been following, the output shouldn't be on 
trace level.

==> Debug level.

Thanks,
Max

On 3/3/2016 4:45 AM, Bengt Rutisson wrote:
>
> Hi Max and Mikael,
>
> On 2016-03-03 10:40, Mikael Gerdin wrote:
>> 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.
>
> +1 for this approach.
>
> I quite agree with Mikael that we should be a bit careful what we log 
> at info level.
>
> Thanks,
> Bengt
>
>>
>> /Mikael
>>
>>>
>>> Tested with jtreg runtime tests. ClassResolutionTest.java has been
>>> modified to check for the new output.
>>>
>>> Thanks,
>>> Max
>>>
>>>
>