前言
最近斷斷續(xù)續(xù)看了《Java Performance The Definitive Guide》前六章冷溃，記錄一下關(guān)于GC部分的讀書筆記。
GC
本書的第五章和第六章主要講了關(guān)于GC相關(guān)的只是盖淡，由于目前線上機器多采用了CMS凿歼，所以重點關(guān)注CMS部分禁舷。先設(shè)置PrintGCDetails后牵咙，觀察gc.log
Understanding the Throughput Collector
這種類型的GC會對Young和Old都進行STW型的收集
YGC
YGC的日志大概長這樣
17.806: [GC [PSYoungGen: 227983K->14463K(264128K)]
280122K->66610K(613696K), 0.0169320 secs]
[Times: user=0.05 sys=0.00, real=0.02 secs]
該段日志表明本次gc發(fā)生在據(jù)程序開始運行12.806秒后（gclog的時間格式可以設(shè)置）攀唯。gc后，young區(qū)的對象占用了14MB內(nèi)存空間（在survivor區(qū)）另凌。在gc前戒幔，young區(qū)對象占用了227MB。目前young區(qū)的總大小為264MB诗茎。
同時，整個heap的占用（包括young區(qū)和old區(qū)）從280MB減少到227MB敢订，目前整個heap的大小為613MB。整個gc操作共耗時0.02s昭齐。整個gc程序消耗的cpu時間比realtime（實際時間）要長矾柜，主要是因為ygc是由多個線程（本次配置為4個線程）共同完成的就谜。
full gc
old區(qū)gc同時會清除young區(qū)的所有對象（包括survivor的對象）吁伺。Old區(qū)中僅剩的對象都有活躍引用租谈，所有這些對象都會被壓縮排列捆愁。
FUllGC的日志大概長這樣
64.546: [Full GC [PSYoungGen: 15808K->0K(339456K)]
[ParOldGen: 457753K->392528K(554432K)] 473561K->392528K(893888K)
[PSPermGen: 56728K->56728K(115392K)], 1.3367080 secs]
[Times: user=4.44 sys=0.01, real=1.34 secs]
這段日志表明，現(xiàn)在Young區(qū)總共占用0bytes(總的大小為339MB)呻逆。old區(qū)中的數(shù)據(jù)從457MB減少到了392MB咖城，因此整個heap使用從473MB減少到了392MB。permgen的大小沒有改變宜雀，在大多數(shù)full gc時握础，permgen大小不會該表（如果permgen區(qū)占滿了，JVM會觸發(fā)一次fullgc進行permgc禀综，此時permgen的占用大小才會改變）。因為full gc有更多工作需要做孤澎，所以花了1.3秒實際時間欠窒，4.4s的cpu時間（因為有四個并行線程）
總結(jié)
- throughput collector有兩種操作：minor gc和full gc。
- gc Log中的時間可以用來衡量gc對于應(yīng)用的影響
Understanding the CMS Collector
由于目前線上的機器大部分使用的是cms gc策略岖妄，所以重點關(guān)注了這部分
cms有三種基本的操作：
- cms進行ygc(將停止所有應(yīng)用線程)
- cms開啟concurrent cycle清除old區(qū)的數(shù)據(jù)
- 如果有必要，cms進行full gc
young gc
cms ygc和throughput的ygc非常相似：data從eden移入到一個survivor區(qū)中衣吠，然后進去old區(qū)茶敏。
cms的gc log和throughput的非常相似
89.853: [GC 89.853: [ParNew: 629120K->69888K(629120K), 0.1218970 secs]
1303940K->772142K(2027264K), 0.1220090 secs]
[Times: user=0.42 sys=0.02, real=0.12 secs]
日志表明：young區(qū)當(dāng)下的大小為629MB，在gc后缚俏，占用了69MB（在survivor區(qū)）惊搏。類似的贮乳，整個Heap的大小為2027MB，在gc后恬惯，仍然有772MB被占用向拆。整個過程花費了0.12s，耗費了0.42s的cpu時間酪耳。
concurrent cycle
根據(jù)heap的占用浓恳，jvm將開啟concurrent cycle。當(dāng)足夠滿的時候碗暗，jvm開啟backgroup線程從heap中移除對象颈将。需要注意的是Old區(qū)不會被壓縮整理：已分配的區(qū)域和空閑區(qū)域可能間隔。當(dāng)ygc后將對象從eden區(qū)移入到old區(qū)中言疗，jvm將使用上述空閑區(qū)域容納這些對象晴圾。
從gclog中可以看出，整個concurrent cycle 分成很多階段噪奄。即使concurrent cycle的主要過程使用background線程，但是仍然有些階段會導(dǎo)致短暫暫停所有應(yīng)用線程都毒。
initial mark phase
concurrent cycle開始于一個initial mark階段，這個階段暫停了所有的應(yīng)用手负。日志如下：
89.976: [GC [1 CMS-initial-mark: 702254K(1398144K)]
772530K(2027264K), 0.0830120 secs]
[Times: user=0.08 sys=0.00, real=0.08 secs]
這個階段主要是負責(zé)找出heap中所有的gc roots蝠猬。第一組數(shù)字表示說目前old區(qū)的大小為1398MB榆芦，對象占用了702MB。第二組數(shù)字說明整個heap的大小為2027MB崎淳，對象占用了772MB拣凹。在在initial mark階段嚣镜，應(yīng)用線程暫停了0.08s菊匿。
mark phase
接下來的就是mark 階段徽职，在這個階段中不會暫停應(yīng)用線程力麸。gc日志中會出現(xiàn)以下行：
90.059: [CMS-concurrent-mark-start]
90.887: [CMS-concurrent-mark: 0.823/0.828 secs]
[Times: user=1.11 sys=0.00, real=0.83 secs]
mark階段耗時0.83s(1.11秒的CPU時間)克蚂。由于只是進行mark摸恍，所以沒有出現(xiàn)和heap內(nèi)存占用相關(guān)的信息立镶。
preclean phase
該階段不會暫停應(yīng)用線程
abortable-preclean phase
有了preclean phase為啥還需要abortable-preclean phase呢，abortable-preclean phase到底是做什么用的缭召。
需要abortable-preclean階段主要考量是因為remark phase階段會需要STW（YGC也是需要STW的）。為了不讓系統(tǒng)在ygc之后馬上進行remark（因為這樣會連續(xù)經(jīng)歷兩次STW搪哪，時間拉長）
噩死。所以abortable-preclean會在young區(qū)差不多50%滿的時候開始行嗤。在ygc完成后垛耳，cms會根據(jù)之前的ygc時間計算下次ygc發(fā)生的時間栈雳，在預(yù)測young區(qū)差不多50%滿的時候停止abortable-preclean，然后緊接著remark階段開始蛀骇。
同時擅憔，由于remark階段會需要重新掃描young區(qū)，所以會存在一個矛盾个榕。為了讓remark更快，young區(qū)必須更锌寥谩（最好是剛minor gc完）所以從remark時間最短的角度來看最好是每次remark之前都要觸發(fā)一次minor gc（設(shè)置CMSScavengeBeforeRemark）。但是這樣又會造成連續(xù)兩次STW（minor gc & remark）仿畸，造成系統(tǒng)不可用時間拉長簿晓。所以最好的解決方案就是為讓ygc和remark之間通過abortable-preclean階段隔開，并且會希望在abortable-preclean階段過程中發(fā)生一次minor gc谒臼，所以在young區(qū)50%滿的時候開始，在進行完一次monir gc底哥，并且估算差不多又一次young區(qū)50%滿的時候停止abortable-preclean（停止abortable-preclean不止取決于很多因素，通過CMSMaxAbortablePrecleanTime可以影響附较，超過CMSMaxAbortablePrecleanTime不管有沒有發(fā)生minor gc都會進入到remark階段事示，所以CMSMaxAbortablePrecleanTime應(yīng)該和minor gc周期保持關(guān)系）
remark phase
緊接著就是remark phase階段肖爵，日志如下：
90.892: [CMS-concurrent-abortable-preclean-start]
92.392: [GC 92.393: [ParNew: 629120K->69888K(629120K), 0.1289040 secs]
1331374K->803967K(2027264K), 0.1290200 secs]
[Times: user=0.44 sys=0.01, real=0.12 secs]
94.473: [CMS-concurrent-abortable-preclean: 3.451/3.581 secs]
[Times: user=5.03 sys=0.03, real=3.58 secs]
94.474: [GC[YG occupancy: 466937 K (629120 K)]
94.474: [Rescan (parallel) , 0.1850000 secs]
94.659: [weak refs processing, 0.0000370 secs]
94.659: [scrub string table, 0.0011530 secs]
[1 CMS-remark: 734079K(1398144K)]
1201017K(2027264K), 0.1863430 secs]
[Times: user=0.60 sys=0.01, real=0.18 secs]
上述日志包括了abortable-preclean和remark秒啦，通過abortable-preclean余境，使得minor gc和remark兩個stw階段之間差不多隔了半個minor gc周期含末。需要注意的是remark階段會scan整個heap，注意日志中的94.474: [GC[YG occupancy: 466937 K (629120 K)]
94.474: [Rescan (parallel) , 0.1850000 secs]
sweep phase
接下來的一個階段是concurrent sweep phase，這個階段不會stw
94.661: [CMS-concurrent-sweep-start]
95.223: [GC 95.223: [ParNew: 629120K->69888K(629120K), 0.1322530 secs]
999428K->472094K(2027264K), 0.1323690 secs]
[Times: user=0.43 sys=0.00, real=0.13 secs]
95.474: [CMS-concurrent-sweep: 0.680/0.813 secs]
[Times: user=1.45 sys=0.00, real=0.82 secs]
這個階段花費了大概0.82s。階段中間還經(jīng)歷了一次minor gc。需要說明的是minor gc可能會同時出現(xiàn)在old collection phases。在整個the sweep phase階段可能會出現(xiàn)任意多個minor gc。
reset phase
最后舞骆，是reset階段
95.474: [CMS-concurrent-reset-start]
95.479: [CMS-concurrent-reset: 0.005/0.005 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]
至此狈惫，整個CMS cycle完成了荸频。
CMS問題
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]
當(dāng)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
第二個問題就是當(dāng)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)存别惦。
permgen fill up
當(dāng)perm區(qū)滿了之后仁讨，需要被回收洞豁，會觸發(fā)一次Full gc
279.803: [Full GC 279.803:
[CMS: 88569K->68870K(1398144K), 0.6714090 secs]
558070K->68870K(2027264K),
[CMS Perm : 81919K->77654K(81920K)],
0.6716570 secs]
CMS問題解決手段(Tuning to Solve Concurrent Mode Failures)
concurrent mode or promotion failures產(chǎn)生的原因其實是由于‘老年代cms cycle和minor gc速度的不匹配’。
The old generation initially fills up by placing the objects right next to each other. When
some amount of the old generation is filled (by default, 70%), the concurrent cycle begins
and the background CMS thread(s) start scanning the old generation for garbage. At
this point, a race is on: CMS must complete scanning the old generation and freeing
objects before the remainder (30%) of the old generation fills up. If the concurrent cycle
loses the race, CMS will experience a concurrent mode failure.
可以從以下多個方面來避免：
- 加大old區(qū)荒给，要不就是加大old區(qū)的比重丈挟，要不就是跳大heap 空間。
- 使得cms cycles更頻繁
- 使用更多的background 線程
Running the background thread more often
要想讓CMS贏得‘比賽’需要使得concurrent cycle更早的執(zhí)行志电。
我們可以通過設(shè)置-XX:CMSInitiatingOccupancyFraction=N 和 -XX:+UseCMSInitiatingOccupancyOnly改變開始執(zhí)行的計算邏輯曙咽。默認的UseCMSInitiatingOccupancyOnly是false，CMS會用一個很復(fù)雜的算法決定什么時候來時concurrent cycle.
當(dāng)UseCMSInitiatingOccupancyOnly設(shè)置為true時挑辆，默認的XX:CMSInitiatingOccupancyFraction是70例朱，也就是說在old區(qū)70%被占滿的時候開始concurrent cycle。
Adjusting the CMS background threads
Each CMS background thread will consume 100% of a CPU on a machine.cms gc后臺線程的數(shù)量可以通過-XX:ConcGCThreads=N設(shè)置鱼蝉。默認的話洒嗤，
ConcGCThreads = (3 + ParallelGCThreads) / 4
總結(jié)
- Avoiding concurrent mode failures is the key to achieving the
best possible performance with CMS.
- The simplest way to avoid those failures (when possible) is to
increase the size of the heap. - Otherwise, the next step is to start the concurrent background
threads sooner by adjusting the CMSInitiatingOccupancyFrac
tion. - Tuning the number of background threads can also help.
監(jiān)控手段
- 最直接的監(jiān)控手段就是通過詳細的gc.log，我們可以通過腳本抓取并分析gc.log魁亦，可以通過關(guān)鍵詞檢測有無‘concurrent mode failures’和‘promotion failed’烁竭，有無‘Fullgc’等，原則上有這些關(guān)鍵字存在需要立即觸發(fā)warning報警吉挣。
- 分析日志可以得出ygc的頻率和時長派撕，ygc頻率過高，平均時間拉長到閾值應(yīng)該觸發(fā)報警
- 可以通過GarbageCollectorMBean獲取collectCount和collectTime睬魂，需要注意的是Count是累加總次數(shù)终吼，collectTime是累加的STW的總時間
總結(jié)
java performance GC相關(guān)讀書筆記，看到新的東西會繼續(xù)補充
