Avoiding 1 long CMS with a big heap

Wed Apr 14 07:24:05 PDT 2010

Hi Jon

>> What jdk release are you using?
6u18

>> What type of  platform are you running on?
Solaris 10 x86 (Sun x4600)

>> You seem to have decided to promote (copy to the tenured generation) 
everything that survives a young gen collection (small 
MaxTenuringThreshold, small survivor spaces). Is that to minimize the 
young gen collection pauses?
this post (
http://mail.openjdk.java.net/pipermail/hotspot-gc-dev/2010-April/001671.html) 
has a bit more info on our allocation behaviour. Basically there is static 
data loaded at startup and then mostly things don't last v long before 
they're eligible for eviction. Therefore my thinking is that since the set 
of live objects at any one time is small and they don't last long then the 
probability of anything surviving 2 young collections is minimal and 
therefore I might as well increase the interval between young collections 
marginally by making active use of that space in eden. 

The target is simply consistently low pauses.

>> Why are you using CMSIncrementalMode?
in the past we found that it helps smooth out the pause times a little, I 
left it in on this run to minimise the no of changes between what we have 
now and what I'm benching. I was expecting a single CMS run and no more 
tbh as I was working on the understanding that it always has one CMS event 
near startup in order to collect some stats on what is going on.

>> Does the long pause occur with every initial mark (CMS-initial-mark) or 
just the first one?
benchmark has run for 16hrs so far and there have been 2 initial marks so 
far, the first one I expected but the 2nd one I didn't.

2010-04-13T22:09:58.463+0000: 12.249: [GC [1 CMS-initial-mark: 
3679K(196608K)] 3679K(16564608K), 0.0009694 secs] [Times: user=0.00 
sys=0.00, real=0.00 secs] 
2010-04-13T23:05:29.072+0000: 3342.854: [GC [1 CMS-initial-mark: 
12018K(196608K)] 7811496K(16564608K), 4.2147116 secs] [Times: user=4.15 
sys=0.06, real=4.22 secs] 

>> Can you send the GC log for a few of the young generation collections 
before the initial mark (the very long pause of ~ 4secs)?
here you go, have stripped out the stopped/concurrent time entries to show 
all the GC events leading upto the long pause & the next 5 young 
collections.

2010-04-13T22:09:58.234+0000: 12.019: [Full GC 12.021: [CMS: 
0K->3679K(196608K), 0.2269262 secs] 4251520K->3679K(16564608K), [CMS Perm 
: 21247K->21209K(21248K)], 0.2286580 secs] [Times: user=0.22 sys=0.01, 
real=0.23 secs] 
2010-04-13T22:09:58.463+0000: 12.249: [GC [1 CMS-initial-mark: 
3679K(196608K)] 3679K(16564608K), 0.0009694 secs] [Times: user=0.00 
sys=0.00, real=0.00 secs] 
2010-04-13T22:09:58.464+0000: 12.250: [CMS-concurrent-mark-start]
2010-04-13T22:10:01.522+0000: 15.308: [CMS-concurrent-mark: 0.024/3.058 
secs] [Times: user=3.29 sys=1.09, real=3.06 secs] 
2010-04-13T22:10:01.522+0000: 15.308: [CMS-concurrent-preclean-start]
2010-04-13T22:10:01.539+0000: 15.325: [CMS-concurrent-preclean: 
0.016/0.017 secs] [Times: user=0.03 sys=0.05, real=0.02 secs] 
2010-04-13T22:10:01.539+0000: 15.325: 
[CMS-concurrent-abortable-preclean-start]
2010-04-13T22:10:08.650+0000: 22.436: [GC 22.437: [ParNew
Desired survivor size 14745600 bytes, new threshold 1 (max 1)
- age   1:    8049864 bytes,    8049864 total
- age   2:        112 bytes,    8049976 total
: 16352000K->7981K(16368000K), 0.0305746 secs] 
16355679K->11661K(16564608K), 0.0312194 secs] [Times: user=0.14 sys=0.05, 
real=0.03 secs] 
 CMS: abort preclean due to time 2010-04-13T22:13:56.812+0000: 250.598: 
[CMS-concurrent-abortable-preclean: 0.013/235.273 secs] [Times: user=48.48 
sys=11.66, real=235.27 secs] 
2010-04-13T22:13:56.814+0000: 250.599: [GC[YG occupancy: 7376304 K 
(16368000 K)]250.600: [Rescan (parallel) , 1.9740400 secs]252.574: [weak 
refs processing, 0.0015189 secs] [1 CMS-remark: 3679K(196608K)] 
7379983K(16564608K), 1.9759675 secs] [Times: user=17.08 sys=0.82, 
real=1.98 secs] 
2010-04-13T22:13:58.791+0000: 252.576: [CMS-concurrent-sweep-start]
2010-04-13T22:13:58.796+0000: 252.581: [CMS-concurrent-sweep: 0.005/0.005 
secs] [Times: user=0.04 sys=0.02, real=0.01 secs] 
2010-04-13T22:13:58.800+0000: 252.585: [CMS-concurrent-reset-start]
2010-04-13T22:13:58.805+0000: 252.591: [CMS-concurrent-reset: 0.006/0.006 
secs] [Times: user=0.03 sys=0.01, real=0.01 secs] 
2010-04-13T22:47:09.067+0000: 2242.850: [GC 2242.851: [ParNew
Desired survivor size 14745600 bytes, new threshold 1 (max 1)
- age   1:    7803368 bytes,    7803368 total
: 16359981K->12388K(16368000K), 0.0589077 secs] 
16363570K->24406K(16564608K) icms_dc=5 , 0.0593692 secs] [Times: user=0.18 
sys=0.06, real=0.06 secs] 
2010-04-13T23:05:29.072+0000: 3342.854: [GC [1 CMS-initial-mark: 
12018K(196608K)] 7811496K(16564608K), 4.2147116 secs] [Times: user=4.15 
sys=0.06, real=4.22 secs] 
2010-04-13T23:05:33.288+0000: 3347.070: [CMS-concurrent-mark-start]
2010-04-13T23:05:33.343+0000: 3347.125: [CMS-concurrent-mark: 0.048/0.056 
secs] [Times: user=0.35 sys=0.15, real=0.06 secs] 
2010-04-13T23:05:33.344+0000: 3347.126: [CMS-concurrent-preclean-start]
2010-04-13T23:05:33.347+0000: 3347.128: [CMS-concurrent-preclean: 
0.003/0.003 secs] [Times: user=0.01 sys=0.01, real=0.00 secs] 
2010-04-13T23:05:33.347+0000: 3347.129: 
[CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2010-04-13T23:05:38.456+0000: 3352.238: 
[CMS-concurrent-abortable-preclean: 0.573/5.109 secs] [Times: user=0.94 
sys=0.24, real=5.11 secs] 
2010-04-13T23:05:38.461+0000: 3352.243: [GC[YG occupancy: 7824966 K 
(16368000 K)]3352.243: [Rescan (parallel) , 4.2295340 secs]3356.473: [weak 
refs processing, 0.0000422 secs] [1 CMS-remark: 12018K(196608K)] 
7836984K(16564608K), 4.2298963 secs] [Times: user=36.56 sys=1.65, 
real=4.23 secs] 
2010-04-13T23:05:42.692+0000: 3356.473: [CMS-concurrent-sweep-start]
2010-04-13T23:05:42.765+0000: 3356.547: [CMS-concurrent-sweep: 0.018/0.074 
secs] [Times: user=0.13 sys=0.05, real=0.07 secs] 
2010-04-13T23:05:42.768+0000: 3356.549: [CMS-concurrent-reset-start]
2010-04-13T23:05:42.771+0000: 3356.552: [CMS-concurrent-reset: 0.003/0.003 
secs] [Times: user=0.01 sys=0.01, real=0.00 secs] 
2010-04-13T23:40:49.463+0000: 5463.242: [GC 5463.243: [ParNew
Desired survivor size 14745600 bytes, new threshold 1 (max 1)
- age   1:    4876232 bytes,    4876232 total
: 16364388K->6895K(16368000K), 0.0338554 secs] 
16375925K->21493K(16564608K) icms_dc=0 , 0.0342923 secs] [Times: user=0.12 
sys=0.04, real=0.03 secs] 
2010-04-14T00:41:32.410+0000: 9106.186: [GC 9106.186: [ParNew
Desired survivor size 14745600 bytes, new threshold 1 (max 1)
- age   1:    7471944 bytes,    7471944 total
: 16358895K->8975K(16368000K), 0.0301672 secs] 
16373493K->23921K(16564608K) icms_dc=0 , 0.0306159 secs] [Times: user=0.12 
sys=0.03, real=0.03 secs] 
2010-04-14T01:42:59.422+0000: 12793.193: [GC 12793.193: [ParNew
Desired survivor size 14745600 bytes, new threshold 1 (max 1)
- age   1:    6720592 bytes,    6720592 total
: 16360975K->10859K(16368000K), 0.1057987 secs] 
16375921K->28778K(16564608K) icms_dc=0 , 0.1062338 secs] [Times: user=0.12 
sys=0.14, real=0.11 secs] 2010-04-14T02:46:12.795+0000: 16586.561: [GC 
16586.561: [ParNew
Desired survivor size 14745600 bytes, new threshold 1 (max 1)
- age   1:    6370400 bytes,    6370400 total
: 16362859K->7334K(16368000K), 0.0498029 secs] 
16380778K->27405K(16564608K) icms_dc=0 , 0.0502474 secs] [Times: user=0.10 
sys=0.04, real=0.05 secs] 
2010-04-14T03:54:06.986+0000: 20660.747: [GC 20660.747: [ParNew
Desired survivor size 14745600 bytes, new threshold 1 (max 1)
- age   1:    5864544 bytes,    5864544 total
: 16359334K->8803K(16368000K), 0.0434378 secs] 
16379405K->30657K(16564608K) icms_dc=0 , 0.0439089 secs] [Times: user=0.10 
sys=0.03, real=0.04 secs] 

Cheers
Matt

Matt Khan
--------------------------------------------------
GFFX Auto Trading
Deutsche Bank, London

---

This e-mail may contain confidential and/or privileged information. If you are not the intended recipient (or have received this e-mail in error) please notify the sender immediately and delete this e-mail. Any unauthorized copying, disclosure or distribution of the material in this e-mail is strictly forbidden.

Please refer to http://www.db.com/en/content/eu_disclosures.htm for additional EU corporate and regulatory disclosures.