Request for review (S): 7166894 Add gc cause to Full GC logging for all collectors

[Bengt Rutisson]

Hi John,

Thanks for looking at this!

On 2012-05-14 21:00, John Cuthbertson wrote:
> Hi Bengt,
>
> Overall this looks good to me, but I do have a couple of minor 
> comments and questions....
>
> arguments.cpp - Typo @ line 3096

Fixed.

>
> gcCause.hpp - fields in the new class should have a leading underscore.

Of course! I keep missing that when I create new classes. Thanks for 
finding it! Fixed.

> g1CollectedHeap.cpp - @ line 3600. IMO using a local to hold the GC 
> string and pass that into the TraceTime constructor would improve the 
> readability significantly.

Fixed.

>
> g1CollectorPolicy.cpp - @ line 888. If you have a log level == finer, 
> where is the print of the date/timestamp prefix now?

Good catch! I clearly removed one line too much. Added it back.

Here is an updated webrev:
http://cr.openjdk.java.net/~brutisso/7166894/webrev.06/

Thanks again for looking at this!
Bengt



>
> Other than that, it looks good?
>
> JohnC
>
> On 05/14/12 00:46, Bengt Rutisson wrote:
>>
>> Hi again,  :-)
>>
>> Here is an updated webrev where PrintGCCause is off by default in 
>> JDK7 but on by default in JDK8:
>> http://cr.openjdk.java.net/~brutisso/7166894/webrev.05/
>>
>> The relevant change is in arguments.cpp:
>> http://cr.openjdk.java.net/~brutisso/7166894/webrev.05/src/share/vm/runtime/arguments.cpp.udiff.html
>>
>> With this proposal there is still one slight change in JDK7 logging. 
>> For full GCs that were triggered by System.gc() calls we used to log 
>> the cause. Now this will not happen unless you add -XX:+PrintGCCause. 
>> This will not break any parsers, but it might make some parsers miss 
>> System.gc() calls.
>>
>> I think we are getting closer to wrapping this change up. It is a 
>> little unclear to me who would like to be listed as reviewers. Could 
>> those that would like to be reviewers please take a look at the 
>> latest webrev and let me know.
>>
>> Thanks,
>> Bengt
>>
>>
>> On 2012-05-11 19:51, Srinivas Ramakrishna wrote:
>>> Mikael, thanks for sounding that note of caution... what you say 
>>> makes sense.
>>>
>>> -- ramki
>>>
>>> On Fri, May 11, 2012 at 10:17 AM, Mikael Vidstedt 
>>> <mikael.vidstedt at oracle.com <mailto:mikael.vidstedt at oracle.com>> wrote:
>>>
>>>
>>>     I'm all for improving the information in the log messages, great
>>>     work! However, I'm not sure I'm warm and fuzzy about potentially
>>>     breaking users' log parsers in a minor update. My preference
>>>     would be to have the PrintGCCause flag be default false in jdk7
>>>     and default true in jdk8+. In general I'd prefer to only change
>>>     the log messages in major releases.
>>>
>>>     Reasonable?
>>>
>>>     Cheers,
>>>     Mikael
>>>
>>>
>>>     On 2012-05-11 07:30, Bengt Rutisson wrote:
>>>>
>>>>     Hi Kris,
>>>>
>>>>     Thanks again for looking at this.
>>>>
>>>>     I had to make some minor changes make it compile on all
>>>>     platforms. Mostly some explicit casts to const char*. Here is
>>>>     an updated webrev:
>>>>     http://cr.openjdk.java.net/~brutisso/7166894/webrev.04/
>>>>     <http://cr.openjdk.java.net/%7Ebrutisso/7166894/webrev.04/>
>>>>
>>>>     More comments inline.
>>>>
>>>>     On 2012-05-08 16:43, Krystal Mok wrote:
>>>>>     Hi Bengt,
>>>>>
>>>>>     The current factoring looks nice and uniform. Thanks :-)
>>>>>
>>>>>     But for most minor GCs and both CMS pause phases, the extra
>>>>>     logging doesn't really give additional information.
>>>>>     Most minor GCs are going to say "Allocation Failure", and the
>>>>>     two CMS phases would change from, e.g.
>>>>>
>>>>>     [GC [1 CMS-initial-mark
>>>>>
>>>>>     to something like
>>>>>
>>>>>     [GC (CMS Initial Mark) [1 CMS-initial-mark
>>>>>
>>>>>     which is probably reasonable given the scope of the change,
>>>>>     but not really helpful.
>>>>>     The "real cause", such as which generation (or perhaps
>>>>>     System.gc() with ExplicitGCInvokesConcurrent, or even GC
>>>>>     locker) is triggering this collection cycle, may be more
>>>>>     useful, but it's hard to fit into the current form.
>>>>
>>>>     Yes, I think you are correct in both cases. The gc cause that
>>>>     we have available does not always add a lot of information.
>>>>     This is relevant to fix but it is a slightly different issue
>>>>     than what this patch sets out to fix. Let's try to get this in
>>>>     first and then evaluate how the GC causes should be set.
>>>>
>>>>     Thanks,
>>>>     Bengt
>>>>
>>>>>
>>>>>     - Kris
>>>>>
>>>>>     On Tue, May 8, 2012 at 10:18 PM, Bengt Rutisson
>>>>>     <bengt.rutisson at oracle.com <mailto:bengt.rutisson at oracle.com>>
>>>>>     wrote:
>>>>>
>>>>>
>>>>>         Hi again everyone,
>>>>>
>>>>>         It seems like the feedback on hotspot-gc-use is that we
>>>>>         should add the GC cause to all collectors but also provide
>>>>>         a switch to turn this logging off.
>>>>>
>>>>>         Here is an updated webrev:
>>>>>         http://cr.openjdk.java.net/~brutisso/7166894/webrev.03/
>>>>>         <http://cr.openjdk.java.net/%7Ebrutisso/7166894/webrev.03/>
>>>>>
>>>>>         Changes:
>>>>>         * GC cause logged for all collectors
>>>>>         * Added the flag -XX:-PrintGCCause to turn the new
>>>>>         information off
>>>>>         * Refactored the string concatenation code into a helper class
>>>>>
>>>>>         I guess I will also have to update the CR to now reflect
>>>>>         the fact that this does not just concern full GCs anymore.
>>>>>
>>>>>         Thanks,
>>>>>         Bengt
>>>>>
>>>>
>>>
>>>
>>
>

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20120515/c2c086f8/attachment.htm>