記錄一次JVM調優【GC日志的分析】

本文轉載自查看原文 2018-09-12 18:17 2046 jvm

首先查看服務器版本默認信息：

修改tomcat/bin/catalina.sh，在最頂端加入JAVA_OPTS="$JAVA_OPTS -XX:+PrintGCDetails -Xloggc:/usr/local/java/apache-tomcat-7.0.78/bin/gc.log"

隨后在 -Xloggc指定路徑下，打開gc.log，部分信息如下：

[GC (Allocation Failure) [PSYoungGen: 15872K->2544K(18432K)] 15872K->4199K(60928K), 0.0076594 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
0.801: [GC (Allocation Failure) [PSYoungGen: 18416K->2554K(34304K)] 20071K->7458K(76800K), 0.0084303 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
1.102: [GC (Allocation Failure) [PSYoungGen: 34298K->2532K(34304K)] 39202K->10385K(76800K), 0.0073978 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
1.324: [GC (Allocation Failure) [PSYoungGen: 34276K->2540K(66048K)] 42129K->14849K(108544K), 0.0077529 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
1.538: [GC (Allocation Failure) [PSYoungGen: 66028K->2542K(66048K)] 78337K->25278K(108544K), 0.0107662 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
1.710: [GC (Allocation Failure) [PSYoungGen: 66030K->11795K(137216K)] 88766K->34540K(179712K), 0.0176510 secs] [Times: user=0.03 sys=0.01, real=0.02 secs]
2.065: [GC (Allocation Failure) [PSYoungGen: 136723K->14318K(139264K)] 159468K->48794K(181760K), 0.0246635 secs] [Times: user=0.04 sys=0.00, real=0.03 secs]
2.090: [Full GC (Ergonomics) [PSYoungGen: 14318K->2377K(139264K)] [ParOldGen: 34476K->42413K(78848K)] 48794K->44791K(218112K), [Metaspace: 13713K->13713K(1062912K)], 0.0826740 secs] [Times: user=0.15 sys=0.01, real=0.08 secs]
2.488: [GC (Allocation Failure) [PSYoungGen: 127305K->22522K(222720K)] 169719K->65057K(301568K), 0.0318258 secs] [Times: user=0.06 sys=0.00, real=0.03 secs]
3.086: [GC (Allocation Failure) [PSYoungGen: 222714K->26617K(268288K)] 265249K->87196K(347136K), 0.0409823 secs] [Times: user=0.07 sys=0.02, real=0.05 secs]
3.731: [GC (Allocation Failure) [PSYoungGen: 268281K->37864K(278016K)] 328860K->112315K(356864K), 0.0531917 secs] [Times: user=0.09 sys=0.02, real=0.05 secs]
3.785: [Full GC (Ergonomics) [PSYoungGen: 37864K->0K(278016K)] [ParOldGen: 74450K->59866K(113152K)] 112315K->59866K(391168K), [Metaspace: 13760K->13760K(1062912K)], 0.1234969 secs] [Times: user=0.24 sys=0.00, real=0.13 secs]
4.434: [GC (Allocation Failure) [PSYoungGen: 240128K->45645K(286208K)] 299994K->105511K(399360K), 0.0358239 secs] [Times: user=0.07 sys=0.00, real=0.04 secs]
4.989: [GC (Allocation Failure) [PSYoungGen: 285773K->42527K(269824K)] 345639K->109322K(382976K), 0.0452064 secs] [Times: user=0.09 sys=0.01, real=0.04 secs]
5.489: [GC (Allocation Failure) [PSYoungGen: 260127K->37422K(255488K)] 326922K->110639K(368640K), 0.0331642 secs] [Times: user=0.06 sys=0.00, real=0.03 secs]
7.060: [GC (Allocation Failure) [PSYoungGen: 255022K->11882K(278016K)] 328239K->89219K(391168K), 0.0199962 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]

7.328: [GC (Metadata GC Threshold) [PSYoungGen: 65740K->160K(276480K)] 143076K->81525K(389632K), 0.0071875 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
7.336: [Full GC (Metadata GC Threshold) [PSYoungGen: 160K->0K(276480K)] [ParOldGen: 81365K->30917K(90624K)] 81525K->30917K(367104K), [Metaspace: 23265K->23265K(1071104K)], 0.0701499 secs] [Times: user=0.12 sys=0.00, real=0.07 secs]
9.690: [GC (Allocation Failure) [PSYoungGen: 216064K->15373K(272896K)] 246981K->46298K(363520K), 0.0266823 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]

9.819: [GC (Metadata GC Threshold) [PSYoungGen: 25761K->8213K(274944K)] 56686K->39146K(365568K), 0.0153547 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
9.835: [Full GC (Metadata GC Threshold) [PSYoungGen: 8213K->0K(274944K)] [ParOldGen: 30933K->37095K(108032K)] 39146K->37095K(382976K), [Metaspace: 38475K->38475K(1083392K)], 0.0922216 secs] [Times: user=0.16 sys=0.00, real=0.09 secs]

77.664: [GC (Allocation Failure) [PSYoungGen: 217088K->56304K(242176K)] 254183K->119858K(350208K), 0.0250691 secs] [Times: user=0.04 sys=0.01, real=0.03 secs]
80.575: [GC (Allocation Failure) [PSYoungGen: 242160K->3375K(262144K)] 305714K->122388K(387072K), 0.0230121 secs] [Times: user=0.02 sys=0.02, real=0.03 secs]
80.599: [Full GC (Ergonomics) [PSYoungGen: 3375K->0K(262144K)] [ParOldGen: 119013K->108779K(213504K)] 122388K->108779K(475648K), [Metaspace: 54741K->54741K(1099776K)], 0.1379975 secs] [Times: user=0.24 sys=0.00, real=0.13 secs]

這里

-Xmx1038m：等價於-XX:MaxHeapSize，設置JVM最大堆內存為1038M。

-Xms64m：等價於-XX:InitialHeapSize，設置JVM初始堆內存為64M。

使用ParallelGC收集器

總共5次full gc，其中兩次是元空間（jdk8默認值21.8M左右）引發的full gc，三次是HotSpot自動選擇和調優引發的FullGC，自適應策略

改善：-XX:MetaspaceSize=64m 初始元空間大小

增加 JAVA_OPTS="$JAVA_OPTS -server -showversion -Xms512m -Xmx512m -XX:MetaspaceSize=64m"

如果-Xmx分配過大，會導致無法為其他tomcat分配內存：There is insufficient memory for the Java Runtime Environment to continue.這里嘗試之后，選擇512m

可以看見

Java HotSpot(TM) 64-Bit Server VM (25.144-b01) for linux-amd64 JRE (1.8.0_144-b01), built on Jul 21 2017 21:57:33 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
Memory: 4k page, physical 4056480k(1077372k free), swap 0k(0k free)
CommandLine flags: -XX:InitialHeapSize=2147483648 -XX:MaxHeapSize=2147483648 -XX:MetaspaceSize=67108864 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC
2.563: [GC (Allocation Failure) [PSYoungGen: 524800K->85308K(611840K)] 524800K->85388K(2010112K), 0.1003043 secs] [Times: user=0.17 sys=0.02, real=0.10 secs]
3.991: [GC (Allocation Failure) [PSYoungGen: 610108K->87037K(611840K)] 610188K->103584K(2010112K), 0.1100503 secs] [Times: user=0.17 sys=0.04, real=0.11 secs]
5.245: [GC (Allocation Failure) [PSYoungGen: 611837K->87018K(611840K)] 628384K->140886K(2010112K), 0.1087186 secs] [Times: user=0.12 sys=0.03, real=0.11 secs]
8.794: [GC (Allocation Failure) [PSYoungGen: 611818K->62918K(611840K)] 665686K->116794K(2010112K), 0.0452909 secs] [Times: user=0.08 sys=0.00, real=0.04 secs]
38.881: [GC (Allocation Failure) [PSYoungGen: 587718K->87036K(611840K)] 641594K->186752K(2010112K), 0.1298147 secs] [Times: user=0.09 sys=0.12, real=0.13 secs]

在38ms之前是減少了4次full gc

重點觀察，新生代->老年代的增量，避免promotion failed. 新生代的差量（預計回收，因為先minor gc，再old判斷）-heap的差量（實際回收）=老年代的增量

eg：5.245: [GC (Allocation Failure) [PSYoungGen: 611837K->87018K(611840K)] 628384K->140886K(2010112K), 0.1087186 secs] [Times: user=0.12 sys=0.03, real=0.11 secs]

old= 611837-87018K-（628384-140886）=37321K，老年代增長了37M左右

繼續改進，替換ParallelGC，改為CMS+ParNew的組合：//當前物理內存4G，剩余內存1G

JAVA_OPTS="$JAVA_OPTS -XX:+PrintGCDetails -Xloggc:/usr/local/java/apache-tomcat-robot/apache-tomcat-web/bin/gc.log -XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=/usr/local/java/apache-tomcat-robot/apache-tomcat-web/bin/java.hprof -XX:+PrintHeapAtGC"
JAVA_OPTS="$JAVA_OPTS -XX:+ExplicitGCInvokesConcurrent"
JAVA_OPTS="$JAVA_OPTS -server -showversion -Xms2g -Xmx2g -Xmn256m
-XX:+UseConcMarkSweepGC
-XX:+UseParNewGC
-XX:MaxGCPauseMillis=200
-XX:+UseCompressedOops
-XX:+UseCMSCompactAtFullCollection
-XX:+CMSClassUnloadingEnabled
-XX:MetaspaceSize=128m
-XX:MaxMetaspaceSize=512m
-XX:MaxTenuringThreshold=7
-XX:TargetSurvivorRatio=90
-XX:+UseCMSInitiatingOccupancyOnly
-XX:+ExplicitGCInvokesConcurrent
-XX:LargePageSizeInBytes=128m
-XX:+CMSParallelRemarkEnabled
-XX:CMSInitiatingOccupancyFraction=70"

TIP：

-XX:TargetSurvivorRatio=90：允許90%的Survivor區被占用（JVM默認為50%）。提高對於Survivor區的使用率

-XX:+ExplicitGCInvokesConcurrent //system.gc使用cms算法

-XX:+DisableExplicitGC//禁止system.gc

-XX:HeapDumpPath=/home/admin/logs/java.hprof //OOM快照文件的地址

-XX:SurvivorRatio=10
Eden與Survivor的占用比例,例如10表示，一個survivor區占用 1/10 的Eden內存，即1/12的新生代內存，
新生代有2個survivor，即S0和S1。所以survivor總共是占用新生代內存的 2/12，Eden與新生代的占比則為 10/12

-XX:MaxTenuringThreshold=6

-XX:+UseCMSCompactAtFullCollection //CMS開啟碎片整理，CMS默認不會整理堆碎片，因此為了防止堆碎片引起full gc，可以開啟該選項
-XX:+UseCompressedOops //啟用指針壓縮，在64位HotSpot中使用32位指針，默認64位會比32位的內存使用多出1.5倍

-XX:+PrintHeapAtGC //每一次GC前和GC后，都打印堆信息。

-XX:+CMSClassUnloadingEnabled //對方法區gc

-XX:PretenureSizeThreshold=65535 //eden區的大對象閾值65M

產生的正常日志片斷：

。。。
{Heap before GC invocations=22 (full 0):
 par new generation   total 235968K, used 235968K [0x0000000080000000, 0x0000000090000000, 0x0000000090000000)
  eden space 209792K, 100% used [0x0000000080000000, 0x000000008cce0000, 0x000000008cce0000)
  from space 26176K, 100% used [0x000000008cce0000, 0x000000008e670000, 0x000000008e670000)
  to   space 26176K,   0% used [0x000000008e670000, 0x000000008e670000, 0x0000000090000000)
 concurrent mark-sweep generation total 1835008K, used 1123030K [0x0000000090000000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 64924K, capacity 66906K, committed 67072K, reserved 1107968K
  class space    used 7769K, capacity 8333K, committed 8448K, reserved 1048576K
2223.576: [GC (Allocation Failure) 2223.576: [ParNew: 235968K->26176K(235968K), 0.0583532 secs] 1358998K->1225544K(2070976K), 0.0585896 secs] [Times: user=0.08 sys=0.02, real=0.06 secs] 
Heap after GC invocations=23 (full 0):
 par new generation   total 235968K, used 26176K [0x0000000080000000, 0x0000000090000000, 0x0000000090000000)
  eden space 209792K,   0% used [0x0000000080000000, 0x0000000080000000, 0x000000008cce0000)
  from space 26176K, 100% used [0x000000008e670000, 0x0000000090000000, 0x0000000090000000)
  to   space 26176K,   0% used [0x000000008cce0000, 0x000000008cce0000, 0x000000008e670000)
 concurrent mark-sweep generation total 1835008K, used 1199368K [0x0000000090000000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 64924K, capacity 66906K, committed 67072K, reserved 1107968K
  class space    used 7769K, capacity 8333K, committed 8448K, reserved 1048576K
}
。。。

打開GC前后輸出堆信息：

黃色（GC前/后）：

before：老年代總大小1835008k，已使用1123030k

after：老年代總大小1835008k，已使用1199368k

橘色（新生代GC變化）：235968-26176-（1358998-1225544）=黃色差值（1199368-1123030）

當啟動服務器后（時隔約1小時），第一次產生full gc：

{Heap before GC invocations=24 (full 0):
 par new generation   total 235968K, used 235967K [0x0000000080000000, 0x0000000090000000, 0x0000000090000000)
  eden space 209792K, 100% used [0x0000000080000000, 0x000000008cce0000, 0x000000008cce0000)
  from space 26176K,  99% used [0x000000008cce0000, 0x000000008e66fff8, 0x000000008e670000)
  to   space 26176K,   0% used [0x000000008e670000, 0x000000008e670000, 0x0000000090000000)
 concurrent mark-sweep generation total 1835008K, used 1275665K [0x0000000090000000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 65433K, capacity 67440K, committed 67584K, reserved 1107968K
  class space    used 7770K, capacity 8336K, committed 8448K, reserved 1048576K
2699.930: [GC (Allocation Failure) 2699.930: [ParNew: 235967K->26176K(235968K), 0.0610195 secs] 1511633K->1386131K(2070976K), 0.0612115 secs] [Times: user=0.09 sys=0.02, real=0.06 secs] 
Heap after GC invocations=25 (full 0):
 par new generation   total 235968K, used 26176K [0x0000000080000000, 0x0000000090000000, 0x0000000090000000)
  eden space 209792K,   0% used [0x0000000080000000, 0x0000000080000000, 0x000000008cce0000)
  from space 26176K, 100% used [0x000000008e670000, 0x0000000090000000, 0x0000000090000000)
  to   space 26176K,   0% used [0x000000008cce0000, 0x000000008cce0000, 0x000000008e670000)
 concurrent mark-sweep generation total 1835008K, used 1359955K [0x0000000090000000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 65433K, capacity 67440K, committed 67584K, reserved 1107968K
  class space    used 7770K, capacity 8336K, committed 8448K, reserved 1048576K
}
2699.992: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1359955K(1835008K)] 1386239K(2070976K), 0.0043239 secs] [Times: user=0.01 sys=0.02, real=0.00 secs] 
2699.997: [CMS-concurrent-mark-start]
2700.036: [CMS-concurrent-mark: 0.039/0.039 secs] [Times: user=0.08 sys=0.00, real=0.04 secs] 
2700.036: [CMS-concurrent-preclean-start]
2700.040: [CMS-concurrent-preclean: 0.004/0.004 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2700.040: [GC (CMS Final Remark) [YG occupancy: 26284 K (235968 K)]2700.040: [Rescan (parallel) , 0.0018878 secs]2700.042: [weak refs processing, 0.0027371 secs]2700.045: [class unloading, 0.0212439 secs]2700.066: [scrub symbol table, 0.0075598 secs]2700.074: [scrub string table, 0.0012169 secs][1 CMS-remark: 1359955K(1835008K)] 1386239K(2070976K), 0.0456603 secs] [Times: user=0.06 sys=0.00, real=0.04 secs] 
2700.086: [CMS-concurrent-sweep-start]
2700.170: [CMS-concurrent-sweep: 0.082/0.083 secs] [Times: user=0.09 sys=0.00, real=0.09 secs] 
2700.170: [CMS-concurrent-reset-start]
2700.175: [CMS-concurrent-reset: 0.005/0.005 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
{Heap before GC invocations=25 (full 1):
 par new generation   total 235968K, used 235968K [0x0000000080000000, 0x0000000090000000, 0x0000000090000000)
  eden space 209792K, 100% used [0x0000000080000000, 0x000000008cce0000, 0x000000008cce0000)
  from space 26176K, 100% used [0x000000008e670000, 0x0000000090000000, 0x0000000090000000)
  to   space 26176K,   0% used [0x000000008cce0000, 0x000000008cce0000, 0x000000008e670000)
 concurrent mark-sweep generation total 1835008K, used 431812K [0x0000000090000000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 65340K, capacity 67220K, committed 67584K, reserved 1107968K
  class space    used 7748K, capacity 8294K, committed 8448K, reserved 1048576K
2938.667: [GC (Allocation Failure) 2938.667: [ParNew: 235968K->26176K(235968K), 0.0448878 secs] 667780K->541410K(2070976K), 0.0450784 secs] [Times: user=0.09 sys=0.00, real=0.05 secs] 
Heap after GC invocations=26 (full 1):
 par new generation   total 235968K, used 26176K [0x0000000080000000, 0x0000000090000000, 0x0000000090000000)
  eden space 209792K,   0% used [0x0000000080000000, 0x0000000080000000, 0x000000008cce0000)
  from space 26176K, 100% used [0x000000008cce0000, 0x000000008e670000, 0x000000008e670000)
  to   space 26176K,   0% used [0x000000008e670000, 0x000000008e670000, 0x0000000090000000)
 concurrent mark-sweep generation total 1835008K, used 515234K [0x0000000090000000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 65340K, capacity 67220K, committed 67584K, reserved 1107968K
  class space    used 7748K, capacity 8294K, committed 8448K, reserved 1048576K
}

可以看到當超過老年代閾值的時候，會觸發cms，清理掉約1g的垃圾

GC之日分析其他實例，參考 http://hot66hot.iteye.com/blog/2075819

新生代(ParNew YGC)promotion failed日志

2014-02-27T21:19:42.460+0800: 210095.040: [GC 210095.040: [ParNew (promotion failed): 1887487K->1887488K(1887488K), 0.4818790 secs]210095.522: [CMS: 13706434K->7942818K(23068672K), 9.7152990 secs] 15358303K->7942818K(24956160K), [CMS Perm : 27424K->27373K(98304K)], 10.1974110 secs] [Times: user=12.06 sys=0.01, real=10.20 secs]

promotion failed一般發生在新生代晉升老年代時,引發Full Gc. //CMS: 13706434K->7942818K(23068672K)指的是老年代的前后變化

解決思路:YGC晉升對象過大,過老.(mid/long Time Object),

調整-XX:PretenureSizeThreshold=65535,//虛擬機提供了一個-XX:PretenureSizeThreshold參數，令大於這個設置值的對象直接在老年代分配。這樣做的目的是避免在Eden區及兩個Survivor區之間發生大量的內存復制，注意:PretenureSizeThreshold參數只對Serial和ParNew兩款收集器有效

　-XX:MaxTenuringThreshold=6，縮短年齡，使新生代空間得以保障

老年代(CMS old gc)分析：

2014-02-28T23:58:42.314+0800: 25789.661: [GC [1 CMS-initial-mark: 17303356K(23068672K)] 18642315K(24903680K), 1.0400410 secs] [Times: user=1.04 sys=0.00, real=1.04 secs]
2014-02-28T23:58:43.354+0800: 25790.701: [CMS-concurrent-mark-start]
2014-02-28T23:58:43.717+0800: 25791.064: [CMS-concurrent-mark: 0.315/0.363 secs] [Times: user=1.64 sys=0.02, real=0.37 secs]
2014-02-28T23:58:43.717+0800: 25791.064: [CMS-concurrent-preclean-start]
2014-02-28T23:58:43.907+0800: 25791.254: [CMS-concurrent-preclean: 0.181/0.190 secs] [Times: user=0.20 sys=0.01, real=0.19 secs]
2014-02-28T23:58:43.907+0800: 25791.254: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time 2014-02-28T23:58:49.082+0800: 25796.429: [CMS-concurrent-abortable-preclean: 5.165/5.174 secs] [Times: user=5.40 sys=0.04, real=5.17 secs]
2014-02-28T23:58:49.083+0800: 25796.430: [GC[YG occupancy: 1365142 K (1835008 K)]2014-02-28T23:58:49.083+0800: 25796.430: [Rescan (parallel) , 0.9690640 secs]2014-02-28T23:58:50.052+0800: 25797.399: [weak refs processing, 0.0006190 secs]2014-02-28T23:58:50.053+0800: 25797.400: [scrub string table, 0.0006290 secs] [1 CMS-remark: 17355150K(23068672K)] 18720292K(24903680K), 0.9706650 secs] [Times: user=16.49 sys=0.06, real=0.97 secs]
2014-02-28T23:58:50.054+0800: 25797.401: [CMS-concurrent-sweep-start]
2014-02-28T23:58:51.940+0800: 25799.287: [CMS-concurrent-sweep: 1.875/1.887 secs] [Times: user=2.03 sys=0.03, real=1.89 secs]
2014-02-28T23:58:51.941+0800: 25799.288: [CMS-concurrent-reset-start]
2014-02-28T23:58:52.067+0800: 25799.414: [CMS-concurrent-reset: 0.127/0.127 secs] [Times: user=0.13 sys=0.00, real=0.13 secs]
2014-03-01T00:00:36.293+0800: 25903.640: [GC2014-03-01T00:00:36.293+0800: 25903.640: [ParNew: 1805234K->226801K(1835008K), 0.1020510 secs] 10902912K->9434796K(24903680K), 0.1023150 secs] [Times: user=1.35 sys=0.02, real=0.10 secs]
2014-03-01T00:07:13.559+0800: 26300.906: [GC2014-03-01T00:07:13.559+0800: 26300.906: [ParNew: 1799665K->248991K(1835008K), 0.0876870 secs] 14086673K->12612462K(24903680K), 0.0879620 secs] [Times: user=1.24 sys=0.01, real=0.09 secs]

CMS的gc日志分為一下幾個步驟，重點關注initial-mark和remark這兩個階段，因為這兩個階段會stop進程。

初始標記（init mark）：收集根引用，這是一個stop-the-world階段。

並發標記（concurrent mark）：這個階段可以和用戶應用並發進行。遍歷老年代的對象圖，標記出活着的對象。

並發預清理（concurrent preclean）：這同樣是一個並發的階段。主要的用途也是用來標記，用來標記那些在前面標記之后，發生變化的引用。主要是為了縮短remark階段的stop-the-world的時間。

重新標記（remark）：這是一個stop-the-world的操作。暫停各個應用，統計那些在發生變化的標記。

並發清理（concurrent sweep）：並發掃描整個老年代，回收一些在對象圖中不可達對象所占用的空間。

並發重置（concurrent reset）：重置某些數據結果，以備下一個回收周期

老年代(CMS old GC ) concurrent mode failure日志

2014-03-03T09:38:26.457+0800: 233373.804: [GC [1 CMS-initial-mark: 17319615K(23068672K)] 17351070K(24903680K), 0.0419440 secs]
[Times: user=0.04 sys=0.00, real=0.04 secs]
2014-03-03T09:38:26.499+0800: 233373.846: [CMS-concurrent-mark-start]
2014-03-03T09:38:28.175+0800: 233375.522: [GC2014-03-03T09:38:28.175+0800: 233375.522: [CMS2014-03-03T09:38:28.887+0800: 233376.234:
[CMS-concurrent-mark: 1.989/2.388 secs] [Times: user=14.37 sys=0.24, real=2.39 secs]
(concurrent mode failure): 17473174K->8394653K(23068672K), 19.3309170 secs] 18319691K->8394653K(24903680K),
[CMS Perm : 23157K->23154K(98304K)], 19.3311700 secs] [Times: user=22.18 sys=0.00, real=19.33 secs]

concurrent mode failure一般發生在CMS GC 運行過程中（有新的大對象或者滿足old閾值的對象晉升老年代）,老年代空間不足，引發MSC(Full GC)

上面的這條發日志說明CMS運行到CMS-concurrent-mark過程中就出現空間不足,產生並發失敗(17319615K(23068672K)占77%),

解決思路：降低YGC頻率，降低CMS GC觸發時機,適當降低CMSInitiatingOccupancyFraction（即分配給老年代更大的預留空間）.

由新生代觸發的老年代(CMS old GC ) concurrent mode failure日志

197.976: [GC 197.976: [ParNew: 260872K->260872K(261952K), 0.0000688 secs]

197.976: [CMS197.981: [CMS-concurrent-sweep: 0.516/0.531 secs] (concurrent mode failure): 402978K->248977K(786432K), 2.3728734 secs] 663850K->248977K(1048384K), 2.3733725 secs]

這個例子表明：GC算法進入了concurrent mode failure狀態，由於老年代的內存碎片太多導致的老年代空間不足，需要調用一個serail Old GC(阻塞了其他線程)來清理系統的Heap

concurrent mode failure和promotion failed差別：

promotion failed是在進行Minor GC時，survivor space放不下、對象只能放入舊生代，而此時舊生代也放不下造成的；

concurrent mode failure是在執行CMS GC的過程中同時有對象要放入舊生代，而此時舊生代空間不足造成的。

當出現concurrent mode failure和promotion failed，會接着引發full gc的。

所以在別一次性占用太多的內存，如果是讀文件，可以采用拆分的方法（批次讀入緩存區）。或者把GC內存調大點

免責聲明！

本站轉載的文章為個人學習借鑒使用，本站對版權不負任何法律責任。如果侵犯了您的隱私權益，請聯系本站郵箱yoyou2525@163.com刪除。

猜您在找 JVM調優之---一次GC調優實戰 JVM調優——之CMS GC日志分析記一次JVM調優之旅（斗爭full gc）記一次JVM Full GC (Metadata GC Threshold)調優經歷一次jvm調優過程一次JVM調優的筆記 JVM調優日志解析分析 JVM調優--GC基礎 JVM調優-GC參數 JVM系列【6】GC與調優1