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

[Coleen Phillimore]

On 3/3/16 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.
Max,

I agree.  This looks really good.

Why would someone turn on this logging?  Well, if they are debugging 
class resolution, which is why the code is there in the first place.   
So ==> Debug level.

I don't think we should use class+resolve rather than classresolve for 
this until there is some better documentation (in the JVM and online) 
about what the cross product of every word (or some non-words) means.  
It's too complicated and hard to use otherwise.

Lastly, for the first round of conversions for the runtime flags, we're 
keeping most of the current output.   Later, when more logging is added 
or when people working on other parts of runtime code use the logging 
there, they can convert that logging and pick the messages that are 
meaningful for that bit of code.  We expect this to change over time.

thanks,
Coleen

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