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

[David Holmes]

On 7/03/2016 7:09 AM, Bengt Rutisson wrote:
> On 2016-03-04 18:37, Max Ockner wrote:
>> 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.
>
> I don't know this logging in detail, but I think it makes sense to
> change the output if it makes the logging more useful. I don't see a
> need for us to preserve the exact same log output if another format
> would be better. So much is changing anyway with the new logging
> framework that this is a good opportunity to improve the logging.
>
>>
>> Would you rather see ~1300 unique logging messages for classresolve on
>> the Info level or on the Debug level?
>
> With that much logging my guess is that I would prefer it on trace level.

But that leaves no further room for expansion with more detail. I may 
want to see the full 1300 messages when I enable -Xlog::classresolve, 
but not the 3900 messages that would be produced with the most verbose 
logging.

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

It sounds good to me: turn on the first level of logging that exists for 
the given tag. But I'm unclear if this is readily detectable.

>>
>> 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.
>
> But if you put the 1300 lines at debug level (or trace) we already don't
> print them if you do -Xlog:all.

Yes but we would like to see them when we use -Xlog:classresolve - 
whether they are info or debug. If you force these to be debug or lower 
then we're asking for a way to make debug (or lower) become the default.

But I still advocate using "info" for this.

Cheers,
David

> Thanks,
> Bengt
>
>>
>> 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
>>>>>>>>>
>>>>>>>>>
>>>>>>>
>>>>>
>>>
>>
>