RFR (XXXS): 7068215: G1: Print reference processing time during remark

[John Cuthbertson]

Hi Everyone,

Can I have a couple of volunteers review this small change? The webrev 
can be found at: http://cr.openjdk.java.net/~johnc/7068215/webrev.0/

Background:
During some recent performance runs of G1, some extremely long remark 
pauses (espccially the first) were observed and the CPU times indicated 
that the remarks were pretty serial. There is speculation that these 
long remarks are caused be the reference process, which is serial by 
default. This CR is to add a timer to the reference processing to 
confirm our suspicions. With the new timer, the output format of the 
remark has changed a little (new output is in *bold*):

_PrintGC (only)_
13.061: [GC pause (young) (initial-mark) 19M->9983K(32M), 0.0108699 secs]
13.072: [GC concurrent-mark-start]
13.120: [GC concurrent-mark-end, 0.0484379 sec]
13.122: [GC remark, 0.0265762 secs]
13.154: [GC concurrent-count-start]
13.160: [GC concurrent-count-end, 0.0058944]
13.160: [GC cleanup 10M->10M(32M), 0.0004928 secs]

No difference from before.

_PrintGC + PrintReferenceGC_
14.537: [GC pause (young) (initial-mark) 19M->10146K(32M), 0.0110351 secs]
14.548: [GC concurrent-mark-start]
14.596: [GC concurrent-mark-end, 0.0474622 sec]
14.596: [GC remark *14.596: [GC remark (ref processing), 0.0274587 
secs]*, 0.0277831 secs]
14.624: [GC concurrent-count-start]
14.630: [GC concurrent-count-end, 0.0059460]
14.630: [GC cleanup 10M->10M(32M), 0.0004955 secs]

_PrintGCDetails (only)_
21.336: [GC concurrent-mark-end, 0.0394013 sec]
21.336: [GC remark *21.347: [GC remark (ref processing), 0.0262900 
secs]*, 0.0376863 secs]
 [Times: user=0.07 sys=0.00, real=0.04 secs]
21.374: [GC concurrent-count-start]
21.380: [GC concurrent-count-end, 0.0059530]
21.380: [GC cleanup 10M->10M(32M), 0.0004814 secs]

The CPU times after the remark are for the remark pause as a whole. 
Using the new output (either the delta between the timestamps or the 
delta between the times) we can synthesize the amount of time it took 
for the actual marking part of the remark pause.

_PrintGCDetails + PrintReferenceGC_
12.450: [GC concurrent-mark-end, 0.0390687 sec]
12.450: [GC remark *12.452: [GC remark (ref processing)*12.452: 
[SoftReference, 0 refs, 0.0000226 secs]12.453: [WeakReference, 9 refs, 
0.0000216 secs]12.453: [FinalReference, 15279 refs, 0.0189796 
secs]12.472: [PhantomReference, 0 refs, 0.0000072 secs]12.472: [JNI Weak 
Reference, 15 refs, 0.0000072 secs], *0.0272514 secs]*, 0.0295062 secs]
 [Times: user=0.04 sys=0.00, real=0.03 secs]
12.480: [GC concurrent-count-start]
12.486: [GC concurrent-count-end, 0.0059510]
12.486: [GC cleanup 10M->10M(32M), 0.0005403 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs]

Thanks,

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