開始我們一直覺得這是網(wǎng)絡(luò)的問題，因?yàn)镹1不可能在3分鐘內(nèi)沒有給N2響應(yīng)，并且當(dāng)Locator向它詢問are-you-dead的時候它還是沒有相應(yīng)，而在當(dāng)前這個case下，它竟然有6分鐘沒有相應(yīng)，那么長的時間里這個節(jié)點(diǎn)會處理什么事情呢？因而我們用了各種工具查網(wǎng)絡(luò)在出問題的那個點(diǎn)上的情況，有沒有中斷、包丟失之類的，然而一無所獲，直到我們從GC的日志中找到了這句話：
要不是親眼所見，我真不敢相信GC會用掉6分多鐘的時間！！自己之前也有看過GC相關(guān)的書籍，但是一直覺得GC很快(估計(jì)是看的不夠多)，因而并沒有引起很大的重視，然后我去翻了一下以前GC的日志，發(fā)現(xiàn)我們它不是一個可以隨便忽略的操作，即使是ParNew GC都有可能花費(fèi)7s的時間！！而且平時也一般都在二三十毫秒的數(shù)量級（這是我們的測試環(huán)境，生產(chǎn)環(huán)境的性能要好很多，基本在幾個毫秒的級別）。
2015-07-23T05:47:05.774-0400: [GC [ParNew: 943744K->75951K(943744K), 7.4119250 secs] 8202594K->7383241K(10380928K), 7.4120460 secs] [Times: user=0.31 sys=0.06, real=7.41 secs]
2015-07-23T05:51:54.529-0400: [GC [ParNew: 914863K->80478K(943744K), 0.0272180 secs] 8222153K->7387768K(10380928K), 0.0273280 secs] [Times: user=0.13 sys=0.00, real=0.02 secs]
2015-07-23T05:59:54.278-0400: [GC [ParNew: 919390K->53806K(943744K), 0.0572200 secs] 8226680K->7361097K(10380928K), 0.0573110 secs] [Times: user=0.19 sys=0.00, real=0.06 secs]
2015-07-23T06:07:41.663-0400: [GC [ParNew: 892718K->42574K(943744K), 1.8347990 secs] 8200009K->7387109K(10380928K), 1.8348970 secs] [Times: user=0.30 sys=0.06, real=1.84 secs]
而CMS的CMS-concurrent-sweep GC經(jīng)常要花費(fèi)10s+的時間，雖然這不是一個STW（Stop The World）操作，但是這個時間也是已經(jīng)很長了，會影響整體性能（它需要耗費(fèi)CPU，我們當(dāng)前設(shè)置4個CPU做GC）。
然而在我們的系統(tǒng)中GC花費(fèi)那么長的時間，當(dāng)然是和我們的內(nèi)存大小設(shè)置有關(guān)系，因?yàn)槲覀兊臄?shù)據(jù)節(jié)點(diǎn)每個內(nèi)存大小10G，其中Young Gen：1G，Perm Gen：200M，Old Gen：～9G，因而做一次Full GC當(dāng)然是比較費(fèi)時間的。所以一種最簡單的做法當(dāng)然是減少內(nèi)存，然而減少一個數(shù)據(jù)節(jié)點(diǎn)的內(nèi)存意味著我們需要增加節(jié)點(diǎn)的個數(shù)，不然無法保證GemFire集群能存下所有的數(shù)據(jù)，而增加節(jié)點(diǎn)個數(shù)又會帶來新的問題，如增加運(yùn)帷難度，節(jié)點(diǎn)出錯的概率提高，提高集群的通信成本，增加MetaData的存儲空間等，因而這個目前不是好的方向。所以我們只能尋求2和3的方案。
當(dāng)前GemFire節(jié)點(diǎn)退出集群問題的直接原因是因?yàn)镻arNew GC promotion失敗，從而引起CMS GC，然而CMS GC又產(chǎn)生concurrent mode failure，進(jìn)而引起STW（Stop The World）的Full GC引起的，因而比較直接的方案就是調(diào)節(jié)JVM的參數(shù)，以減少GC停頓時間，并且盡量避免Full GC，即方案2。對JVM參數(shù)調(diào)節(jié)首先可以從選擇不同的GC收集器開始，如對Young Gen的Serial、ParNew、Parallel Scavenge，對Old Gen的CMS、Serial Old（MSC）、Parallel Old，或者是直接用G1，我們目前使用ParNew+CMS，已經(jīng)使用多年，而且老板屬于保守型，這條路也基本走不通，因而這里只介紹ParNew+CMS的GC。
對ParNew收集器，它是Serial收集器的多線程版本，使用復(fù)制算法，由于每次GC的存活對象很少，因而它使用兩個Survivor和一個Eden實(shí)現(xiàn)，默認(rèn)情況下Survivor和Eden的比例是1：8，因而這里可以調(diào)節(jié)的參數(shù)有Young Gen的總大小（-XX:NewSize=1024M -XX:MaxNewSize=1024M），Survivor和Eden的比例（-XX:SurvivorRatio=8），收集線程數(shù)（-XX:ParallelGCThreads，默認(rèn)與CPU數(shù)量相同），對對象大小超過一定數(shù)值的直接晉升到老年代（-XX:PretenureSizeThreshold，無默認(rèn)值），設(shè)置晉升到老年代的年齡（-XX:MaxTenuringThreshold，默認(rèn)15），開啟Promotion失敗的擔(dān)保（-XX:+HandlePromotionFailure，1.6默認(rèn)開啟）。在我們的設(shè)置中，Young Gen的總大小和最大大小設(shè)置為一樣（1G）以減少動態(tài)分配的開銷，然而在觀察中發(fā)現(xiàn)102.4M的Survivor大小有些時候并不足以存放所有的存活對象，因而可以適當(dāng)增加Young Gen的大小：
2015-07-23T05:25:57.260-0400: [GC [ParNew: 932867K->104832K(943744K), 0.3366410 secs] 7881112K->7169555K(10380928K), 0.3367350 secs] [Times: user=0.59 sys=0.01, real=0.34 secs]
如該GC日志顯示有Young Gen內(nèi)存從932867K降到104832K（102.375M），減少828035K，然而實(shí)際內(nèi)存從7881112K下降到7169555K，只減少了711557K，即有116478K的對象直接晉升到了Old Gen（這些對象有部分可能是已經(jīng)到了晉升的年齡，然而由于Minor GC后Survivor幾乎滿了，因而基本可以確定有部分對象并沒有到達(dá)晉升年齡而直接晉升了）。
在觀察ParNew GC的日志后，我發(fā)現(xiàn)大部分情況user和real的時間保持在1:1到5:1之間，然而其實(shí)我們有8個CPU，即8個CPU并沒有很好的發(fā)生作用，反而因?yàn)榫€程交互開銷而影響了它的性能，因而可以設(shè)置4個線程來回收；另外，通過日志我還發(fā)現(xiàn)有些時候real的時間要遠(yuǎn)遠(yuǎn)超過user的時間：
(943744K), 7.4119250 secs] 8202594K->7383241K(10380928K), 7.4120460 secs] [Times: user=0.31 sys=0.06, real=
2015-07-23T06:21:44.474-0400: [GC [ParNew: 897098K->87972K(943744K), 0.0572610 secs] 8806476K->7997350K(10380928K), 0.0573410 secs] [Times: user=0.33 sys=0.00, real=0.05 secs]
2015-07-23T06:21:45.974-0400: [GC [ParNew: 926884K->104832K(943744K), 2.4767030 secs] 8836262K->8033953K(10380928K), 2.4767970 secs] [Times: user=0.66 sys=0.06, real=2.47 secs]
2015-07-23T06:21:59.836-0400: [GC [ParNew: 943744K->104832K(943744K), 8.0761790 secs] 8923644K->8137862K(10380928K), 8.0762750 secs] [Times: user=0.73 sys=0.10, real=8.07 secs]
2015-07-23T06:22:24.289-0400: [GC [ParNew: 943744K->104832K(943744K), 3.4770350 secs] 9044635K->8223741K(10380928K), 3.4771560 secs] [Times: user=0.26 sys=0.05, real=3.47 secs]
2015-07-23T06:22:38.464-0400: [GC [ParNew: 943744K->104832K(943744K), 0.8620630 secs] 9062653K->8225897K(10380928K), 0.8621870 secs] [Times: user=0.21 sys=0.01, real=0.86 secs]
2015-07-23T06:22:40.993-0400: [GC [ParNew: 943744K->60810K(943744K), 0.0665070 secs] 9064809K->8181875K(10380928K), 0.0665910 secs] [Times: user=0.25 sys=0.00, real=0.06 secs]
這里大部分Survivor不足以存放所有的存活對象，然而并不是所有的，如第一條就不是，對這個我一直很納悶，在網(wǎng)上也沒有找到非常可能的答案，但是大概
這個答案看起來比較靠譜，簡單來說，就是當(dāng)時有很多page faults，這個也符合我們當(dāng)時的情況，因?yàn)檫@臺機(jī)器原本內(nèi)存不是那么足，因而偶爾會出現(xiàn)內(nèi)存swap，而且在這種情況下，所有的sys時間相對都比較長，也是一個佐證；另外也有人解釋說ParNew在
Stop-The-World之前要確保所有JNI線程都暫停下來，因而需要等待到達(dá)safepoint，這個貌似不太像我們遇到的情況，因?yàn)槲覀儧]有使用外部的JNI，如果內(nèi)部自己的JNI應(yīng)該不至于有那么大的影響(但是這個點(diǎn)正好說明我們使用JNI的時候要非常小心，如果有函數(shù)運(yùn)行時間太長會影響JVM的穩(wěn)定性，甚至讓JVM沒有響應(yīng)，因?yàn)樗贕C的時候要等這個長時間的JNI方法結(jié)束，或到達(dá)safepoint。
更正：這里對safepoint有這樣的解釋：
A point during program execution at which all GC roots are known and all heap object contents are consistent. From a global point of view, all threads must block at a safepoint before the GC can run. (As a special case, threads running JNI code can continue to run, because they use only handles. During a safepoint they must block instead of loading the contents of the handle.) From a local point of view, a safepoint is a distinguished point in a block of code where the executing thread may block for the GC. Most call sites qualify as safepoints. There are strong invariants which hold true at every safepoint, which may be disregarded at non-safepoints. Both compiled Java code and C/C++ code be optimized between safepoints, but less so across safepoints. The JIT compiler emits a GC map at each safepoint. C/C++ code in the VM uses stylized macro-based conventions (e.g., TRAPS) to mark potential safepoints.，所以看起來這個論斷是有問題的)。ParNew暫停的時間都比較短，而且在大部分情況下，或者在其他內(nèi)存夠用的集群中我們沒有遇到那么久的GC時間，因而基本不需要過多調(diào)節(jié)，所以其他都保持了它的默認(rèn)值。
更正：前幾天我們再次發(fā)現(xiàn)ParNew GC用去186.63s：
2015-08－07T14:57:22.317+0100: [GC[ParNew: 845794K->88289K(943744K), 186.6537260 secs] 6808480K->6087745K(10380928K), 186.6540490 secs][Times: user=1703.17 sys=194.13, real=186.63 secs]
通過一些系統(tǒng)工具，我們發(fā)現(xiàn)在問題發(fā)生的時候，當(dāng)時那臺機(jī)器有26%左右的Swap內(nèi)存，并且有很高的page fault，因而我們基本能肯定這是內(nèi)存數(shù)據(jù)被換出到Swap然后在GC的時候產(chǎn)生page fault引起的。并且在
這里還提及到了swap中每4KB數(shù)據(jù)會增加10ms的GC時間：
A very high sys time suggests the OS is struggling with the application. I would make sure there is no chance the application has been partially swapped to disk as it must be completely in main memory for the GC to run is a reasonable time. Every 4 KB swapped to disk and add 10 ms to the GC time.
因而我們基本能肯定發(fā)生那么長的時間就是因?yàn)閮?nèi)存swap引起的，據(jù)說在Cassandra調(diào)優(yōu)時有些直接把虛擬內(nèi)存禁掉，以防出現(xiàn)類似的問題。
CMS收集器調(diào)節(jié)
重點(diǎn)當(dāng)然是要調(diào)節(jié)CMS收集器，即要避免它在收集時停頓過長，更要避免產(chǎn)生promotion failed和concurrent mode failure的情況，因?yàn)檫@兩種情況發(fā)生后都會引起CMS做Stop-The-World GC，其中第二中情況在做GC時還會做整理（Compact），因而會有更久的停頓，而我們這次是兩種情況同時遇到了。要避免這兩種情況的發(fā)生需要先理解為什么會發(fā)生這兩種情況。
首先，我們來看看promotion failed發(fā)生的情況：
我們知道當(dāng)對象到一定的年齡，或者在某次回收過程中一個Survivor無法裝下所有存活的對象，或者一個對象的大小超過-XX:PretenureSizeThreshold設(shè)置的值，就會被promote到Old Gen中，而在promote過程中如果Old Gen無法裝下所有的內(nèi)存時就會產(chǎn)生promotion failed（這里說CMS是根據(jù)預(yù)估的值：Modern CMS collector estimates size of objects to be promoted using statistics from previous collections. If old space does not have enough free bytes to hold estimated promotion amount, concurrent mode failure will be raise.但是我的理解是這是ParNew做的GC，為什么由CMS來預(yù)估？所以應(yīng)該是ParNew把需要promote的對象傳遞給CMS，然后CMS做預(yù)估決定是否有足夠多的內(nèi)存存放這些新promote的對象），此時就會先做一遍CMS GC，然后將新promote的對象存放到Old Gen中，由于這屬于ParNew GC的范圍，因而這次的CMS GC依然處于STW狀態(tài)，因而這會花比較久的時間。如這次的ParNew GC，花費(fèi)5.75s：
2015-07-20T08:23:00.028-0400: [GC [ParNew (promotion failed): 844305K->841244K(943744K), 0.2358120 secs][CMS: 6282619K->1891959K(9437184K), 5.5098940 secs] 7126660K->1891959K(10380928K), [CMS Perm : 67716K->66078K(112860K)], 5.7458460 secs] [Times: user=4.77 sys=0.02, real=5.75 secs]
2015-07-20T08:23:06.532-0400: [GC [ParNew: 838912K->7606K(943744K), 0.0063650 secs] 2730871K->1899566K(10380928K), 0.0065380 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
我們當(dāng)前的設(shè)置：-XX:CMSInitiatingOccupancyFraction=79 -XX:+UseCMSInitiatingOccupancyOnly，也就是只有到Old Gen占用79%后才會觸發(fā)CMS GC，這里只占66.57%，因而還沒能觸發(fā)CMS GC，然而此時ParNew GC只回收了3061K的對象，還有841244K的對象存活，而一個Survivor只有104857.6K大小，此時需要promote大概736386.4K大小的數(shù)據(jù)到Old Gen中，此時Old Gen還有（9437184K-6282619K=3154565K）大小的內(nèi)存，雖然遠(yuǎn)遠(yuǎn)大于被promote的對象，但是我們知道CMS采用標(biāo)記-清除（Mark-Sweep）算法，而不主動整理（Compact），但是它在每次回收時會合并相鄰的內(nèi)存空間，然而跑久了難免會產(chǎn)生內(nèi)存碎片，也就是說此時內(nèi)存碎片已經(jīng)很多了，無法容納新promote的對象，要不就是新promote的對象大小太大，或者碎片太小，因而需要出發(fā)一次CMS GC來釋放一些空間（此時發(fā)生的CMS是不是已經(jīng)退化成Serial Old收集器算法了？即在收集的過程還是整理？），以保證能存放下所有新promote出的對象。這里GC日志中并沒有顯示出什么這次ParNew GC后，Young Gen還剩下多少內(nèi)存，但是根據(jù)下一次ParNew GC的初始大小是838912K，小于之前存活下來的對象（841244K），因而我們可以確定這次GC的結(jié)果是把多余的對象promtoe到Old Gen中了。
所以根據(jù)分析，我們可以從兩個方向調(diào)節(jié)參數(shù)：
1. 降低CMS GC的閾值。
2. 提前減少Old Gen中的碎片，即讓CMS GC做整理。
對降低CMS GC閾值，我們可以調(diào)節(jié)參數(shù)：-XX:CMSInitiatingOccupancyFraction，默認(rèn)大小68，我們可以將它設(shè)置成60。對提前減少Old Gen的碎片，這個比較麻煩，我們不想每次CMS GC都做整理（Compact），因而這會比較浪費(fèi)，會增加GC總體的時間以及停頓的時間，而且也比較危險(xiǎn)，因?yàn)槿f一某次整理時間太長會引起集群的不穩(wěn)定（可以設(shè)置-XX:UseCMSCompactAtFullCollection來實(shí)現(xiàn)這個功能）。還有一種辦法是設(shè)置每經(jīng)歷N次CMS后做一次整理，通過-XX:CMSFullGCsBeforeCompaction=<N>來設(shè)置，這個相對可以接受一些。當(dāng)然如果能找到一個相對空閑的時間手動觸發(fā)一次Full GC，并且確保讓它能觸發(fā)整理（這個目前還沒有找到合適的方法，JConsole提供的GC按鈕是一個可選項(xiàng)，但是不確定。我做了一下嘗試：
2015-07-31T16:04:49.183+0800: [Full GC (System) [CMS: 3861443K->1072505K(9437184K), 2.9535440 secs] 4458634K->1072505K(10380928K), [CMS Perm : 68183K->67112K(112880K)], 2.9537000 secs] [Times: user=2.94 sys=0.00, real=2.95 secs]
看起來是減少了不少內(nèi)存，按日志的格式，看起來像是Serial Old的算法？另外，使用這個功能要確保-XX:-DisableExplicitGC是關(guān)閉的，雖然這就是默認(rèn)值）。
值得注意的是，promotion failed的情況也可以產(chǎn)生很長的停頓，這里我們看到總的時間是378.38s，user的時間只有5.56s，而sys的時間高達(dá)1.80s，看起來和ParNew長時間停頓的情況類似，即產(chǎn)生了對象換出到虛擬內(nèi)存了？
2015-07-22T08:20:04.712-0400: [GC [ParNew (promotion failed): 842147K->839927K(943744K), 0.2343990 secs][CMS: 7382737K->1921345K(9437184K), 378.2061130 secs] 8224802K->1921345K(10380928K), [CMS Perm : 67406K->66061K(112260K)], 378.4406520 secs] [Times: user=5.56 sys=1.80, real=378.38 secs]
關(guān)于產(chǎn)生promotion failed，這里還有更詳細(xì)的解釋，如涉及到PLAB（Promotion Local Allocation Buffer）的介紹等，以及這里是對它的更正。值得注意的是，CMS在管理內(nèi)存中使用空閑列表的方式，然而這種方式可能會存在某些問題，如這句話所說（具體就不展開了）：
CMS memory manager is using separate free lists for different size of chunks. Using these free lists, it can effectively fill small holes in fragmented memory space with objects of exact size. This technique is known to be fairly effective (and widely used in C/C++ memory managers). But, surprisingly, it doesn't seems to work well for JVM in many real live situations.
然后，再來看看concurrent mode failure的情況：
依然是這篇文章，作者說concurrent mode failure是在Young GC發(fā)生前，它會預(yù)估Old Gen是否有足夠的空間存放從Young Gen中promote上來的對象，CMS收集器根據(jù)之前統(tǒng)計(jì)來預(yù)估這些對象的大小，如果Old Gen沒有足夠的空間存放這個預(yù)估的值，就會發(fā)生concurrent mode failure。此時不一定會產(chǎn)生Full GC，有些時候JVM只是等待當(dāng)前并行收集完成，但是用戶程序此時還是會STW直到這次收集技術(shù)。
At beginning of each young GC, collector should ensure that there is enough free memory in old space to promote aged objects from young space. Modern CMS collector estimates size of objects to be promoted using statistics from previous collections. If old space does not have enough free bytes to hold estimated promotion amount, concurrent mode failure will be raise. Concurrent mode failure doesn't necessary lead to Full GC, in certain cases JVM will just wait for concurrent collection cycle to finish, but application will remain in STW pause until young collection will be finished.
然而根據(jù)我的觀察，concurrent mode failure都是發(fā)生在CMS已經(jīng)開始，但是在中間階段，出現(xiàn)ParNew的promotion failed。
如這是發(fā)生在CMS-concurrent-abortable-preclean階段：
2015-07-19T06:17:04.919-0400: [GC [1 CMS-initial-mark: 7612366K(9437184K)] 7726317K(10380928K), 0.0208180 secs] [Times: user=0.02 sys=0.01, real=0.02 secs]
2015-07-19T06:17:05.275-0400: [CMS-concurrent-mark: 0.334/0.334 secs] [Times: user=1.62 sys=0.02, real=0.33 secs]
2015-07-19T06:17:05.294-0400: [CMS-concurrent-preclean: 0.019/0.019 secs] [Times: user=0.04 sys=0.00, real=0.02 secs]
2015-07-19T06:17:05.936-0400: [GC [ParNew (promotion failed): 943744K->943744K(943744K), 0.2429280 secs][CMS2015-07-19T06:17:06.239-0400: [CMS-concurrent-abortable-preclean: 0.493/0.945 secs] [Times: user=1.54 sys=0.06, real=0.95 secs]
(concurrent mode failure): 7747387K->1603792K(9437184K), 5.4145810 secs] 8556110K->1603792K(10380928K), [CMS Perm : 65203K->63169K(108704K)], 5.6576200 secs] [Times: user=4.66 sys=0.01, real=5.66 secs]
這是ParNew發(fā)生時，CMS-concurrent-preclean結(jié)束不久，此時ParNew花費(fèi)0.2429280s完成，想premote一些對象而失敗，因而CMS在06:17:06.239完成步驟：CMS-concurrent-abortable-preclean，然而這個步驟結(jié)束后，依然無法容納promote上來的對象，所以需要做一個Full GC，完成以后Old Gen內(nèi)存從7747387K下降到1603792K，總內(nèi)存從8556110K下降到1603792K，即將所有Young Gen中存活的對象放到了Old Gen中了。
這是發(fā)生在CMS-concurrent-sweep階段：
2015-07-23T06:25:36.290-0400: [CMS-concurrent-preclean: 19.091/174.559 secs] [Times: user=53.37 sys=3.66, real=174.53 secs]
2015-07-23T06:25:36.525-0400: [CMS-concurrent-abortable-preclean: 0.133/0.235 secs] [Times: user=0.37 sys=0.00, real=0.24 secs]
2015-07-23T06:25:36.526-0400: [GC[YG occupancy: 719822 K (943744 K)][Rescan (parallel) , 0.0487460 secs][weak refs processing, 0.0002160 secs] [1 CMS-remark: 8636790K(9437184K)] 9356613K(10380928K), 0.0490460 secs] [Times: user=0.32 sys=0.00, real=0.05 secs]
2015-07-23T06:25:38.022-0400: [GC [ParNew: 942035K->104832K(943744K), 3.4626740 secs] 9571668K->8831757K(10380928K), 3.4627820 secs] [Times: user=0.35 sys=0.07, real=3.47 secs]
2015-07-23T06:25:43.548-0400: [GC [ParNew (promotion failed): 943744K->943744K(943744K), 3.9544520 secs][CMS2015-07-23T06:31:11.405-0400: [CMS-concurrent-sweep: 327.407/334.829 secs] [Times: user=8.42 sys=1.77, real=334.78 secs]
(
concurrent mode failure): 8881917K->1234174K(9437184K), 357.1201510 secs] 9645662K->1234174K(10380928K), [CMS Perm : 67582K->63968K(111848K)], 361.0747320 secs] [Times: user=10.25 sys=1.59, real=361.02 secs]
這里基本和上面類似，ParNew在06:25:43.548結(jié)束，花費(fèi)3.9544520s發(fā)現(xiàn)promotion failed，啟動CMS GC，但在327.407s（從ParNew開始算起）完成CMS-concurrent-sweep后還是無法存放promote上來的對象，而發(fā)生concurrent mode failure，然后開始整理以容納promote的對象，花費(fèi)20s左右時間，最后做Perm GC，花費(fèi)4s左右。這里CMS-concurrent-sweep之所以要花費(fèi)327.407s的時間，應(yīng)該還是和page faults相關(guān)吧？
這是發(fā)生在CMS-concurrent-mark階段：
2015-07-17T03:21:28.701-0400: [GC [1 CMS-initial-mark: 7598316K(9437184K)] 7703150K(10380928K), 1.5896460 secs] [Times: user=0.02 sys=0.00, real=1.59 secs]
2015-07-17T03:22:16.910-0400: [GC [ParNew (promotion failed): 943744K->943744K(943744K), 7.5542170 secs][CMS2015-07-17T03:22:26.210-0400: [CMS-concurrent-mark: 32.098/55.919 secs] [Times: user=32.19 sys=1.54, real=55.91 secs]
(
concurrent mode failure): 8270889K->1474450K(9437184K), 27.2265650 secs] 9074498K->1474450K(10380928K), [CMS Perm : 64992K->63114K(108020K)], 34.7809080 secs] [Times: user=6.10 sys=0.21, real=34.78 secs]
這里的問題類似，不贅述。
這是另一種情況下發(fā)生在CMS-concurrent-abortable-preclean階段：2015-07-23T06:24:47.450-0400: [GC [1 CMS-initial-mark: 3938781K(5973632K)] 3998846K(6126976K), 0.0030340 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2015-07-23T06:24:47.546-0400: [CMS-concurrent-mark: 0.093/0.093 secs] [Times: user=0.27 sys=0.01, real=0.09 secs]
2015-07-23T06:24:47.559-0400: [CMS-concurrent-preclean: 0.013/0.013 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
2015-07-23T06:24:47.665-0400: [GC [ParNew2015-07-23T06:24:47.675-0400: [CMS-concurrent-abortable-preclean: 0.012/0.116 secs] [Times: user=0.16 sys=0.02, real=0.11 secs]
(
promotion failed): 133502K->140562K(153344K), 0.0393600 secs][CMS (
concurrent mode failure): 3948765K->479672K(5973632K), 1.9491860 secs] 4072283K->479672K(6126976K), [CMS Perm : 62974K->62509K(108776K)], 1.9886830 secs] [Times: user=0.62 sys=0.00, real=1.99 secs]
這里ParNew發(fā)生時正在執(zhí)行CMS-concurrent-abortable-preclean，而在結(jié)束時發(fā)生promotion failed，同時因?yàn)樗槠瑔栴}發(fā)生concurrent mode failure，因而出現(xiàn)Full GC。
concurrent mode failure除了和promotion failed同時發(fā)生，我在想會不會出現(xiàn)這樣的場景：CMS整個生命周期分成多個步驟，在這個過程中由于有其他新增的內(nèi)存需要分配，但是沒有足夠多的空間分配，因而產(chǎn)生concurrent mode failure的情況呢？這個在之前出現(xiàn)OOM的時候找到過一個類似的，雖然它之前是因?yàn)镻arNew promotion failed，產(chǎn)生Full GC，然后在Full GC過程中發(fā)生的。即如果是這種情況，一般代表內(nèi)存不夠用，需要增加內(nèi)存空間。
2015-07-30T11:12:38.469+0900: [GC [ParNew (promotion failed): 941415K->941415K(943744K), 0.0385590 secs] 9771224K->9867504K(10380928K), 0.0387350 secs] [Times: user=0.38 sys=0.00, real=0.04 secs]
GC locker: Trying a full collection because scavenge failed
2015-07-30T11:12:38.508+0900: [Full GC [CMS2015-07-30T11:12:38.685+0900: [CMS-concurrent-sweep: 0.863/0.911 secs] [Times: user=5.14 sys=0.32, real=0.91 secs]
(concurrent mode failure): 8926088K->8485034K(9437184K), 5.7188070 secs] 9867504K->8485034K(10380928K), [CMS Perm : 65574K->65559K(110780K)], 5.7189380 secs] [Times: user=5.70 sys=0.00, real=5.71 secs]
雖然分析了那么多，還有一個疑問沒能解決，對這個問題的調(diào)節(jié)方法還是一樣的：1. 降低CMS GC的閾值；2. 提前減少Old Gen中的碎片，即讓CMS GC做整理。這里不再贅述。
最后，我們可以看看其他的調(diào)節(jié)方式：
1. 我們知道CMS收集器很多過程是并發(fā)進(jìn)行的，因而我們可以控制并發(fā)線程的個數(shù)：-XX:ParallelCMSThreads=4，我們采用的值是4，和ParNew相同。CMS默認(rèn)的回收線程數(shù)是(CPU個數(shù)+3)/4。
2. 在歷史上還出現(xiàn)過增量式并發(fā)收集器（Incremental Concurrent Mark Sweep，i-CMS）。因?yàn)閷ι儆?個CPU的時候，如果GC占用一般左右的CPU資源，會影響用戶線程的吞吐量，因而增量式并發(fā)收集器的思想是在并發(fā)標(biāo)記和并發(fā)清理時讓用戶線程和GC線程交替運(yùn)行以減少GC占用太多的資源，特別是在只有一個CPU的情況下，即使在CMS并發(fā)階段，還是會產(chǎn)生STW的現(xiàn)象，因而可以使用i-CMS來避免這種情況。然而i-CMS已經(jīng)不再推薦使用，具體可以參考這里。大概的原因是現(xiàn)在已經(jīng)很少只有一個CPU的硬件了，而且i-CMS在線程切換時會花費(fèi)更多的資源和時間，它更加復(fù)雜，有更多的參數(shù)，難以調(diào)節(jié)，會產(chǎn)生更多的碎片。
3. 可以簡單介紹一下CMS的整個過程（還可以參考這里，或者這里，雖然這里用的例子是1.4.2的版本，我用的是1.6.30，會有一些區(qū)別）。以一個正常的CMS為例：
2015-07-21T22:17:20.667-0400: [GC [1 CMS-initial-mark: 7462216K(9437184K)] 7583692K(10380928K), 0.0223830 secs] [Times: user=0.02 sys=0.00, real=0.03 secs]
2015-07-21T22:17:21.055-0400: [CMS-concurrent-mark: 0.365/0.365 secs] [Times: user=1.75 sys=0.03, real=0.36 secs]
2015-07-21T22:17:21.075-0400: [CMS-concurrent-preclean: 0.020/0.020 secs] [Times: user=0.04 sys=0.00, real=0.02 secs]
2015-07-21T22:17:23.851-0400: [CMS-concurrent-abortable-preclean: 1.586/2.776 secs] [Times: user=5.60 sys=0.10, real=2.78 secs]
2015-07-21T22:17:23.852-0400: [GC[YG occupancy: 679011 K (943744 K)][Rescan (parallel) , 0.1319540 secs][weak refs processing, 0.0001560 secs] [1 CMS-remark: 7511697K(9437184K)] 8190709K(10380928K), 0.1321850 secs] [Times: user=0.46 sys=0.01, real=0.13 secs]
2015-07-21T22:17:30.242-0400: [CMS-concurrent-sweep: 6.004/6.258 secs] [Times: user=11.89 sys=0.17, real=6.26 secs]
2015-07-21T22:17:30.261-0400: [CMS-concurrent-reset: 0.018/0.018 secs] [Times: user=0.04 sys=0.00, real=0.02 secs]
1 CMS-initial-mark：初始標(biāo)記標(biāo)記階段，STW，CMS起始點(diǎn)，標(biāo)記所有Root對象直接可達(dá)的對象，7462216K是CMS觸發(fā)時Old Gen的內(nèi)存大小，7583692K是Old Gen＋Young Gen的內(nèi)存大小。
CMS-concurrent-mark：重新標(biāo)記階段，和用戶線程同時處理，遍歷初始標(biāo)記出來的對象的所有直接或間接可達(dá)對象。CPU時間0.365s，總共0.365s（wall time）。這里times時間不是那么準(zhǔn)確，因?yàn)槠鹩谠撾A段的開始，但是中間可能包含其他的事情，如用戶線程的執(zhí)行影響等。
CMS-concurrent-preclean：preclean階段，這個階段依然和用戶線程同時處理，它會繼續(xù)查看在重新標(biāo)記階段新產(chǎn)生的對象：從Young Gen promote上來的對象，新分配的對象，或被修改的對象。這個階段主要用于減少下一次重新標(biāo)記（remark）的時間，因?yàn)橹匦聵?biāo)記會STW。CPU時間0.020s，總共0.020s（wall time）。
CMS-concurrent-abortable-preclean：可中斷的preclean階段，和用戶線程同時處理，當(dāng)preclean已經(jīng)結(jié)束的時候就可以開始remark了，然而如果這樣設(shè)計(jì)，由于CMS-concurrent-preclean和用戶線程一起運(yùn)行，當(dāng)它結(jié)束的時候，Young Gen已經(jīng)使用了很多了，但是這里面有很多是可以回收的，為了提升效率就可以先ParNew GC回收掉多余的對象，然后就會接著執(zhí)行remark，就可以減少remark的時間；而如果Young Gen使用的很少，就可以立即啟動remark過程；而如果介于之間，就可以先等待一會讓eden占用一些空間后再啟動remark，從而將ParNew GC的STW和remark的STW錯分開。因而CMS的設(shè)計(jì)者就想出remark的執(zhí)行時機(jī)還依賴于eden的使用情況（因?yàn)樾聦ο罂偸窍确峙涞絜den空間），即通過兩個變量來控制：CMSScheduleRemarkEdenSize和CMSScheduleRemarkEdenPenetration，它們的默認(rèn)值分別是2M和50%，表示在CMS-concurrent-preclean結(jié)束后，如果eden只使用了少于2M，則直接啟動remark；如果超過2M，但沒有超過50%，則先啟動CMS-concurrent-abortable-preclean，直到eden的使用率超過了50%，然后啟動remark過程，這樣就保證了remark和ParNew GC中間會有一定的時間間隔；如果已經(jīng)超過了50%，就等待下次ParNew GC完成，然后再做remark？貌似只有這樣才能解釋的通這些日志，當(dāng)remark階段準(zhǔn)備好后它可以隨時被中斷，它的中斷不是錯。如這種日志：
2015-06-16T03:15:21.471-0400: [CMS-concurrent-preclean: 0.030/0.031 secs] [Times: user=0.05 sys=0.00, real=0.03 secs]
CMS: abort preclean due to time 2015-06-16T03:15:26.659-0400: [CMS-concurrent-abortable-preclean: 3.351/5.187 secs] [Times: user=3.50 sys=0.04, real=5.19 secs]
2015-06-16T03:15:26.659-0400: [GC[YG occupancy: 561249 K (943744 K)][Rescan (parallel) , 0.1650010 secs][weak refs processing, 0.0000680 secs] [1 CMS-remark: 7465008K(9437184K)] 8026257K(10380928K), 0.1651410 secs] [Times: user=0.52 sys=0.00, real=0.16 secs]
這個日志表示preclean結(jié)束后，eden的空間在2M和50%之間，因而啟動abortable-preclean階段，直到4.84s后才因?yàn)閑den超過50%后中斷CMS-concurrent-abortable-preclean，并開始remark，實(shí)際使用0.16s。
2015-07-03T08:15:21.840-0400: [CMS-concurrent-preclean: 0.019/0.019 secs] [Times: user=0.04 sys=0.00, real=0.02 secs]
2015-07-03T08:15:22.605-0400: [GC [ParNew2015-07-03T08:15:22.636-0400: [CMS-concurrent-abortable-preclean: 0.693/0.795 secs] [Times: user=1.30 sys=0.06, real=0.79 secs]
: 943744K->104832K(943744K), 0.2089320 secs] 8446030K->7838840K(10380928K), 0.2090220 secs] [Times: user=0.60 sys=0.01, real=0.21 secs]
2015-07-03T08:15:22.815-0400: [GC[YG occupancy: 120239 K (943744 K)][Rescan (parallel) , 0.0289020 secs][weak refs processing, 0.0001000 secs] [1 CMS-remark: 7734008K(9437184K)] 7854247K(10380928K), 0.0290690 secs] [Times: user=0.13 sys=0.00, real=0.03 secs]
這個日志表示在CMS-concurrent-preclean結(jié)束后，eden使用空間已經(jīng)超過50%，所以啟動abortable-preclean，并在155ms后啟動ParNew GC，在ParNew停止31ms后停止CMS-concurrent-abortable-preclean，而remark隨后開始，經(jīng)歷30ms結(jié)束。
2015-07-30T12:06:22.199+0900: [CMS-concurrent-preclean: 0.007/0.007 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2015-07-30T12:06:22.199+0900: [GC[YG occupancy: 2534 K (19136 K)][Rescan (parallel) , 0.0016670 secs][weak refs processing, 0.0000110 secs] [1 CMS-remark: 1984060K(3050752K)] 1986594K(3069888K), 0.0017300 secs] [Times: user=0.03 sys=0.00, real=0.00 secs]
這個日志表示preclean結(jié)束后eden使用少于2M，因而跳過abortable-preclean，直接開始remark階段。
1 CMS-remark：重新標(biāo)記階段，STW，這里YG occupancy表示該階段開始時Young Gen的大小，因?yàn)檫@個階段的時間長短部分依賴于Young Gen的大小；Rescan用于多線程掃描程序停止時存活的對象，花費(fèi)0.1319540s；weak refs processing用于處理weak reference的情況，花費(fèi)0.0001s，如果這個階段花費(fèi)太長時間，可以打開開關(guān)：-XX:+ParallelRefProcEnabled來調(diào)節(jié)；然后開始重新標(biāo)記，即重新從Root對象遍歷標(biāo)記存活對象。
CMS-concurrent-sweep：并發(fā)清理，和其他線程同時執(zhí)行，做真正的清理工作，如把可以回收的內(nèi)存放回空閑列表，合并相鄰內(nèi)存空間等。
CMS-concurrent-reset：重置CMS的狀態(tài)用于下一次執(zhí)行。
這篇博客寫了一個多星期了，終于快收尾了。對于GC，所實(shí)話自己以前關(guān)注的并不多，一直覺得自己了解到的東西已經(jīng)夠用了，直到這次一個同事把我們項(xiàng)目中GemFire節(jié)點(diǎn)調(diào)出和GC的停頓時間聯(lián)系起來，然后我突然感覺很多問題豁然開朗了。因而這一周潛心讀了很多相關(guān)文章來完成這篇博客。其實(shí)還有很多可以說的，或者自己不了解的，這些只能留待以后慢慢補(bǔ)充，但是經(jīng)歷這個事件后，發(fā)現(xiàn)自己對GC的了解和一些設(shè)計(jì)思想提升了一個檔次，記之。