CMS concurrent phase takes too long time
843829Aug 13 2009 — edited Oct 9 2009We have a problem that CMS-remark time takes about 1.5 secs which is inappropriate for our app.
JVM parameters are:
-server -XX:PermSize=256m -XX:+CMSParallelRemarkEnabled -XX:CMSInitiatingOccupancyFraction=70 -XX:+UseCMSInitiatingOccupancyOnly -XX:+DoEscapeAnalysis -Xmx6000M -Xms6000M -XX:+UseConcMarkSweepGC -XX:+PrintGCTimeStamps -XX:+PrintGCDetails
Sample of GC log is:
11421,845: [GC 11421,845: [ParNew: 151142K->11964K(153344K), 0,0381950 secs] 4306109K->4174832K(6126976K), 0,0382790 secs] [Times: user=0,23 sys=0,03, real=0,04 secs]
11429,050: [GC 11429,050: [ParNew: 148284K->12240K(153344K), 0,0381560 secs] 4311152K->4182703K(6126976K), 0,0382390 secs] [Times: user=0,23 sys=0,01, real=0,03 secs]
11436,450: [GC 11436,450: [ParNew: 148560K->12274K(153344K), 0,0836100 secs] 4319023K->4189891K(6126976K), 0,0836920 secs] [Times: user=0,20 sys=0,02, real=0,08 secs]
11444,078: [GC 11444,078: [ParNew: 148594K->13071K(153344K), 0,0513830 secs] 4326211K->4197787K(6126976K), 0,0514660 secs] [Times: user=0,32 sys=0,00, real=0,05 secs]
11444,166: [GC [1 CMS-initial-mark: 4184715K(5973632K)] 4198023K(6126976K), 0,0140900 secs] [Times: user=0,02 sys=0,00, real=0,02 secs]
11444,180: [CMS-concurrent-mark-start]
11446,600: [CMS-concurrent-mark: 2,420/2,420 secs] [Times: user=5,32 sys=0,16, real=2,42 secs]
11446,600: [CMS-concurrent-preclean-start]
11447,165: [CMS-concurrent-preclean: 0,562/0,565 secs] [Times: user=0,74 sys=0,06, real=0,56 secs]
11447,165: [CMS-concurrent-abortable-preclean-start]
11451,435: [GC 11451,435: [ParNew: 149391K->13380K(153344K), 0,0441070 secs] 4334107K->4205327K(6126976K), 0,0441910 secs] [Times: user=0,30 sys=0,02, real=0,05 secs]
CMS: abort preclean due to time 11452,169: [CMS-concurrent-abortable-preclean: 4,932/5,004 secs] [Times: user=5,88 sys=0,17, real=5,01 secs]
11452,170: [GC[YG occupancy: 29204 K (153344 K)]11452,170: [Rescan (parallel) , 0,0111590 secs]11452,181: [weak refs processing, 0,9491600 secs] [1 CMS-remark: 4191947K(5973632K)] 4221151K(6126976K), 1,4008690 secs] [Times: user=1,45 sys=0,01, real=1,40 secs]
11453,572: [CMS-concurrent-sweep-start]
11457,005: [CMS-concurrent-sweep: 3,432/3,434 secs] [Times: user=6,08 sys=0,39, real=3,43 secs]
11457,005: [CMS-concurrent-reset-start]
11457,040: [CMS-concurrent-reset: 0,035/0,035 secs] [Times: user=0,04 sys=0,02, real=0,04 secs]
11458,517: [GC 11458,517: [ParNew: 149700K->17024K(153344K), 0,1692510 secs] 1245351K->1120297K(6126976K), 0,1693320 secs] [Times: user=1,10 sys=0,08, real=0,17 secs]
11465,585: [GC 11465,585: [ParNew: 153344K->17024K(153344K), 0,0793740 secs] 1256617K->1130603K(6126976K), 0,0794570 secs] [Times: user=0,28 sys=0,01, real=0,08 secs]
11472,349: [GC 11472,349: [ParNew: 153344K->17024K(153344K), 0,0798080 secs] 1266923K->1141696K(6126976K), 0,0798890 secs] [Times: user=0,34 sys=0,01, real=0,09 secs]
11479,066: [GC 11479,066: [ParNew: 153344K->16857K(153344K), 0,0559290 secs] 1278016K->1153598K(6126976K), 0,0560140 secs] [Times: user=0,40 sys=0,00, real=0,06 secs]
What can we go to decrease this time?