前言
前幾天收到線上某機器cms-initial-remark次數(shù)超過13次報警搬卒，這臺機器長時間沒有過新功能上線棕兼，為啥會出現(xiàn)頻繁cms gc告警呢梅掠，遂一起排查。
輸出啟動參數(shù)
登陸了問題發(fā)生的機器玉掸∪恤铮考慮到是gc問題，首先想到的是輸出虛擬機的參數(shù)司浪，使用ps或者jps找到j(luò)ava進程泊业，然后使用jinfo輸出啟動參數(shù)，啟動參數(shù)如下：
-Djava.util.logging.config.file=/home/admin/xxx/.default/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Dcatalina.vendor=alibaba -Djava.security.egd=file:/dev/./urandom -Dlog4j.defaultInitOverride=true -Dorg.apache.tomcat.util.http.ServerCookie.ALLOW_EQUALS_IN_VALUE=true -Dorg.apache.tomcat.util.http.ServerCookie.ALLOW_HTTP_SEPARATORS_IN_V0=true -Xms4g -Xmx4g -Xmn2g -XX:PermSize=96m -XX:MaxPermSize=256m -XX:SurvivorRatio=10 -XX:+UseConcMarkSweepGC -XX:+UseCMSCompactAtFullCollection -XX:+CMSClassUnloadingEnabled -XX:CMSMaxAbortablePrecleanTime=5000 -XX:CMSInitiatingOccupancyFraction=80 -XX:-HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/admin/logs -Xloggc:/home/admin/logs/gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Djava.awt.headless=true -Dsun.net.client.defaultConnectTimeout=10000 -Dsun.net.client.defaultReadTimeout=30000 -XX:MaxDirectMemorySize=1g -XX:+UseCMSInitiatingOccupancyOnly -XX:+ExplicitGCInvokesConcurrent -Dsun.rmi.dgc.server.gcInterval=2592000000 -Dsun.rmi.dgc.client.gcInterval=2592000000 -XX:ParallelGCThreads=4 -DJM.LOG.PATH=/home/admin/logs -DJM.SNAPSHOT.PATH=/home/admin/snapshots -Dfile.encoding=GB18030 -Dhsf.publish.delayed=false -Dhsf.server.ip=11.183.92.169 -Dproject.name=xxx -Djava.endorsed.dirs=/opt/taobao/tomcat/endorsed -Dcatalina.logs=/home/admin/xxx/logs/catalina -Dcatalina.base=/home/admin/xxx/.default -Dcatalina.home=/opt/taobao/tomcat -Djava.io.tmpdir=/home/admin/xxx/.default/temp
同時確定了機器jdk的版本仍然是1.6
挑選出與gc有關(guān)的啟動參數(shù)分析一下：
- -Xms 4g -Xmx4g啊易，最小最大堆內(nèi)存為4g吁伺，鎖定堆大小，不動態(tài)調(diào)整租谈。
- -Xmn2g篮奄，年輕代占2g。
- -XX:SurvivorRatio=10割去，表示兩個survivor : eden = 2 : 10,單個survivor占年輕代的1/12
- -XX:PermSize=96m -XX:MaxPermSize=256m窟却，永久代初始值為96m，最大值256m
- -XX:+UseConcMarkSweepGC 使用cms gc收集算法
- -XX:+UseCMSCompactAtFullCollection 在發(fā)生‘full gc’時對老年大內(nèi)存空間進行整理壓縮
- -XX:+CMSClassUnloadingEnabled 在cms gc時對永久代進行回收（卸載類或者卸載類加載器）
- -XX:CMSMaxAbortablePrecleanTime=5000 AbortablePreclean是cms過程中的一個階段呻逆，用于平衡ygc 和remark階段（避免連續(xù)兩次stw）夸赫，設(shè)定該階段最長時間為5s
- -XX:CMSInitiatingOccupancyFraction=80 -XX:+UseCMSInitiatingOccupancyOnly 合起來用表示老年代used占capacity 80%的時候開啟cms collection cycle.
- -XX:MaxDirectMemorySize=1g 最大直接內(nèi)存大小為1g
- -XX:+ExplicitGCInvokesConcurrent，將顯示調(diào)用System.gc()轉(zhuǎn)化成一次cms gc（本應(yīng)發(fā)生full gc）咖城。
- XX:ParallelGCThreads=4 并行收集的gc線程數(shù)為4,所以cms線程數(shù)ConcGCT
hreads = (3 + ParallelGCThreads) / 1 = 1
GC日志
A機器
要定位gc問題茬腿，最核心的就是看gc日志定位問題。用工具dump了gc log分析宜雀，結(jié)果如下：
不看不知道切平，一看嚇一跳。
- cms gc的cycle數(shù)量達到了驚人的6543次
- 存在4次Mix GC州袒，并且由‘promotion failed’原因?qū)е?/li>
- 存在一次perm區(qū)溢出的cms gc
存在的問題已經(jīng)比較清楚了
- 頻繁發(fā)生cms gc
- 存在一定程度的promotion failed（這種gc的傷害比較大揭绑，應(yīng)該盡量避免）
- 存在意思perm溢出
那為啥會頻繁的開始cms collection cycle呢，先挑選幾條cms的日志
2017-10-12T22:35:56.602+0800: 777539.404: [GC [1 CMS-initial-mark: 950754K(2097152K)] 1939671K(4019584K), 0.7363400 secs] [Times: user=0.73 sys=0.01, real=0.74 secs]
2017-10-12T22:35:57.339+0800: 777540.141: [CMS-concurrent-mark-start]
2017-10-12T22:35:57.988+0800: 777540.791: [GC 777540.791: [ParNew: 1815272K->70343K(1922432K), 0.0484420 secs] 2766027K->1021205K(4019584K), 0.0486410 secs] [Times: user=0.15 sys=0.00, real=0.05 secs]
2017-10-12T22:35:59.137+0800: 777541.940: [CMS-concurrent-mark: 1.748/1.799 secs] [Times: user=4.08 sys=0.08, real=1.80 secs]
2017-10-12T22:35:59.137+0800: 777541.940: [CMS-concurrent-preclean-start]
2017-10-12T22:35:59.149+0800: 777541.952: [CMS-concurrent-preclean: 0.011/0.012 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
2017-10-12T22:35:59.149+0800: 777541.952: [CMS-concurrent-abortable-preclean-start]
由于jvm并沒有把發(fā)生cms gc的原因給輸出郎哭，所以只能結(jié)合條件倒推下他匪。我在jvm群里咨詢了幾位大大想問下cms gc前后old區(qū)的大小變化，大大們的回答如下：
大大1：
看gc log夸研， initial mark 的記錄是cms 觸發(fā)時的used和capacity邦蜜，是之前的
final remark的記錄是之后的，我一般是這么理解的
大大2：
整個cms gc是從initial mark開始到remark結(jié)束亥至，initial mark告訴你觸發(fā)cms的old區(qū)大小悼沈，remark會告訴你cms后old區(qū)的使用情況
看了下日志：
**[GC [1 CMS-initial-mark: 950754K(2097152K)] ** 表示說開始gc之前old的大小為950754K，大約占整個old區(qū)的45%左右姐扮，但是結(jié)合 -XX:CMSInitiatingOccupancyFraction=80 -XX:+UseCMSInitiatingOccupancyOnly 來看絮供，觸發(fā)這臺cms gc的原因不是old區(qū)內(nèi)存占用超過80%。
那么問題來了茶敏，觸發(fā)這次cms gc的原因到底是什么呢壤靶？咨詢了jvm群的大大，google了下外網(wǎng)和內(nèi)網(wǎng)文章惊搏。1.6版本的cms gc主要原因如下：
- 老年代空間使用率超過設(shè)定值
- 永久代空間使用率超過設(shè)定值
- System.gc()調(diào)用并且設(shè)置了-XX:+ExplicitGCInvokesConcurrent 將一次full gc轉(zhuǎn)化為cms gc
目前已經(jīng)排除第一條贮乳，那么第二條是否滿足呢。需要注意的是perm區(qū)的閾值由-XX:CMSInitiatingPermOccupancyFraction指定恬惯，該值如果不設(shè)置的話是92向拆，使用jstat -gcutil觀察下使用情況如下：
S0 S1 E O P YGC YGCT FGC FGCT GCT
0.00 61.24 14.84 45.36 92.67 17167 771.384 14136 7486.615 8257.999
0.00 61.24 14.99 45.36 92.67 17167 771.384 14136 7486.615 8257.999
0.00 61.24 15.09 45.36 92.67 17167 771.384 14136 7486.615 8257.999
0.00 61.24 15.19 45.36 92.67 17167 771.384 14136 7486.615 8257.999
0.00 61.24 15.27 45.36 92.67 17167 771.384 14137 7486.821 8258.205
可以看到Perm區(qū)的占比為92.67超過默認值92，所以cms gc會一直被觸發(fā)酪耳。至于FGC次數(shù)為何那么大浓恳，可以參考R大的[文章]（http://rednaxelafx.iteye.com/blog/1108768），cms 的initial-mark和remark都會計算到FGC次數(shù)里碗暗，所以jstat FGC次數(shù)可以理解為stw的次數(shù)吧奖蔓。
從上述日志基本可以確定這臺機器的頻繁gc原因是由于perm區(qū)占用率大導(dǎo)致的。
B機器
在分析了這臺機器是由于perm占用導(dǎo)致的cms gc后讹堤，我又查看了另外一臺機器吆鹤，發(fā)現(xiàn)了另外一個問題。
dump了另外一臺機器的gc log分析
檢測到的GC問題
篩選出了【9】條疑似問題的GC洲守，跳過了【4307】條可能正常的GC
存在【0】次Full GC及【3】次Mix GC(Mix GC相當于Full GC疑务，一次stop，多代進行回收)
【66.0%】【2/3】的Mix GC是因為晉升失敗導(dǎo)致的
存在【2】次晉升失敗的情況
過濾出來的GC中CMS GC比例占了【44%】【4/9】
調(diào)優(yōu)建議
預(yù)測到您可能沒有設(shè)置-XX:+UseCMSInitiatingOccupancyOnly梗醇，如果設(shè)置了請檢查-XX:CMSInitiatingOccupancyFraction的值是否小于83知允，如果這個條件滿足，說明老生代GC效果不給力叙谨，或者新生代GC過于頻繁晉升對象多温鸽，可嘗試調(diào)大CMSInitiatingOccupancyFraction或者調(diào)大老生代的大小
結(jié)合日志和之前的分析可疑看出來這臺機器的cms gc主要是由于老年代占用過大以及比較碎片化導(dǎo)致的。
問題解決
原因清楚了之后調(diào)整就比較簡單了，最終是將Xmx和Xms調(diào)整到了5g涤垫，將permsize和MaxPermSize調(diào)整到了384M姑尺。觀察了幾天沒有再出現(xiàn)頻繁cms gc的問題。
題外話
system gc
該機器的頻繁cms gc原因找到了蝠猬，再多分析一下cms gc的另外一個原因（System.gc）切蟋。
system gc主要有幾個原因：
- rmi定時調(diào)用
- 代碼調(diào)用 可以通過btrace或者arthas定位調(diào)用代碼
- 堆外內(nèi)存清理
- Dsun.rmi.dgc.server.gcInterval=2592000000 -Dsun.rmi.dgc.client.gcInterval=2592000000
cms fail
concurrent mode failure
gc log會出現(xiàn)一些問題日志，表明cms遭遇了問題榆芦，首先就是‘concurrent mode failure’.
日志如下：
267.006: [GC 267.006: [ParNew: 629120K->629120K(629120K), 0.0000200 secs]
267.006: [CMS267.350: [CMS-concurrent-mark: 2.683/2.804 secs]
[Times: user=4.81 sys=0.02, real=2.80 secs]
(concurrent mode failure):
1378132K->1366755K(1398144K), 5.6213320 secs]
2007252K->1366755K(2027264K),
[CMS Perm : 57231K->57222K(95548K)], 5.6215150 secs]
[Times: user=5.63 sys=0.00, real=5.62 secs]
當minor gc發(fā)生了柄粹，但是old區(qū)中沒有足夠的空間容納需要晉升的對象時，cms會觸發(fā)一次full gc匆绣。此時STW驻右，所有應(yīng)用線程都會停止，old區(qū)中dead對象會被清理崎淳，上述日志中表明old區(qū)清理到了136MB堪夭，但是full gc STW了5.62s。這個操作是單線程進行的凯力，所以花費了很長時間茵瘾。
promotion failed
第二個問題就是當old區(qū)有足夠的空間給待晉升的對象時，但是由于空閑內(nèi)存過于碎片化導(dǎo)致的咐鹤。
6043.903: [GC 6043.903:
[ParNew (promotion failed): 614254K->629120K(629120K), 0.1619839 secs]
6044.217: [CMS: 1342523K->1336533K(2027264K), 30.7884210 secs]
2004251K->1336533K(1398144K),
[CMS Perm : 57231K->57231K(95548K)], 28.1361340 secs]
[Times: user=28.13 sys=0.38, real=28.13 secs]
日志表明拗秘，cms開始了一次ygc，而且認為old區(qū)中有足夠的空間來容納待晉升的對象（否則祈惶，將會導(dǎo)致concurrent mode failure問題）雕旨，然后由于old區(qū)內(nèi)存過于碎片化，導(dǎo)致cms無法晉升這些對象捧请。
所以凡涩，在minor gc的過程中，cms嘗試去清理和壓縮整理old區(qū)疹蛉。好消息是heap最終會被重新壓縮整理活箕，碎片化問題得以解決。但是會帶來一個28秒的停頓時間可款。這個時間比發(fā)生‘concurrent mode failure’時消耗的時間要長育韩，因為此時整個heap進行了壓縮整理，而concurrent mode failure只free掉old區(qū)的內(nèi)存闺鲸。
