開始我們一直覺得這是網絡的問題,因為N1不可能在3分鐘內沒有給N2響應,并且當Locator向它詢問are-you-dead的時候它還是沒有相應,而在當前這個case下,它竟然有6分鐘沒有相應,那么長的時間里這個節點會處理什么事情呢?因而我們用了各種工具查網絡在出問題的那個點上的情況,有沒有中斷、包丟失之類的,然而一無所獲,直到我們從GC的日志中找到了這句話:
要不是親眼所見,我真不敢相信GC會用掉6分多鐘的時間!!自己之前也有看過GC相關的書籍,但是一直覺得GC很快(估計是看的不夠多),因而并沒有引起很大的重視,然后我去翻了一下以前GC的日志,發現我們它不是一個可以隨便忽略的操作,即使是ParNew GC都有可能花費7s的時間!!而且平時也一般都在二三十毫秒的數量級(這是我們的測試環境,生產環境的性能要好很多,基本在幾個毫秒的級別)。
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經常要花費10s+的時間,雖然這不是一個STW(Stop The World)操作,但是這個時間也是已經很長了,會影響整體性能(它需要耗費CPU,我們當前設置4個CPU做GC)。
然而在我們的系統中GC花費那么長的時間,當然是和我們的內存大小設置有關系,因為我們的數據節點每個內存大小10G,其中Young Gen:1G,Perm Gen:200M,Old Gen:~9G,因而做一次Full GC當然是比較費時間的。所以一種最簡單的做法當然是減少內存,然而減少一個數據節點的內存意味著我們需要增加節點的個數,不然無法保證GemFire集群能存下所有的數據,而增加節點個數又會帶來新的問題,如增加運帷難度,節點出錯的概率提高,提高集群的通信成本,增加MetaData的存儲空間等,因而這個目前不是好的方向。所以我們只能尋求2和3的方案。
當前GemFire節點退出集群問題的直接原因是因為ParNew GC promotion失敗,從而引起CMS GC,然而CMS GC又產生concurrent mode failure,進而引起STW(Stop The World)的Full GC引起的,因而比較直接的方案就是調節JVM的參數,以減少GC停頓時間,并且盡量避免Full GC,即方案2。對JVM參數調節首先可以從選擇不同的GC收集器開始,如對Young Gen的Serial、ParNew、Parallel Scavenge,對Old Gen的CMS、Serial Old(MSC)、Parallel Old,或者是直接用G1,我們目前使用ParNew+CMS,已經使用多年,而且老板屬于保守型,這條路也基本走不通,因而這里只介紹ParNew+CMS的GC。
對ParNew收集器,它是Serial收集器的多線程版本,使用復制算法,由于每次GC的存活對象很少,因而它使用兩個Survivor和一個Eden實現,默認情況下Survivor和Eden的比例是1:8,因而這里可以調節的參數有Young Gen的總大小(-XX:NewSize=1024M -XX:MaxNewSize=1024M),Survivor和Eden的比例(-XX:SurvivorRatio=8),收集線程數(-XX:ParallelGCThreads,默認與CPU數量相同),對對象大小超過一定數值的直接晉升到老年代(-XX:PretenureSizeThreshold,無默認值),設置晉升到老年代的年齡(-XX:MaxTenuringThreshold,默認15),開啟Promotion失敗的擔保(-XX:+HandlePromotionFailure,1.6默認開啟)。在我們的設置中,Young Gen的總大小和最大大小設置為一樣(1G)以減少動態分配的開銷,然而在觀察中發現102.4M的Survivor大小有些時候并不足以存放所有的存活對象,因而可以適當增加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內存從932867K降到104832K(102.375M),減少828035K,然而實際內存從7881112K下降到7169555K,只減少了711557K,即有116478K的對象直接晉升到了Old Gen(這些對象有部分可能是已經到了晉升的年齡,然而由于Minor GC后Survivor幾乎滿了,因而基本可以確定有部分對象并沒有到達晉升年齡而直接晉升了)。
在觀察ParNew GC的日志后,我發現大部分情況user和real的時間保持在1:1到5:1之間,然而其實我們有8個CPU,即8個CPU并沒有很好的發生作用,反而因為線程交互開銷而影響了它的性能,因而可以設置4個線程來回收;另外,通過日志我還發現有些時候real的時間要遠遠超過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不足以存放所有的存活對象,然而并不是所有的,如第一條就不是,對這個我一直很納悶,在網上也沒有找到非常可能的答案,但是大概
這個答案看起來比較靠譜,簡單來說,就是當時有很多page faults,這個也符合我們當時的情況,因為這臺機器原本內存不是那么足,因而偶爾會出現內存swap,而且在這種情況下,所有的sys時間相對都比較長,也是一個佐證;另外也有人解釋說ParNew在
Stop-The-World之前要確保所有JNI線程都暫停下來,因而需要等待到達safepoint,這個貌似不太像我們遇到的情況,因為我們沒有使用外部的JNI,如果內部自己的JNI應該不至于有那么大的影響(但是這個點正好說明我們使用JNI的時候要非常小心,如果有函數運行時間太長會影響JVM的穩定性,甚至讓JVM沒有響應,因為它在GC的時候要等這個長時間的JNI方法結束,或到達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暫停的時間都比較短,而且在大部分情況下,或者在其他內存夠用的集群中我們沒有遇到那么久的GC時間,因而基本不需要過多調節,所以其他都保持了它的默認值。
更正:前幾天我們再次發現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]
通過一些系統工具,我們發現在問題發生的時候,當時那臺機器有26%左右的Swap內存,并且有很高的page fault,因而我們基本能肯定這是內存數據被換出到Swap然后在GC的時候產生page fault引起的。并且在
這里還提及到了swap中每4KB數據會增加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.
因而我們基本能肯定發生那么長的時間就是因為內存swap引起的,據說在Cassandra調優時有些直接把虛擬內存禁掉,以防出現類似的問題。
CMS收集器調節
重點當然是要調節CMS收集器,即要避免它在收集時停頓過長,更要避免產生promotion failed和concurrent mode failure的情況,因為這兩種情況發生后都會引起CMS做Stop-The-World GC,其中第二中情況在做GC時還會做整理(Compact),因而會有更久的停頓,而我們這次是兩種情況同時遇到了。要避免這兩種情況的發生需要先理解為什么會發生這兩種情況。
首先,我們來看看promotion failed發生的情況:
我們知道當對象到一定的年齡,或者在某次回收過程中一個Survivor無法裝下所有存活的對象,或者一個對象的大小超過-XX:PretenureSizeThreshold設置的值,就會被promote到Old Gen中,而在promote過程中如果Old Gen無法裝下所有的內存時就會產生promotion failed(這里說CMS是根據預估的值: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來預估?所以應該是ParNew把需要promote的對象傳遞給CMS,然后CMS做預估決定是否有足夠多的內存存放這些新promote的對象),此時就會先做一遍CMS GC,然后將新promote的對象存放到Old Gen中,由于這屬于ParNew GC的范圍,因而這次的CMS GC依然處于STW狀態,因而這會花比較久的時間。如這次的ParNew GC,花費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]
我們當前的設置:-XX:CMSInitiatingOccupancyFraction=79 -XX:+UseCMSInitiatingOccupancyOnly,也就是只有到Old Gen占用79%后才會觸發CMS GC,這里只占66.57%,因而還沒能觸發CMS GC,然而此時ParNew GC只回收了3061K的對象,還有841244K的對象存活,而一個Survivor只有104857.6K大小,此時需要promote大概736386.4K大小的數據到Old Gen中,此時Old Gen還有(9437184K-6282619K=3154565K)大小的內存,雖然遠遠大于被promote的對象,但是我們知道CMS采用標記-清除(Mark-Sweep)算法,而不主動整理(Compact),但是它在每次回收時會合并相鄰的內存空間,然而跑久了難免會產生內存碎片,也就是說此時內存碎片已經很多了,無法容納新promote的對象,要不就是新promote的對象大小太大,或者碎片太小,因而需要出發一次CMS GC來釋放一些空間(此時發生的CMS是不是已經退化成Serial Old收集器算法了?即在收集的過程還是整理?),以保證能存放下所有新promote出的對象。這里GC日志中并沒有顯示出什么這次ParNew GC后,Young Gen還剩下多少內存,但是根據下一次ParNew GC的初始大小是838912K,小于之前存活下來的對象(841244K),因而我們可以確定這次GC的結果是把多余的對象promtoe到Old Gen中了。
所以根據分析,我們可以從兩個方向調節參數:
1. 降低CMS GC的閾值。
2. 提前減少Old Gen中的碎片,即讓CMS GC做整理。
對降低CMS GC閾值,我們可以調節參數:-XX:CMSInitiatingOccupancyFraction,默認大小68,我們可以將它設置成60。對提前減少Old Gen的碎片,這個比較麻煩,我們不想每次CMS GC都做整理(Compact),因而這會比較浪費,會增加GC總體的時間以及停頓的時間,而且也比較危險,因為萬一某次整理時間太長會引起集群的不穩定(可以設置-XX:UseCMSCompactAtFullCollection來實現這個功能)。還有一種辦法是設置每經歷N次CMS后做一次整理,通過-XX:CMSFullGCsBeforeCompaction=<N>來設置,這個相對可以接受一些。當然如果能找到一個相對空閑的時間手動觸發一次Full GC,并且確保讓它能觸發整理(這個目前還沒有找到合適的方法,JConsole提供的GC按鈕是一個可選項,但是不確定。我做了一下嘗試:
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]
看起來是減少了不少內存,按日志的格式,看起來像是Serial Old的算法?另外,使用這個功能要確保-XX:-DisableExplicitGC是關閉的,雖然這就是默認值)。
值得注意的是,promotion failed的情況也可以產生很長的停頓,這里我們看到總的時間是378.38s,user的時間只有5.56s,而sys的時間高達1.80s,看起來和ParNew長時間停頓的情況類似,即產生了對象換出到虛擬內存了?
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]
關于產生promotion failed,這里還有更詳細的解釋,如涉及到PLAB(Promotion Local Allocation Buffer)的介紹等,以及這里是對它的更正。值得注意的是,CMS在管理內存中使用空閑列表的方式,然而這種方式可能會存在某些問題,如這句話所說(具體就不展開了):
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發生前,它會預估Old Gen是否有足夠的空間存放從Young Gen中promote上來的對象,CMS收集器根據之前統計來預估這些對象的大小,如果Old Gen沒有足夠的空間存放這個預估的值,就會發生concurrent mode failure。此時不一定會產生Full GC,有些時候JVM只是等待當前并行收集完成,但是用戶程序此時還是會STW直到這次收集技術。
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.
然而根據我的觀察,concurrent mode failure都是發生在CMS已經開始,但是在中間階段,出現ParNew的promotion failed。
如這是發生在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發生時,CMS-concurrent-preclean結束不久,此時ParNew花費0.2429280s完成,想premote一些對象而失敗,因而CMS在06:17:06.239完成步驟:CMS-concurrent-abortable-preclean,然而這個步驟結束后,依然無法容納promote上來的對象,所以需要做一個Full GC,完成以后Old Gen內存從7747387K下降到1603792K,總內存從8556110K下降到1603792K,即將所有Young Gen中存活的對象放到了Old Gen中了。
這是發生在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結束,花費3.9544520s發現promotion failed,啟動CMS GC,但在327.407s(從ParNew開始算起)完成CMS-concurrent-sweep后還是無法存放promote上來的對象,而發生concurrent mode failure,然后開始整理以容納promote的對象,花費20s左右時間,最后做Perm GC,花費4s左右。這里CMS-concurrent-sweep之所以要花費327.407s的時間,應該還是和page faults相關吧?
這是發生在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]
這里的問題類似,不贅述。
這是另一種情況下發生在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發生時正在執行CMS-concurrent-abortable-preclean,而在結束時發生promotion failed,同時因為碎片問題發生concurrent mode failure,因而出現Full GC。
concurrent mode failure除了和promotion failed同時發生,我在想會不會出現這樣的場景:CMS整個生命周期分成多個步驟,在這個過程中由于有其他新增的內存需要分配,但是沒有足夠多的空間分配,因而產生concurrent mode failure的情況呢?這個在之前出現OOM的時候找到過一個類似的,雖然它之前是因為ParNew promotion failed,產生Full GC,然后在Full GC過程中發生的。即如果是這種情況,一般代表內存不夠用,需要增加內存空間。
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]
雖然分析了那么多,還有一個疑問沒能解決,對這個問題的調節方法還是一樣的:1. 降低CMS GC的閾值;2. 提前減少Old Gen中的碎片,即讓CMS GC做整理。這里不再贅述。
最后,我們可以看看其他的調節方式:
1. 我們知道CMS收集器很多過程是并發進行的,因而我們可以控制并發線程的個數:-XX:ParallelCMSThreads=4,我們采用的值是4,和ParNew相同。CMS默認的回收線程數是(CPU個數+3)/4。
2. 在歷史上還出現過增量式并發收集器(Incremental Concurrent Mark Sweep,i-CMS)。因為對少于4個CPU的時候,如果GC占用一般左右的CPU資源,會影響用戶線程的吞吐量,因而增量式并發收集器的思想是在并發標記和并發清理時讓用戶線程和GC線程交替運行以減少GC占用太多的資源,特別是在只有一個CPU的情況下,即使在CMS并發階段,還是會產生STW的現象,因而可以使用i-CMS來避免這種情況。然而i-CMS已經不再推薦使用,具體可以參考這里。大概的原因是現在已經很少只有一個CPU的硬件了,而且i-CMS在線程切換時會花費更多的資源和時間,它更加復雜,有更多的參數,難以調節,會產生更多的碎片。
3. 可以簡單介紹一下CMS的整個過程(還可以參考這里,或者這里,雖然這里用的例子是1.4.2的版本,我用的是1.6.30,會有一些區別)。以一個正常的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:初始標記標記階段,STW,CMS起始點,標記所有Root對象直接可達的對象,7462216K是CMS觸發時Old Gen的內存大小,7583692K是Old Gen+Young Gen的內存大小。
CMS-concurrent-mark:重新標記階段,和用戶線程同時處理,遍歷初始標記出來的對象的所有直接或間接可達對象。CPU時間0.365s,總共0.365s(wall time)。這里times時間不是那么準確,因為起于該階段的開始,但是中間可能包含其他的事情,如用戶線程的執行影響等。
CMS-concurrent-preclean:preclean階段,這個階段依然和用戶線程同時處理,它會繼續查看在重新標記階段新產生的對象:從Young Gen promote上來的對象,新分配的對象,或被修改的對象。這個階段主要用于減少下一次重新標記(remark)的時間,因為重新標記會STW。CPU時間0.020s,總共0.020s(wall time)。
CMS-concurrent-abortable-preclean:可中斷的preclean階段,和用戶線程同時處理,當preclean已經結束的時候就可以開始remark了,然而如果這樣設計,由于CMS-concurrent-preclean和用戶線程一起運行,當它結束的時候,Young Gen已經使用了很多了,但是這里面有很多是可以回收的,為了提升效率就可以先ParNew GC回收掉多余的對象,然后就會接著執行remark,就可以減少remark的時間;而如果Young Gen使用的很少,就可以立即啟動remark過程;而如果介于之間,就可以先等待一會讓eden占用一些空間后再啟動remark,從而將ParNew GC的STW和remark的STW錯分開。因而CMS的設計者就想出remark的執行時機還依賴于eden的使用情況(因為新對象總是先分配到eden空間),即通過兩個變量來控制:CMSScheduleRemarkEdenSize和CMSScheduleRemarkEdenPenetration,它們的默認值分別是2M和50%,表示在CMS-concurrent-preclean結束后,如果eden只使用了少于2M,則直接啟動remark;如果超過2M,但沒有超過50%,則先啟動CMS-concurrent-abortable-preclean,直到eden的使用率超過了50%,然后啟動remark過程,這樣就保證了remark和ParNew GC中間會有一定的時間間隔;如果已經超過了50%,就等待下次ParNew GC完成,然后再做remark?貌似只有這樣才能解釋的通這些日志,當remark階段準備好后它可以隨時被中斷,它的中斷不是錯。如這種日志:
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結束后,eden的空間在2M和50%之間,因而啟動abortable-preclean階段,直到4.84s后才因為eden超過50%后中斷CMS-concurrent-abortable-preclean,并開始remark,實際使用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結束后,eden使用空間已經超過50%,所以啟動abortable-preclean,并在155ms后啟動ParNew GC,在ParNew停止31ms后停止CMS-concurrent-abortable-preclean,而remark隨后開始,經歷30ms結束。
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結束后eden使用少于2M,因而跳過abortable-preclean,直接開始remark階段。
1 CMS-remark:重新標記階段,STW,這里YG occupancy表示該階段開始時Young Gen的大小,因為這個階段的時間長短部分依賴于Young Gen的大小;Rescan用于多線程掃描程序停止時存活的對象,花費0.1319540s;weak refs processing用于處理weak reference的情況,花費0.0001s,如果這個階段花費太長時間,可以打開開關:-XX:+ParallelRefProcEnabled來調節;然后開始重新標記,即重新從Root對象遍歷標記存活對象。
CMS-concurrent-sweep:并發清理,和其他線程同時執行,做真正的清理工作,如把可以回收的內存放回空閑列表,合并相鄰內存空間等。
CMS-concurrent-reset:重置CMS的狀態用于下一次執行。
這篇博客寫了一個多星期了,終于快收尾了。對于GC,所實話自己以前關注的并不多,一直覺得自己了解到的東西已經夠用了,直到這次一個同事把我們項目中GemFire節點調出和GC的停頓時間聯系起來,然后我突然感覺很多問題豁然開朗了。因而這一周潛心讀了很多相關文章來完成這篇博客。其實還有很多可以說的,或者自己不了解的,這些只能留待以后慢慢補充,但是經歷這個事件后,發現自己對GC的了解和一些設計思想提升了一個檔次,記之。