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

[Bengt Rutisson]

Hi Max,

On 2016-03-10 15:54, Max Ockner wrote:
> Hello,
>
> Thanks to everyone for their ideas and help. If there are no more 
> concerns, I would like to submit this.

I'm not one of the reviewers of this, (just had a quick look now and it 
does look good to me) but since I was involved in other discussions in 
this email thread I thought I'd say that I am fine with you pushing this.

I think the discussions regarding how to use the UL framework will be 
handled in other threads.

Thanks,
Bengt

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