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

[John Cuthbertson]

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
>