long unaccounted pause during concurrent mark phase of ParNew cycle
atulksh
atulksh at hotmail.com
Thu Feb 4 23:03:03 UTC 2010
Hi Jon,
Thanks for your response. Actually the 36 seconds that it is reporting that
it took for the concurrent mark phase is correct. But the time I am
mentioning is in between two ParNew cycles during the concurrent mark phase.
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]
Notice that the two ParNews happened 29 seconds apart. During this period
what we see is our app is hung and not accepting any new requests. It is as
though the application is frozen for that amount of time. We noticed this
because our users complained about the app not responding quickly sometimes.
After analysing our logs, we realized this was the point where that
happened. Otherwise this would just look like normal GC activity.
One more thing that we see is in our GC logs these are the only times when
there is such a long gap between two ParNew cycles. Otherwise we get ParNew
pretty much every second, at a few seconds apart at max.
Atul
Jon Masamitsu wrote:
>
> Atul,
>
> Do you mean the 36 secs here?
>
> > 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]
>
> That is a concurrent phase (i.e., the application threads
> are still running although they have to share the hardware
> threads with the concurrent GC threads).
>
> Jon
>
> On 02/04/10 12:37, atulksh wrote:
>> 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-tp27459365p27461205.html
Sent from the OpenJDK Hotspot Garbage Collection mailing list archive at Nabble.com.
More information about the hotspot-gc-dev
mailing list