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

[Bengt Rutisson]

Hi John, Jesper and Jon,

Thanks for the reviews!

Since JPRT will be down from tomorrow I would like to push this today. 
So, I'll go ahead and push this now.

Thanks again for looking at this,
Bengt

On 2012-04-25 13:07, Bengt Rutisson wrote:
>
> 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
>>>
>>
>