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

[Max Ockner]

We have tried to preserve some of the output exactly (or very close to) 
the way it was.  Some of the corresponding tags produce a ton of output. 
In the case of classresolve, you can not shrink the output anymore 
without changing its meaning, since there is no redundant info. I can't 
think of a good way to split the output across multiple levels since all 
of the output seems equally verbose and equally useful.  It originally 
seemed like the output from ConstantPool might be the most verbose, and 
would therefore deserve to live at the Debug level, but it only seemed 
that way because of a subtle flaw in the existing logging which exploded 
the output by a factor of 4.  So I don't think it would be appropriate 
to split the output for classresolve over several levels.

Would you rather see ~1300 unique logging messages for classresolve on 
the Info level or on the Debug level?

As a side thought, I wonder if Xlog:<tag> should default to the most 
course level which produces output for the specified tag.

That way, setting the classresolve output to Debug level would be OK. 
Logging  "-Xlog:all" could avoid printing 1300 lines for the 
"classresolve" tag, and "-Xlog:classresolve" would display the output 
for the classresolve tag even though it is debug level. Just a thought.

Thanks,
Max

On 3/4/2016 7:02 AM, Bengt Rutisson wrote:
>
>
> 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
>>>>>>>
>>>>>>>
>>>>>
>>>
>