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

[Max Ockner]

Hello,

Thanks to everyone for their ideas and help. If there are no more 
concerns, I would like to submit this.

Thanks,
Max

On 3/9/2016 1:49 PM, Rachel Protacio wrote:
> 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
>>>>>
>>>>>
>>>
>>
>