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

[Bengt Rutisson]

On 2016-03-04 11:25, David Holmes wrote:
> On 4/03/2016 7:47 PM, Bengt Rutisson wrote:
>>
>>
>> On 2016-03-04 03:54, David Holmes wrote:
>>> On 3/03/2016 7:45 PM, 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.
>>>
>>> As I wrote in the bug report there are philosophically quite different
>>> ways to view the the three logging levels - and this has been
>>> discussed before. I view "info", "debug" and "trace" as three levels
>>> of logging applicable to any chosen tag. Others view them as some
>>> global indicator of priority/importance such that some "less
>>> important" tags will never use "info" because their output is not
>>> considered worthy - only in this world is "-Xlog:all" considered 
>>> useful.
>>>
>>> If I say -Xlog:foo I expect to see some logging for foo.
>>
>> But even if you look at it as that the levels only are applicable for a
>> particular tag, why would you want "info" on that tag to produce extreme
>> amounts of data? I would expect -Xlog:foo to give me reasonable high
>> level info about foo. If I want more details I would use 
>> -Xlog:foo=debug.
>
> It all depends on what you are logging. If it is a high frequency 
> event then you will get a lot of data even at info levels.

But that's my point. If it is a high frequency event you probably don't 
want to log every event at the info level. That will be useless 
information. What you probably want to do is aggregate and log useful 
information less frequently. Then if someone needs to dig into the 
detail they would enable more logging at debug or trace level to see 
every individual event.

Bengt

>
> David
> -----
>
>> And if "info" for each individual tag logs a sensible amount of data,
>> then -Xlog:all will work pretty well for most cases.
>>
>> Bengt
>>
>>>
>>> David
>>> -----
>>>
>>>
>>>> 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
>>>>>>
>>>>>>
>>>>
>>