Long time of CMS-concurrent-mark (JDK6u20 of 64 bit)!
843829May 17 2010 — edited Aug 29 2010we have a server which has some app data about 11g and will be clean every 24hour(for 600 user's concurrent every second), so we use 64bit and CMS strategy for big memory. but I found the JVM cost a lot of time when it in
CMS-concurrent-mark phase. Our app need high response time and high throughput, but when the GC work, the app is nearly stoped, in that time all the incoming request are delayed or denied. I try to many parameter's adjust, the gc time not reduce yet. who can give me any advice? thanks very much!
follow is my environment:
*1. java -version*
java version "1.6.0_20"
Java(TM) SE Runtime Environment (build 1.6.0_20-b02)
Java HotSpot(TM) 64-Bit Server VM (build 16.3-b01, mixed mode)
*2. jvm flag:*
-Dfile.encoding=utf-8 -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime -Xloggc:/home/appSes/ses/oper/gc.log -XX:+DoEscapeAnalysis -XX:CMSFullGCsBeforeCompaction=2 -XX:GCTimeRatio=19 -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=65 -XX:+CMSScavengeBeforeRemark -XX:ParallelCMSThreads=12 -XX:CMSAbortablePrecleanWaitMillis=50 -XX:+CMSClassUnloadingEnabled -XX:+CMSConcurrentMTEnabled -XX:CMSMarkStackSize=2M -XX:CMSMarkStackSizeMax=8M -XX:+ParallelRefProcEnabled -Xms20g -Xmx20g -Xmn512m -XX:ParallelGCThreads=14 -XX:MaxPermSize=96m -Dsun.rmi.dgc.client.gcInterval=7200000 -Dsun.rmi.dgc.server.gcInterval=7200000 -XX:+UseFastAccessorMethods -XX:-UseFastEmptyMethods -XX:+UseFastJNIAccessors -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -Xnoclassgc -XX:+DisableExplicitGC -XX:+UseCMSCompactAtFullCollection -XX:+CMSParallelRemarkEnabled
*3. a piece of jstat.log which in a long time CMS:*
[2010-05-18 09:01:31] 62.55 89.17 100.00 64.84 59.90 103554 10971.403 215 40.465 11011.868
[2010-05-18 09:01:34] 100.00 0.00 98.54 65.05 59.90 103558 10971.923 216 40.638 11012.561
[2010-05-18 09:01:35] S0 S1 E O P YGC YGCT FGC FGCT GCT
[2010-05-18 09:01:35] 0.00 88.51 94.46 65.09 59.90 103559 10972.040 216 40.638 11012.678
[2010-05-18 09:01:38] 0.00 88.51 100.00 65.09 59.90 103559 10972.040 216 40.638 11012.678
[2010-05-18 09:01:41] 0.00 88.51 100.00 65.09 59.90 103559 10972.040 216 40.638 11012.678
[2010-05-18 09:01:44] 0.00 88.51 100.00 65.09 59.90 103559 10972.040 216 40.638 11012.678
[2010-05-18 09:01:47] 0.00 88.51 100.00 65.09 59.90 103559 10972.040 216 40.638 11012.678
[2010-05-18 09:01:47] S0 S1 E O P YGC YGCT FGC FGCT GCT
[2010-05-18 09:01:47] 0.00 88.51 100.00 65.09 59.90 103559 10972.040 216 40.638 11012.678
[2010-05-18 09:01:50] 0.00 88.51 100.00 65.09 59.90 103559 10972.040 216 40.638 11012.678
[2010-05-18 09:01:53] 0.00 88.51 100.00 65.09 59.90 103559 10972.040 216 40.638 11012.678
[2010-05-18 09:01:56] 71.93 100.00 100.00 65.26 59.90 103562 10972.269 216 40.638 11012.908
4. related gc.log(61490seconds is date: 2010-05-18 09:01:33):
61489.856: [GC [1 CMS-initial-mark: 13290792K(20447232K)] 13351245K(20919104K), 0.1731200 secs] [Times: user=0.17 sys=0.00, real=0.17 secs]
Total time for which application threads were stopped: 0.1781290 seconds
61490.029: [CMS-concurrent-mark-start]
61517.383: [GC 61517.383: [ParNew: 465850K->44707K(471872K), 0.1084130 secs] 13902124K->13491735K(20919104K), 0.1087710 secs] [Times: user=0.99 sys=0.02, rea
l=0.10 secs]
Total time for which application threads were stopped: 0.1135880 seconds
Application time: 0.4469450 seconds
61517.944: [GC 61517.944: [ParNew: 464163K->40162K(471872K), 0.1099520 secs] 13911191K->13497981K(20919104K), 0.1103180 secs] [Times: user=0.97 sys=0.01, rea
l=0.11 secs]
.....
61520.932: [GC 61520.933: [ParNew: 455311K->37334K(471872K), 0.1099960 secs] 13952936K->13545086K(20919104K), 0.1103340 secs] [Times: user=0.94 sys=0.02, rea
l=0.12 secs]
Total time for which application threads were stopped: 0.1149740 seconds
61521.390: [CMS-concurrent-mark: 29.006/31.360 secs] [Times: user=232.58 sys=13.16, real=31.36 secs]
61521.390: [CMS-concurrent-preclean-start]
Application time: 0.3612640 seconds
61521.410: [GC 61521.410: [ParNew: 456790K->52165K(471872K), 0.1005290 secs] 13964542K->13569067K(20919104K), 0.1008860 secs] [Times: user=0.95 sys=0.01, rea
l=0.10 secs]
Total time for which application threads were stopped: 0.1054530 seconds
Application time: 0.2823790 seconds
61526.214: [CMS-concurrent-preclean: 3.376/4.824 secs] [Times: user=32.50 sys=1.51, real=4.83 secs]
61526.214: [CMS-concurrent-abortable-preclean-start]
61527.195: [CMS-concurrent-abortable-preclean: 0.717/0.981 secs] [Times: user=5.71 sys=0.26, real=0.98 secs]
Application time: 0.0061130 seconds
61527.206: [GC[YG occupancy: 59834 K (471872 K)]61527.206: [GC 61527.206: [ParNew: 59834K->30554K(471872K), 0.0909460 secs] 13668965K->13647914K(20919104K),
0.0912800 secs] [Times: user=0.86 sys=0.02, real=0.09 secs]
61527.297: [Rescan (parallel) , 0.0379870 secs]61527.335: [weak refs processing, 0.0039690 secs]61527.339: [class unloading, 0.0136120 secs]61527.353: [scrub
symbol & string tables, 0.0088270 secs] [1 CMS-remark: 13617360K(20447232K)] 13647914K(20919104K), 0.1598230 secs] [Times: user=1.42 sys=0.02, real=0.16 sec
s]
Total time for which application threads were stopped: 0.1647720 seconds
61527.366: [CMS-concurrent-sweep-start]
61589.259: [CMS-concurrent-sweep: 50.917/61.893 secs] [Times: user=344.45 sys=16.69, real=61.89 secs]
61589.259: [CMS-concurrent-reset-start]
61589.461: [CMS-concurrent-reset: 0.202/0.202 secs] [Times: user=1.32 sys=0.07, real=0.20 secs]