<!DOCTYPE html PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN">
<html>
<head>
</head>
<body bgcolor="#ffffff" text="#000000">
Hi Everyone,<br>
<br>
Can I have a couple of volunteers review this small change? The webrev
can be found at: <a class="moz-txt-link-freetext" href="http://cr.openjdk.java.net/~johnc/7068215/webrev.0/">http://cr.openjdk.java.net/~johnc/7068215/webrev.0/</a><br>
<br>
Background:<br>
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*):<br>
<br>
<u>PrintGC (only)</u><br>
13.061: [GC pause (young) (initial-mark) 19M->9983K(32M), 0.0108699
secs]<br>
13.072: [GC concurrent-mark-start]<br>
13.120: [GC concurrent-mark-end, 0.0484379 sec]<br>
13.122: [GC remark, 0.0265762 secs]<br>
13.154: [GC concurrent-count-start]<br>
13.160: [GC concurrent-count-end, 0.0058944]<br>
13.160: [GC cleanup 10M->10M(32M), 0.0004928 secs]<br>
<br>
No difference from before.<br>
<br>
<u>PrintGC + PrintReferenceGC</u><br>
14.537: [GC pause (young) (initial-mark) 19M->10146K(32M), 0.0110351
secs]<br>
14.548: [GC concurrent-mark-start]<br>
14.596: [GC concurrent-mark-end, 0.0474622 sec]<br>
14.596: [GC remark <b>14.596: [GC remark (ref processing), 0.0274587
secs]</b>, 0.0277831 secs]<br>
14.624: [GC concurrent-count-start]<br>
14.630: [GC concurrent-count-end, 0.0059460]<br>
14.630: [GC cleanup 10M->10M(32M), 0.0004955 secs]<br>
<br>
<u>PrintGCDetails (only)</u><br>
21.336: [GC concurrent-mark-end, 0.0394013 sec]<br>
21.336: [GC remark <b>21.347: [GC remark (ref processing), 0.0262900
secs]</b>, 0.0376863 secs]<br>
[Times: user=0.07 sys=0.00, real=0.04 secs] <br>
21.374: [GC concurrent-count-start]<br>
21.380: [GC concurrent-count-end, 0.0059530]<br>
21.380: [GC cleanup 10M->10M(32M), 0.0004814 secs]<br>
<br>
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.<br>
<br>
<u>PrintGCDetails + PrintReferenceGC</u><br>
12.450: [GC concurrent-mark-end, 0.0390687 sec]<br>
12.450: [GC remark <b>12.452: [GC remark (ref processing)</b>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], <b>0.0272514 secs]</b>,
0.0295062 secs]<br>
[Times: user=0.04 sys=0.00, real=0.03 secs] <br>
12.480: [GC concurrent-count-start]<br>
12.486: [GC concurrent-count-end, 0.0059510]<br>
12.486: [GC cleanup 10M->10M(32M), 0.0005403 secs]<br>
[Times: user=0.00 sys=0.00, real=0.00 secs] <br>
<br>
Thanks,<br>
<br>
JohnC<br>
</body>
</html>