Request for review (S): 7163848: G1: Log GC Cause for a GC

[Bengt Rutisson]

Hi John,

Thanks for looking at this!

Good catch about record_collection_pause_start(). I've updated this and 
I also re-instated the assert that I had removed.

Here's an updated webrev based on your comments:
http://cr.openjdk.java.net/~brutisso/7163848/webrev.01/

Now the log messages look like this:

[Full GC (System.gc()) 394K->299K(100M), 0.0618841 secs]
[GC pause (G1 Evacuation Pause) (young) 20M->325K(100M), 0.0213615 secs]
[GC pause (G1 Humongous Allocation) (young) (initial-mark) 
32M->32M(100M), 0.0038521 secs]

With log level finer and finest the second entry above will look like this:

[GC pause (G1 Evacuation Pause) (young), 0.00431665 secs]

The size information is printed on separate lines as part of the GC details.

Thanks again for the review!
Bengt

On 2012-04-24 19:03, John Cuthbertson wrote:
> Hi Bengt,
>
> Apologies. A bad cut'n paste of the code. It should have been:
>
> void G1CollectorPolicy::record_collection_pause_start(double 
> start_time_sec,
>                                                     size_t start_used) {
> if (G1Log::finer()) {
>   gclog_or_tty->stamp(PrintGCTimeStamps);
>   gclog_or_tty->print("[GC pause (%s)", gcs_are_young() ? "young" : 
> "mixed");
>   gclog_or_tty->print(" (%s)",  GCCause::to_string(_g1->gc_cause()));
> }
>
> The other thing I was thinking - based upon your output:
>
> [GC pause (young) (G1 Evacuation Pause) 149M->118M(244M), 0.2433432 secs]
> [GC pause (young) (initial-mark) (G1 Evacuation Pause) 
> 160M->128M(247M), 0.1768634 secs]
> [GC pause (young) (initial-mark) (G1 Humongous Allocation) 
> 32M->32M(100M), 0.0104583 secs]
> [GC pause (mixed) (G1 Evacuation Pause) 128M->82M(256M), 0.5632070 secs]
> [Full GC (System.gc()) 417K->321K(100M), 0.0324733 secs]
> [Full GC (Permanent Generation Full) 285K->285K(7168K), 0.0270867 secs]
> [Full GC (Last ditch collection) 285K->275K(7168K), 0.0268307 secs]
> [Full GC (No GC)[GC concurrent-root-region-scan-end, 0.0007064]
>
> is that you may want to move the "initial-mark" to after the GC cause 
> (because it doesn't come out every pause) and potentially even before 
> the young./mixed. That way the cause is always the 3rd field. If not 
> then you should print the cause in 
> G1CollectorPolicy::record_collection_pause_end() before 
> "(initial-mark)" is printed. Or move the "initial-mark" message into 
> record_collection_pause_start().
>
> Anyway the main point is that with this change as it stands - there 
> will be different line output between "fine" and "finer" - and we 
> should try to avoid that.
>
> JohnC
>
> On 04/24/12 09:35, John Cuthbertson wrote:
>> Hi Bengt,
>>
>> These are very similar to the changes I gave to Stanley Guan to 
>> identify the reason for 7143858.
>>
>> In G1CollectedHeap::do_collection(), you've removed the assert:
>>
>> assert(!system_gc || explicit_gc, "invariant");
>>
>> was this intentional?
>>
>> Also don't you also want the same change in 
>> G1CollectorPolicy::record_collection_pause_start():
>>
>> void G1CollectorPolicy::record_collection_pause_start(double 
>> start_time_sec,
>>                                                      size_t 
>> start_used) {
>>  if (G1Log::finer()) {
>>    gclog_or_tty->stamp(PrintGCTimeStamps);
>>    gclog_or_tty->print(" (%s)", gcs_are_young() ? "young" : "mixed");
>>    gclog_or_tty->print("[GC pause (%s)", 
>> GCCause::to_string(_g1->gc_cause()));
>>  }
>>
>> Other than that - it looks good.
>>
>> JohnC
>>
>> On 04/24/12 05:12, Bengt Rutisson wrote:
>>>
>>> Hi everyone,
>>>
>>> Could I have a couple of reviews for this change?
>>> http://cr.openjdk.java.net/~brutisso/7163848/webrev.00/
>>>
>>> Background
>>>
>>> Many times it is useful to know why a GC happened. The GC cause 
>>> tells us that, but it has not been exposed in the log file before. 
>>> The change adds that information to the log entries for PrintGC.
>>>
>>> Here are some examples of what the logging looks like with this change:
>>>
>>> [GC pause (young) (G1 Evacuation Pause) 149M->118M(244M), 0.2433432 
>>> secs]
>>> [GC pause (young) (initial-mark) (G1 Evacuation Pause) 
>>> 160M->128M(247M), 0.1768634 secs]
>>> [GC pause (young) (initial-mark) (G1 Humongous Allocation) 
>>> 32M->32M(100M), 0.0104583 secs]
>>> [GC pause (mixed) (G1 Evacuation Pause) 128M->82M(256M), 0.5632070 
>>> secs]
>>> [Full GC (System.gc()) 417K->321K(100M), 0.0324733 secs]
>>> [Full GC (Permanent Generation Full) 285K->285K(7168K), 0.0270867 secs]
>>> [Full GC (Last ditch collection) 285K->275K(7168K), 0.0268307 secs]
>>> [Full GC (No GC)[GC concurrent-root-region-scan-end, 0.0007064]
>>>
>>> We might want to re-phrase the GC cause names, but that should 
>>> probably be a separate CR since it will affect jstat and others that 
>>> use the GCCause::to_string() method.
>>>
>>> Thanks,
>>> Bengt
>>
>