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

[Rachel Protacio]

Looks good to me, Max. And I agree with your decision about the level.

Rachel

On 3/3/2016 3:34 PM, Max Ockner wrote:
> 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
>>>>
>>>>
>>
>