long unaccounted pause during concurrent mark phase of ParNew cycle
atulksh
atulksh at hotmail.com
Thu Feb 4 20:37:35 UTC 2010
Hi,
We have an application that is freezing (pausing) for a very long (tens of
seconds) time during the concurrent mark phase of the ParNew cycle. This
pause is consistently seen when there is good amount of activity on the
server. We tried to upgrade the JVM (JRE 6) from Update 02 to Update 17
keeping all the parameters same, but the pauses did not go away (they became
more consistent and slightly longer). We even tried to enable CompressedOops
option, thinking that that would reduce memory requirements, but that has
not helped.
We are running on 64bit SUSE 10.1 platform with 32Gb of RAM and 8 core
machine. 26g is allocated to the java process. The full set of VM parameters
are here
-Xmx26g
-Xms26g
-server
-XX:+UseConcMarkSweepGC
-XX:PermSize=256m
-XX:MaxPermSize=256m
-XX:+PrintTenuringDistribution
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:CMSInitiatingOccupancyFraction=70
-XX:-CMSParallelRemarkEnabled
The nature of the pause is like this. All the application threads that are
being processed seem to stop responding. New requests that come to our app
server are not processed and get queued. When the pause ends then everything
frees up and seems to go on normally henceforth. In the GC you see a gap
between the ParNews. The following are two examples of the pauses. Notice
the pause from 10:13:06 to 10:13:35 (29 seconds) in the first one and
11:29:04 to 11:29:17 (13 seconds) in the second one. These pauses only occur
in the concurrent mark phase. They do not seem to occur at any other time or
anywhere else in the CMS cycle.
....
Thu Feb 4 10:12:59 2010: [GC [1 CMS-initial-mark: 18976170K(27092608K)]
18989786K(27245952K), 0.0059140 secs] [Times: user=0.01 sys=0.00, real=0.01
secs]
Thu Feb 4 10:12:59 2010: [CMS-concurrent-mark-start]
Thu Feb 4 10:12:59 2010 [18,980,009 K]: [GC 42035.293: [ParNew Desired
survivor size 8716288 bytes, new threshold 4 (max 4) - age 1: 1833064
bytes, 1833064 total - age 2: 18472 bytes, 1851536 total :
148315K->3839K(153344K), 0.0400230 secs] 19124486K->18980009K(27245952K),
0.0401580 secs] [Times: user=0.25 sys=0.00, real=0.04 secs]
Thu Feb 4 10:12:59 2010 [18,979,036 K]: [GC 42035.415: [ParNew Desired
survivor size 8716288 bytes, new threshold 4 (max 4) - age 1: 2068376
bytes, 2068376 total - age 2: 23792 bytes, 2092168 total - age
3: 18472 bytes, 2110640 total : 140159K->2866K(153344K), 0.0352200
secs] 19116329K->18979036K(27245952K), 0.0353520 secs] [Times: user=0.29
sys=0.00, real=0.03 secs]
Thu Feb 4 10:12:59 2010 [18,979,103 K]: [GC 42035.535: [ParNew Desired
survivor size 8716288 bytes, new threshold 4 (max 4) - age 1: 1782608
bytes, 1782608 total - age 2: 22032 bytes, 1804640 total - age
3: 23792 bytes, 1828432 total - age 4: 18472 bytes,
1846904 total : 139186K->2933K(153344K), 0.0498480 secs]
19115356K->18979103K(27245952K), 0.0499850 secs] [Times: user=0.24 sys=0.00,
real=0.05 secs]
Thu Feb 4 10:12:59 2010 [18,979,181 K]: [GC 42035.673: [ParNew Desired
survivor size 8716288 bytes, new threshold 4 (max 4) - age 1: 2161000
bytes, 2161000 total - age 2: 22032 bytes, 2183032 total - age
3: 22032 bytes, 2205064 total - age 4: 23792 bytes,
2228856 total : 139253K->2992K(153344K), 0.0400420 secs]
19115423K->18979181K(27245952K), 0.0401730 secs] [Times: user=0.26 sys=0.00,
real=0.04 secs]
Thu Feb 4 10:13:06 2010 [18,979,876 K]: [GC 42042.243: [ParNew Desired
survivor size 8716288 bytes, new threshold 4 (max 4) - age 1: 2113272
bytes, 2113272 total - age 2: 23792 bytes, 2137064 total - age
3: 22032 bytes, 2159096 total - age 4: 22032 bytes,
2181128 total : 138855K->3662K(153344K), 0.0465500 secs]
19115044K->18979876K(27245952K), 0.0466840 secs] [Times: user=0.27 sys=0.00,
real=0.04 secs]
Thu Feb 4 10:13:35 2010 [18,979,051 K]: [GC 42071.809: [ParNew Desired
survivor size 8716288 bytes, new threshold 4 (max 4) - age 1: 219056
bytes, 219056 total - age 2: 1867632 bytes, 2086688 total - age
3: 23792 bytes, 2110480 total - age 4: 22032 bytes,
2132512 total : 139982K->2814K(153344K), 0.0426920 secs]
19116196K->18979051K(27245952K), 0.0428200 secs] [Times: user=0.28 sys=0.00,
real=0.05 secs]
Thu Feb 4 10:13:35 2010: [CMS-concurrent-mark: 36.272/36.715 secs] [Times:
user=56.34 sys=0.34, real=36.71 secs]
....
....
Thu Feb 4 11:28:59 2010: [GC [1 CMS-initial-mark: 19012252K(27092608K)]
19032719K(27245952K), 0.0279440 secs] [Times: user=0.02 sys=0.00, real=0.03
secs]
Thu Feb 4 11:28:59 2010: [CMS-concurrent-mark-start]
Thu Feb 4 11:28:59 2010 [19,154,661 K]: [GC 46595.614: [ParNew Desired
survivor size 8716288 bytes, new threshold 1 (max 4) - age 1: 17431976
bytes, 17431976 total : 153344K->17024K(153344K), 0.9259390 secs]
19165596K->19154661K(27245952K), 0.9260890 secs] [Times: user=1.23 sys=0.05,
real=0.93 secs]
Thu Feb 4 11:29:00 2010 [19,199,696 K]: [GC 46596.973: [ParNew Desired
survivor size 8716288 bytes, new threshold 1 (max 4) - age 1: 17448432
bytes, 17448432 total : 153344K->17024K(153344K), 0.3054460 secs]
19290981K->19199696K(27245952K), 0.3055930 secs] [Times: user=0.79 sys=0.07,
real=0.31 secs]
Thu Feb 4 11:29:01 2010 [19,229,358 K]: [GC 46597.722: [ParNew Desired
survivor size 8716288 bytes, new threshold 1 (max 4) - age 1: 10331408
bytes, 10331408 total : 153344K->17024K(153344K), 0.1449040 secs]
19336016K->19229358K(27245952K), 0.1450630 secs] [Times: user=0.59 sys=0.02,
real=0.15 secs]
Thu Feb 4 11:29:02 2010 [19,240,015 K]: [GC 46598.038: [ParNew Desired
survivor size 8716288 bytes, new threshold 1 (max 4) - age 1: 17354120
bytes, 17354120 total : 153344K->17024K(153344K), 0.0935440 secs]
19365678K->19240015K(27245952K), 0.0936870 secs] [Times: user=0.59 sys=0.00,
real=0.10 secs]
Thu Feb 4 11:29:02 2010 [19,302,509 K]: [GC 46598.347: [ParNew Desired
survivor size 8716288 bytes, new threshold 1 (max 4) - age 1: 17432360
bytes, 17432360 total : 151519K->17024K(153344K), 0.4619430 secs]
19374510K->19302509K(27245952K), 0.4620890 secs] [Times: user=1.19 sys=0.02,
real=0.46 secs]
Thu Feb 4 11:29:03 2010 [19,329,594 K]: [GC 46599.030: [ParNew Desired
survivor size 8716288 bytes, new threshold 1 (max 4) - age 1: 11933296
bytes, 11933296 total : 153344K->17024K(153344K), 0.1492670 secs]
19438829K->19329594K(27245952K), 0.1494200 secs] [Times: user=0.77 sys=0.03,
real=0.15 secs]
Thu Feb 4 11:29:03 2010 [19,337,176 K]: [GC 46599.423: [ParNew Desired
survivor size 8716288 bytes, new threshold 4 (max 4) - age 1: 5719032
bytes, 5719032 total : 153344K->12852K(153344K), 0.0675180 secs]
19465914K->19337176K(27245952K), 0.0676670 secs] [Times: user=0.46 sys=0.02,
real=0.07 secs]
Thu Feb 4 11:29:03 2010 [19,338,256 K]: [GC 46599.754: [ParNew Desired
survivor size 8716288 bytes, new threshold 2 (max 4) - age 1: 6783616
bytes, 6783616 total - age 2: 5570080 bytes, 12353696 total :
149172K->13931K(153344K), 0.0650520 secs] 19473496K->19338256K(27245952K),
0.0652060 secs] [Times: user=0.42 sys=0.01, real=0.07 secs]
Thu Feb 4 11:29:04 2010 [19,340,264 K]: [GC 46600.144: [ParNew Desired
survivor size 8716288 bytes, new threshold 2 (max 4) - age 1: 2190136
bytes, 2190136 total - age 2: 6762648 bytes, 8952784 total :
150251K->10375K(153344K), 0.0709470 secs] 19474576K->19340264K(27245952K),
0.0710920 secs] [Times: user=0.48 sys=0.01, real=0.07 secs]
Thu Feb 4 11:29:17 2010 [19,345,928 K]: [GC 46613.628: [ParNew Desired
survivor size 8716288 bytes, new threshold 4 (max 4) - age 1: 760488
bytes, 760488 total - age 2: 2173472 bytes, 2933960 total :
146695K->9279K(153344K), 0.0689390 secs] 19476584K->19345928K(27245952K),
0.0691070 secs] [Times: user=0.45 sys=0.00, real=0.07 secs]
Thu Feb 4 11:29:17 2010: [CMS-concurrent-mark: 15.853/18.260 secs] [Times:
user=29.26 sys=0.55, real=18.26 secs]
Thu Feb 4 11:29:17 2010: [CMS-concurrent-preclean-start]
....
Any idea what may causing these pauses and what possible JVM tuning would be
neccessary to avoid these pauses? Your help greatly appreciated.
Thank you very much.
Atul
--
View this message in context: http://old.nabble.com/long-unaccounted-pause-during-concurrent-mark-phase-of-ParNew-cycle-tp27459365p27459365.html
Sent from the OpenJDK Hotspot Garbage Collection mailing list archive at Nabble.com.
More information about the hotspot-gc-dev
mailing list