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

Bengt Rutisson bengt.rutisson at oracle.com
Sun Mar 6 21:09:34 UTC 2016 


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.

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

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

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

More information about the hotspot-runtime-dev mailing list