0 Replies Latest reply: Dec 3, 2012 7:41 AM by 977207 RSS

    The app repeats doing CMS gc

    977207
      From the gc log, it can be seen that the jvm continually does CMS gc, but this should not happen because no MEM region is full. It causes heavy CPU load, and affects the performance of the app. How should I fix it?

      The jvm version is:
      java version "1.6.0_32"
      Java(TM) SE Runtime Environment (build 1.6.0_32-b05)
      Java HotSpot(TM) 64-Bit Server VM (build 20.7-b02, mixed mode)

      The jvm parameters are:
      -Xloggc:/home/work/zookeeper/zookeeper/bin/../../logs/zk.gc.log -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintHeapAtGC -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+CMSClassUnloadingEnabled -XX:CMSInitiatingOccupancyFraction=80 -XX:+UseCMSCompactAtFullCollection -XX:CMSFullGCsBeforeCompaction=0 -XX:-CMSParallelRemarkEnabled -XX:SoftRefLRUPolicyMSPerMB=0 -XX:MaxTenuringThreshold=7 -Xmx40960m -Xms40960m -Xmn4096m -XX:SurvivorRatio=8 -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.local.only=false


      The gc log looks like:

      2012-12-03T21:36:21.318+0800: 540992.881: [GC [1 CMS-initial-mark: 231752K(37748736K)] 277522K(41523648K), 0.0098000 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
      2012-12-03T21:36:21.328+0800: 540992.891: [CMS-concurrent-mark-start]
      2012-12-03T21:36:21.617+0800: 540993.180: [CMS-concurrent-mark: 0.287/0.289 secs] [Times: user=0.70 sys=0.11, real=0.29 secs]
      2012-12-03T21:36:21.617+0800: 540993.180: [CMS-concurrent-preclean-start]
      2012-12-03T21:36:21.730+0800: 540993.293: [CMS-concurrent-preclean: 0.107/0.113 secs] [Times: user=0.12 sys=0.02, real=0.11 secs]
      2012-12-03T21:36:21.730+0800: 540993.293: [CMS-concurrent-abortable-preclean-start]
      CMS: abort preclean due to time 2012-12-03T21:36:26.840+0800: 540998.402: [CMS-concurrent-abortable-preclean: 5.029/5.109 secs] [Times: user=7.23 sys=0.97, real=5.11 secs]
      2012-12-03T21:36:26.840+0800: 540998.402: [GC[YG occupancy: 664470 K (3774912 K)]540998.402: [Rescan (non-parallel) 540998.402: [grey object rescan, 0.0033470 secs]540998.406: [root rescan, 0.3562490 secs], 0.3596340 secs]540998.762: [weak refs processing, 0.0000110 secs]540998.762: [class unloading, 0.0016050 secs]540998.764: [scrub symbol & string tables, 0.0015880 secs] [1 CMS-remark: 231752K(37748736K)] 896222K(41523648K), 0.3634930 secs] [Times: user=0.36 sys=0.00, real=0.37 secs]
      2012-12-03T21:36:27.203+0800: 540998.766: [CMS-concurrent-sweep-start]
      2012-12-03T21:36:27.360+0800: 540998.923: [CMS-concurrent-sweep: 0.157/0.157 secs] [Times: user=0.24 sys=0.04, real=0.15 secs]
      2012-12-03T21:36:27.360+0800: 540998.923: [CMS-concurrent-reset-start]
      2012-12-03T21:36:27.442+0800: 540999.005: [CMS-concurrent-reset: 0.082/0.082 secs] [Times: user=0.11 sys=0.02, real=0.09 secs]
      2012-12-03T21:36:29.443+0800: 541001.006: [GC [1 CMS-initial-mark: 231751K(37748736K)] 1092289K(41523648K), 0.4426390 secs] [Times: user=0.44 sys=0.00, real=0.44 secs]
      2012-12-03T21:36:29.886+0800: 541001.449: [CMS-concurrent-mark-start]
      2012-12-03T21:36:30.166+0800: 541001.729: [CMS-concurrent-mark: 0.280/0.280 secs] [Times: user=0.67 sys=0.07, real=0.28 secs]
      2012-12-03T21:36:30.166+0800: 541001.729: [CMS-concurrent-preclean-start]
      2012-12-03T21:36:30.334+0800: 541001.897: [CMS-concurrent-preclean: 0.145/0.168 secs] [Times: user=0.18 sys=0.07, real=0.17 secs]
      2012-12-03T21:36:30.335+0800: 541001.897: [CMS-concurrent-abortable-preclean-start]
      CMS: abort preclean due to time 2012-12-03T21:36:35.432+0800: 541006.995: [CMS-concurrent-abortable-preclean: 5.021/5.098 secs] [Times: user=7.32 sys=1.00, real=5.10 secs]
      2012-12-03T21:36:35.433+0800: 541006.995: [GC[YG occupancy: 1428754 K (3774912 K)]541006.995: [Rescan (non-parallel) 541006.995: [grey object rescan, 0.0048800 secs]541007.000: [root rescan, 0.8390170 secs], 0.8439350 secs]541007.839: [weak refs processing, 0.0000100 secs]541007.839: [class unloading, 0.0016140 secs]541007.841: [scrub symbol & string tables, 0.0015830 secs] [1 CMS-remark: 231751K(37748736K)] 1660506K(41523648K), 0.8477980 secs] [Times: user=0.85 sys=0.00, real=0.84 secs]
      2012-12-03T21:36:36.280+0800: 541007.843: [CMS-concurrent-sweep-start]
      2012-12-03T21:36:36.437+0800: 541008.000: [CMS-concurrent-sweep: 0.157/0.157 secs] [Times: user=0.27 sys=0.07, real=0.16 secs]
      2012-12-03T21:36:36.438+0800: 541008.000: [CMS-concurrent-reset-start]
      2012-12-03T21:36:36.519+0800: 541008.082: [CMS-concurrent-reset: 0.082/0.082 secs] [Times: user=0.12 sys=0.02, real=0.08 secs]
      2012-12-03T21:36:38.522+0800: 541010.084: [GC [1 CMS-initial-mark: 231751K(37748736K)] 1985608K(41523648K), 0.9436770 secs] [Times: user=0.95 sys=0.00, real=0.95 secs]
      2012-12-03T21:36:39.465+0800: 541011.028: [CMS-concurrent-mark-start]
      2012-12-03T21:36:39.758+0800: 541011.321: [CMS-concurrent-mark: 0.286/0.293 secs] [Times: user=1.03 sys=0.15, real=0.29 secs]
      2012-12-03T21:36:39.758+0800: 541011.321: [CMS-concurrent-preclean-start]
      2012-12-03T21:36:39.939+0800: 541011.502: [CMS-concurrent-preclean: 0.154/0.181 secs] [Times: user=0.37 sys=0.09, real=0.18 secs]
      2012-12-03T21:36:39.940+0800: 541011.502: [CMS-concurrent-abortable-preclean-start]
      CMS: abort preclean due to time 2012-12-03T21:36:45.040+0800: 541016.603: [CMS-concurrent-abortable-preclean: 5.022/5.100 secs] [Times: user=6.14 sys=0.98, real=5.10 secs]
      2012-12-03T21:36:45.040+0800: 541016.603: [GC[YG occupancy: 2322836 K (3774912 K)]541016.603: [Rescan (non-parallel) 541016.603: [grey object rescan, 0.0032300 secs]541016.606: [root rescan, 1.3647710 secs], 1.3680480 secs]541017.971: [weak refs processing, 0.0000100 secs]541017.971: [class unloading, 0.0016300 secs]541017.973: [scrub symbol & string tables, 0.0015810 secs] [1 CMS-remark: 231751K(37748736K)] 2554588K(41523648K), 1.3719240 secs] [Times: user=1.37 sys=0.00, real=1.38 secs]
      2012-12-03T21:36:46.412+0800: 541017.975: [CMS-concurrent-sweep-start]
      2012-12-03T21:36:46.569+0800: 541018.132: [CMS-concurrent-sweep: 0.157/0.157 secs] [Times: user=0.31 sys=0.12, real=0.15 secs]
      2012-12-03T21:36:46.569+0800: 541018.132: [CMS-concurrent-reset-start]
      2012-12-03T21:36:46.651+0800: 541018.214: [CMS-concurrent-reset: 0.082/0.082 secs] [Times: user=0.11 sys=0.02, real=0.08 secs]
      2012-12-03T21:36:48.653+0800: 541020.215: [GC [1 CMS-initial-mark: 231751K(37748736K)] 2877080K(41523648K), 1.4493290 secs] [Times: user=1.45 sys=0.00, real=1.44 secs]
      2012-12-03T21:36:50.102+0800: 541021.665: [CMS-concurrent-mark-start]
      2012-12-03T21:36:50.388+0800: 541021.951: [CMS-concurrent-mark: 0.283/0.286 secs] [Times: user=1.04 sys=0.20, real=0.29 secs]
      2012-12-03T21:36:50.388+0800: 541021.951: [CMS-concurrent-preclean-start]
      2012-12-03T21:36:50.573+0800: 541022.136: [CMS-concurrent-preclean: 0.157/0.185 secs] [Times: user=0.29 sys=0.13, real=0.19 secs]
      2012-12-03T21:36:50.573+0800: 541022.136: [CMS-concurrent-abortable-preclean-start]
      CMS: abort preclean due to time 2012-12-03T21:36:55.693+0800: 541027.255: [CMS-concurrent-abortable-preclean: 5.036/5.119 secs] [Times: user=6.13 sys=0.98, real=5.12 secs]
      2012-12-03T21:36:55.693+0800: 541027.256: [GC[YG occupancy: 3274549 K (3774912 K)]541027.256: [Rescan (non-parallel) 541027.256: [grey object rescan, 0.0028090 secs]541027.258: [root rescanc, 1.9476740 secs], 1.9505210 secs]541029.206: [weak refs processing, 0.0000110 secs]541029.206: [class unloading, 0.0016280 secs]541029.208: [scrub symbol & string tables, 0.0015800 secs] [1 CMS-remark: 231751K(37748736K)] 3506301K(41523648K), 1.9543950 secs] [Times: user=1.96 sys=0.00, real=1.95 secs]
      2012-12-03T21:36:57.647+0800: 541029.210: [CMS-concurrent-sweep-start]
      {Heap before GC invocations=13361 (full 27024):
      par new generation   total 3774912K, used 3387766K [0x000000302c920000, 0x000000312c920000, 0x000000312c920000)
        eden space 3355520K, 100% used [0x000000302c920000, 0x00000030f9600000, 0x00000030f9600000)
        from space 419392K,   7% used [0x00000030f9600000, 0x00000030fb57d8a0, 0x0000003112f90000)
        to   space 419392K,   0% used [0x0000003112f90000, 0x0000003112f90000, 0x000000312c920000)
      concurrent mark-sweep generation total 37748736K, used 231751K [0x000000312c920000, 0x0000003a2c920000, 0x0000003a2c920000)
      concurrent-mark-sweep perm gen total 24564K, used 14108K [0x0000003a2c920000, 0x0000003a2e11d000, 0x0000003a31b20000)
      2012-12-03T21:36:57.766+0800: 541029.329: [GC 541029.329: [ParNew: 3387766K->29628K(3774912K), 0.0156690 secs] 3619517K->261382K(41523648K), 0.0157240 secs]c [Times: user=0.11 sys=0.01, real=0.02 secs]
      Heap after GC invocations=13362 (full 27024):
      par new generation total 3774912K, used 29628K [0x000000302c920000, 0x000000312c920000, 0x000000312c920000)
      eden space 3355520K, 0% used [0x000000302c920000, 0x000000302c920000, 0x00000030f9600000)
      from space 419392K, 7% used [0x0000003112f90000, 0x0000003114c7f270, 0x000000312c920000)
      to space 419392K, 0% used [0x00000030f9600000, 0x00000030f9600000, 0x0000003112f90000)
      concurrent mark-sweep generation total 37748736K, used 231754K [0x000000312c920000, 0x0000003a2c920000, 0x0000003a2c920000)
      concurrent-mark-sweep perm gen total 24564K, used 14108K [0x0000003a2c920000, 0x0000003a2e11d000, 0x0000003a31b20000)
      }
      2012-12-03T21:36:57.823+0800: 541029.386: [CMS-concurrent-sweep: 0.157/0.176 secs] [Times: user=0.48 sys=0.12, real=0.18 secs]
      2012-12-03T21:36:57.823+0800: 541029.386: [CMS-concurrent-reset-start]
      2012-12-03T21:36:57.907+0800: 541029.470: [CMS-concurrent-reset: 0.084/0.084 secs] [Times: user=0.15 sys=0.07, real=0.08 secs]
      2012-12-03T21:36:59.236+0800: 541030.799: [GC