譯者著：其實(shí)本文的中心意思非常簡(jiǎn)單泡态，沒(méi)有耐心的讀者建議直接拉到最后看結(jié)論部分选泻，有興趣的讀者可以詳細(xì)閱讀一下苇本。
原文發(fā)表于Linkedin Engineering决记，作者 Zhenyun Zhuang是Linkedin的一名Staff Software Engineer摧冀，聯(lián)合作者Cuong Tran是Linkedin的一名Sr. Staff Engineer。
在我們的生產(chǎn)環(huán)境中系宫，我們不斷發(fā)現(xiàn)一些運(yùn)行在JVM上的應(yīng)用程序索昂，偶爾會(huì)因?yàn)橛涗汮VM的GC日志，而被后臺(tái)的IO操作（例如OS的頁(yè)緩存回寫）阻塞扩借，出現(xiàn)長(zhǎng)時(shí)間的STW（Stop-The-World）停頓椒惨。在這些STW停頓的過(guò)程中，JVM會(huì)暫停所有的應(yīng)用程序線程潮罪，此時(shí)應(yīng)用程序會(huì)停止對(duì)用戶請(qǐng)求的響應(yīng)康谆，這對(duì)于要求低延遲的系統(tǒng)來(lái)說(shuō)，因此所導(dǎo)致的高延遲是不可接受的嫉到。
我們的調(diào)查表明沃暗，導(dǎo)致這些停頓的原因，是當(dāng)JVM GC（垃圾回收）在寫GC日時(shí)何恶，由于write()系統(tǒng)調(diào)用所造成的孽锥。對(duì)于這些日志的寫入操作，即使是采用異步寫模式（例如细层，帶緩存的IO或者非阻塞IO）忱叭，仍然會(huì)被OS的頁(yè)緩存回寫等機(jī)制阻塞相當(dāng)長(zhǎng)的一段時(shí)間。
我們將討論解決這個(gè)問(wèn)題的各種方式今艺。對(duì)于要求低延遲的Java應(yīng)用程序來(lái)說(shuō)韵丑，我們建議將Java日志文件移動(dòng)到一個(gè)單獨(dú)的、或者高性能的磁盤驅(qū)動(dòng)上（例如SSD虚缎，tmpfs）撵彻。
生產(chǎn)環(huán)境中的問(wèn)題
當(dāng)JVM管理的Java堆空間進(jìn)行垃圾回收后钓株，JVM可能會(huì)停頓，并對(duì)應(yīng)用程序造成STW停頓陌僵。根據(jù)在啟動(dòng)Java實(shí)例時(shí)指定的JVM選項(xiàng)轴合，GC日志文件會(huì)記錄不同類型的GC和JVM行為。
雖然某些因?yàn)镚C導(dǎo)致的STW停頓（掃描/標(biāo)記/壓縮堆對(duì)象）已經(jīng)被大家熟知碗短，但是我們發(fā)現(xiàn)后臺(tái)IO負(fù)載也會(huì)造成長(zhǎng)時(shí)間的STW停頓受葛。在我們的生產(chǎn)環(huán)境中曾經(jīng)出現(xiàn)過(guò)，一些關(guān)鍵的Java應(yīng)用程序發(fā)生許多無(wú)法解釋的長(zhǎng)時(shí)間STW停頓（> 5秒） 偎谁。這些停頓既不能從應(yīng)用程序?qū)拥倪壿嬜芴病⒁矡o(wú)法從JVM GC行為的角度加以解釋。如下所示巡雨，我們展示了一個(gè)超過(guò)4秒的長(zhǎng)時(shí)間STW停頓闰渔，以及一些GC信息。當(dāng)時(shí)我們選擇的垃圾回收器是G1铐望。在一個(gè)只有8GB堆內(nèi)存和使用并行Young Garbage Collection的G1環(huán)境下冈涧，垃圾回收通常不需要1秒即可完成，并且GC日志的影響也微乎其微正蛙。但是應(yīng)用程序線程卻停頓了超過(guò)4秒督弓。所有GC完成的工作總量（例如，回收的堆大衅寡椤）也無(wú)法解釋這個(gè)長(zhǎng)達(dá)4.17秒的停頓咽筋。
2015-12-20T16:09:04.088-0800: 95.743: [GC pause (G1 Evacuation Pause) (young) (initial-mark) 8258M->6294M(10G), 0.1343256 secs] 2015-12-20T16:09:08.257-0800: 99.912: Total time for which application threads were stopped: 4.1692476 seconds
使用G1收集器時(shí)一次4.17秒的GC STW停頓
另一個(gè)例子，下面的GC日志顯示了另一次11.45秒的STW停頓徊件。這次使用的垃圾回收器是CMS（Concurrent Mark Sweep (譯者注：原文中筆誤寫成了Concurrent Mode Sweep奸攻，已聯(lián)系原作者修改)）。其中“user”/“sys”的時(shí)間幾乎可以忽略虱痕，但是“real”表示的GC時(shí)間卻超過(guò)了11秒睹耐。通過(guò)最后一行，我們可以確定應(yīng)用程序發(fā)生了11.45秒的停頓部翘。
2016-01-14T22:08:28.028+0000: 312052.604: [GC (Allocation Failure) 312064.042: [ParNew Desired survivor size 1998848 bytes, new threshold 15 (max 15) - age 1: 1678056 bytes, 1678056 total : 508096K->3782K(508096K), 0.0142796 secs] 1336653K->835675K(4190400K), 11.4521443 secs] [Times: user=0.18 sys=0.01, real=11.45 secs] 2016-01-14T22:08:39.481+0000: 312064.058: Total time for which application threads were stopped: 11.4566012 seconds
使用CMS收集器時(shí)一次11.45秒的GC STW停頓
由于應(yīng)用程序要求非常低的延遲硝训，所以我們花費(fèi)了相當(dāng)多的精力來(lái)調(diào)查這個(gè)問(wèn)題。最后新思，我們成功重現(xiàn)了這個(gè)問(wèn)題窖梁，發(fā)現(xiàn)了根本原因，以及相應(yīng)的解決方案夹囚。
在實(shí)驗(yàn)環(huán)境中重現(xiàn)問(wèn)題
對(duì)于這個(gè)導(dǎo)致無(wú)法解釋的長(zhǎng)時(shí)間JVM停頓的問(wèn)題纵刘，我們開始嘗試在實(shí)驗(yàn)環(huán)境中重現(xiàn)它。為了使該過(guò)程能夠得到更好的控制并重復(fù)重現(xiàn)荸哟，我們?cè)O(shè)計(jì)了一個(gè)簡(jiǎn)單的壓測(cè)程序假哎，來(lái)代替復(fù)雜的生產(chǎn)環(huán)境應(yīng)用程序瞬捕。
我們將在兩個(gè)場(chǎng)景下運(yùn)行這個(gè)壓測(cè)程序：含有后臺(tái)IO行為以及不含有后臺(tái)IO行為。不含有后臺(tái)IO的場(chǎng)景我們稱之為“基準(zhǔn)線（baseline）”舵抹，而含有后臺(tái)IO的場(chǎng)景用來(lái)重現(xiàn)問(wèn)題肪虎。
Java壓測(cè)程序
我們這個(gè)Java壓測(cè)程序只是不斷地生成10KB的對(duì)象，并放到一個(gè)隊(duì)列中惧蛹。當(dāng)對(duì)象數(shù)量達(dá)到100000時(shí)扇救，會(huì)從隊(duì)列中刪除一半的對(duì)象。因此堆中存放的對(duì)象最大數(shù)量就是100000個(gè)香嗓，大概會(huì)占用1GB的空間迅腔。這個(gè)過(guò)程會(huì)持續(xù)一段固定的時(shí)間（例如5分鐘）。
這個(gè)程序的源代碼和后臺(tái)IO的生成腳本陶缺，都位于https://github.com/zhenyun/JavaGCworkload。我們考慮的主要性能指標(biāo)是長(zhǎng)時(shí)間JVM GC停頓的數(shù)量洁灵。
后臺(tái)IO
后臺(tái)IO我們通過(guò)一個(gè)bash腳本饱岸，不斷地復(fù)制大文件來(lái)模擬。后臺(tái)程序會(huì)生成150MB/s的寫入負(fù)載徽千，可以使一個(gè)普通磁盤的IO變得足夠繁忙苫费。為了更好理解生成的IO負(fù)載的壓力大小，我們使用“sar -d -p 2”來(lái)收集await（磁盤處理IO請(qǐng)求的平均時(shí)間（以毫秒計(jì)））双抽，tps（每秒發(fā)往物理設(shè)備的傳輸總數(shù)）和wr_sec-per-s（寫入設(shè)備的扇區(qū)數(shù)）百框。它們分別的平均數(shù)值為：await=421 ms, tps=305, wr_sec-per-s=302K。
系統(tǒng)準(zhǔn)備
情景1 （不含后臺(tái)IO負(fù)載）
運(yùn)行基準(zhǔn)線測(cè)試不需要有后臺(tái)IO牍汹。所有JVM GC 停頓的時(shí)間序列數(shù)據(jù)如下圖所示铐维。沒(méi)有觀察到超過(guò)250ms的停頓。
情景1（不含后臺(tái)IO負(fù)載）中所有的JVM GC 停頓
情景2 （含有后臺(tái)IO負(fù)載）
當(dāng)后臺(tái)IO開始運(yùn)行后慎菲，在只有5分鐘的運(yùn)行時(shí)間內(nèi)嫁蛇，壓測(cè)程序就出現(xiàn)了一次超過(guò)3.6秒的STW停頓，以及3次超過(guò)0.5秒的停頓露该！
情景2（含有后臺(tái)IO負(fù)載）中所有的JVM GC 停頓
調(diào)查
為了了解是哪個(gè)系統(tǒng)調(diào)用引起了STW停頓睬棚，我們使用了strace來(lái)分析JVM實(shí)例產(chǎn)生的系統(tǒng)調(diào)用。
我們首先確認(rèn)了JVM將GC信息記錄到文件解幼，使用的是異步IO的方式抑党。我們又跟蹤了JVM從啟動(dòng)后產(chǎn)生的所有系統(tǒng)調(diào)用。GC日志文件在異步模式下打開撵摆，并且沒(méi)有觀察到fsync()調(diào)用底靠。
16:25:35.411993 open("gc.log", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3 <0.000073>
所捕獲的用于打開GC日志文件的JVM系統(tǒng)調(diào)用open()
但是，跟蹤結(jié)果顯示特铝，JVM發(fā)起的幾個(gè)異步系統(tǒng)調(diào)用write()出現(xiàn)了不同尋常的長(zhǎng)時(shí)間執(zhí)行情況苛骨。通過(guò)檢查系統(tǒng)調(diào)用和JVM停頓的時(shí)間戳篱瞎，我們發(fā)現(xiàn)它們恰好吻合。在下圖中痒芝，我們分別對(duì)比展示了兩分鐘內(nèi)系統(tǒng)調(diào)用和JVM停頓的時(shí)間序列俐筋。
時(shí)間序列對(duì)比（JVM STW停頓）
時(shí)間序列對(duì)比（系統(tǒng)調(diào)用write()）
我們集中注意來(lái)看，位于13:32:35秒時(shí)最長(zhǎng)達(dá)1.59秒的這次停頓严衬，相應(yīng)的GC日志和strace輸出顯示如下：
GC日志和strace輸出
我們來(lái)試著理解一下發(fā)生了什么澄者。
- 在35.04時(shí)（第2行），一次young GC開始了请琳，并且經(jīng)過(guò)0.12秒完成粱挡。
- 這次young GC完成于時(shí)間35.17，并且JVM試圖通過(guò)一次系統(tǒng)調(diào)用
write()（第4行）俄精，將young GC的統(tǒng)計(jì)信息輸出到gc日志文件中询筏。 - write()調(diào)用被阻塞了1.47秒，最后于時(shí)間36.64（第5行）完成竖慧，花費(fèi)了1.47秒的時(shí)間嫌套。
- 當(dāng)write()調(diào)用于時(shí)間36.64返回JVM時(shí)，JVM記錄下這次用時(shí)1.59秒的STW停頓（例如圾旨，0.12+0.47）（第3行）踱讨。
換句話說(shuō)，實(shí)際的STW停頓時(shí)間包含兩部分：（1） GC時(shí)間（例如砍的，young GC）和 （2）GC記錄日志的時(shí)間（例如痹筛， 調(diào)用write()的時(shí)間）。
這些數(shù)據(jù)說(shuō)明廓鞠，GC記錄日志的過(guò)程發(fā)生在JVM的STW停頓過(guò)程中帚稠，并且記錄日志所用的時(shí)間也屬于STW停頓時(shí)間的一部分。特別需要說(shuō)明床佳，整個(gè)應(yīng)用程序的停頓主要由兩部分組成：由于JVM GC行為造成的停頓翁锡，以及為了記錄JVM GC日志，系統(tǒng)調(diào)用write()被OS阻塞的時(shí)間夕土。下面這張圖展示了二者之間的關(guān)系馆衔。
在記錄GC日志過(guò)程中JVM和OS之間的交互
如果記錄GC日志的過(guò)程（例如write()調(diào)用）被OS阻塞，阻塞時(shí)間也會(huì)被計(jì)算到STW的停頓時(shí)間內(nèi)怨绣。新的問(wèn)題是角溃，為什么帶有緩存的寫入會(huì)被阻塞？在深入了解各種資料篮撑，包括操作系統(tǒng)內(nèi)核的源代碼之后减细，我們意識(shí)到帶有緩存的寫入可能被內(nèi)核代碼所阻塞。這里面有多重原因赢笨，包括：（1）“stable page write”和（2）“journal committing”未蝌。
Stable page write: JVM對(duì)GC日志文件的寫入驮吱，首先會(huì)使得相應(yīng)的文件緩存頁(yè)“變臟”。即使緩存頁(yè)稍后會(huì)通過(guò)OS的回寫機(jī)制被持久化到磁盤文件萧吠，但是在內(nèi)存中使緩存頁(yè)變臟的過(guò)程左冬，由于“stable page write”仍然會(huì)受到頁(yè)競(jìng)爭(zhēng)的影響。在“stable page write”下纸型，如果某頁(yè)正處于OS回寫過(guò)程中拇砰，那么對(duì)該頁(yè)的write()調(diào)用就不得不等待回寫完成。為了避免只有一部分新頁(yè)被持久化到磁盤上狰腌，內(nèi)核會(huì)鎖定該頁(yè)以確保數(shù)據(jù)一致性除破。
Journal committing: 對(duì)于帶有日志（journaling）的文件系統(tǒng)，在寫文件時(shí)都會(huì)生成相應(yīng)的journal日志琼腔。當(dāng)JVM向GC日志文件追加內(nèi)容時(shí)瑰枫，會(huì)產(chǎn)生新的塊，因此文件系統(tǒng)則需要先將journal日志數(shù)據(jù)提交到磁盤丹莲。在提交journal日志的過(guò)程中光坝，如果OS還有其他的IO行為，則提交可能需要等待圾笨。如果后臺(tái)的IO行為非常繁重教馆，那么等待時(shí)間可能會(huì)非常長(zhǎng)逊谋。注意擂达，EXT4文件系統(tǒng)有一個(gè)“delayed allocation”功能，可以將journal數(shù)據(jù)提交延遲到OS回寫后再進(jìn)行胶滋，從而降低等待時(shí)間板鬓。還要注意的是，將EXT4的數(shù)據(jù)模式從默認(rèn)的“ordered”改成“writeback”并不能解決這個(gè)問(wèn)題究恤，因?yàn)閖ournal數(shù)據(jù)需要在write-to-extend調(diào)用返回之前被持久化俭令。
后臺(tái)IO行為
從JVM垃圾回收的角度來(lái)看，通常的生產(chǎn)環(huán)境都無(wú)法避免后臺(tái)的IO行為部宿。這些IO行為有幾個(gè)來(lái)源：（1）OS活動(dòng)抄腔；（2）管理和監(jiān)控軟件；（3）其他共存的應(yīng)用程序理张；（4）同一個(gè)JVM實(shí)例的IO行為赫蛇。首先，OS包含許多機(jī)制（例如雾叭，”/proc“文件系統(tǒng)）會(huì)引起向底層磁盤寫入數(shù)據(jù)悟耘。其次，像CFEngine這樣的系統(tǒng)級(jí)軟件也會(huì)進(jìn)行磁盤IO操作织狐。第三暂幼，如果當(dāng)前節(jié)點(diǎn)上還存在其他共享磁盤的應(yīng)用程序筏勒，那么這些應(yīng)用程序都會(huì)爭(zhēng)搶IO。第四旺嬉，除了GC日志之外管行，JVM實(shí)例也可能以其他方式使用磁盤IO。
解決方案
由于當(dāng)前HotSpot JVM實(shí)現(xiàn)（包括其他實(shí)現(xiàn)）中鹰服，GC日志會(huì)被后臺(tái)的IO行為所阻塞病瞳，所以有一些解決方案可以避免寫GC日志文件的問(wèn)題。
首先悲酷，JVM實(shí)現(xiàn)完全可以解決掉這個(gè)問(wèn)題套菜。顯然，如果將寫GC日志的操作與可能會(huì)導(dǎo)致STW停頓的JVM GC處理過(guò)程分開设易，這個(gè)問(wèn)題自然就不存在了逗柴。例如，JVM可以將記錄GC日志的功能放到另一個(gè)線程中顿肺，獨(dú)立來(lái)處理日志文件的寫入戏溺，這樣就不會(huì)增加STW停頓的時(shí)間了。但是屠尊，這種采用其他線程來(lái)處理的方式旷祸，可能會(huì)導(dǎo)致在JVM崩潰時(shí)丟失最后的GC日志信息。最好的方式讼昆，可能是提供一個(gè)JVM選項(xiàng)托享，讓用戶來(lái)選擇適合的方式。
由于后臺(tái)IO造成的STW停頓時(shí)間浸赫，與IO的繁重程度有關(guān)闰围，所以我們可以采用多種方式來(lái)降低后臺(tái)IO的壓力。例如既峡，不要在同一節(jié)點(diǎn)上安裝其他IO密集型的應(yīng)用程序羡榴，減少其他類型的日志行為，提高日志回滾頻率等等运敢。
對(duì)于低延遲應(yīng)用程序（例如需要提供用戶在線互動(dòng)的程序）校仑，長(zhǎng)時(shí)間的STW停頓（例如>0.25秒）是不可忍受的。因此传惠，必須進(jìn)行有針對(duì)性的優(yōu)化迄沫。如果要避免因?yàn)镺S導(dǎo)致的長(zhǎng)時(shí)間STW停頓，首要措施就是要避免因?yàn)镺S的IO行為導(dǎo)致寫GC日志被阻塞涉枫。
一個(gè)解決辦法是將GC日志文件放到tmpfs上（例如邢滑，-Xloggc:/tmpfs/gc.log）。因?yàn)閠mpfs沒(méi)有磁盤文件備份，所以tmpfs文件不會(huì)導(dǎo)致磁盤行為困后，因此也不會(huì)被磁盤IO阻塞乐纸。但是，這種方法存在兩個(gè)問(wèn)題：（1）當(dāng)系統(tǒng)崩潰后摇予，GC日志文件將會(huì)丟失汽绢；（2）它需要消耗物理內(nèi)存。補(bǔ)救的方法是周期性的將日志文件備份到持久化存儲(chǔ)上侧戴，以減少丟失量宁昭。
另一個(gè)辦法是將GC日志文件放到SSD（固態(tài)硬盤，Solid-State Drives）上酗宋，它通常能提供更好的IO性能积仗。根據(jù)IO負(fù)載情況，可以選擇專門為GC日志提供一個(gè)SSD作為存儲(chǔ)蜕猫，或者與其他IO程序共用SSD寂曹。不過(guò)，這樣就需要將SSD的成本考慮在內(nèi)回右。
與使用SSD這樣高成本的方案相比隆圆，更經(jīng)濟(jì)的方式是將GC日志文件放在單獨(dú)一個(gè)HDD磁盤上。由于這塊磁盤上只有記錄GC日志的IO行為翔烁，所以這塊專有的HDD磁盤應(yīng)該可以滿足低停頓的JVM性能要求渺氧。實(shí)際上，我們之前演示的場(chǎng)景一就可以看做為這一方案蹬屹，因?yàn)樵谟涗汫C日志的磁盤上沒(méi)有任何其他的IO行為侣背。
將GC日志放到SSD和tmpfs的評(píng)估
我們采用了專有文件系統(tǒng)的解決方案，將GC日志文件分別放到SSD和tmpfs上哩治。然后我們按照?qǐng)鼍岸械暮笈_(tái)IO負(fù)載秃踩，運(yùn)行了相同的Java壓測(cè)程序衬鱼。
對(duì)于SSD和tmpfs二者而言业筏，我們觀察到了相似的結(jié)果阎肝，并且下圖展示了將GC日志放到SSD磁盤上的結(jié)果魁巩。我們注意到乒融，JVM停頓的性能幾乎可以與場(chǎng)景一相媲美褐捻，并且所有停頓都小于0.25秒豪嗽。二者的結(jié)果均表明后臺(tái)的IO負(fù)載沒(méi)有影響到應(yīng)用程序的性能旅掂。
將GC日志遷到SSD后的所有的JVM STW停頓
結(jié)論
有低延遲要求的Java應(yīng)用程序需要極短的JVM GC停頓张遭。但是瞬项，當(dāng)磁盤IO壓力很大時(shí)岁经，JVM可能被阻塞一段較長(zhǎng)的時(shí)間朋沮。
我們對(duì)該問(wèn)題進(jìn)行了調(diào)查，并且發(fā)現(xiàn)如下原因：
- JVM GC需要通過(guò)發(fā)起系統(tǒng)調(diào)用
write()缀壤，來(lái)記錄GC行為樊拓。 -
write()調(diào)用可以被后臺(tái)磁盤IO所阻塞纠亚。 - 記錄GC日志屬于JVM停頓的一部分，因此
write()調(diào)用的時(shí)間也會(huì)被計(jì)算在JVM STW的停頓時(shí)間內(nèi)筋夏。
我們提出了一系列解決該問(wèn)題的方案蒂胞。重要的是，我們的發(fā)現(xiàn)可以幫助JVM實(shí)現(xiàn)來(lái)改進(jìn)該問(wèn)題条篷。對(duì)于低延遲應(yīng)用程序來(lái)說(shuō)骗随，最簡(jiǎn)單有效的措施是將GC日志文件放到單獨(dú)的HDD或者高性能磁盤（例如SSD）上，來(lái)避免IO競(jìng)爭(zhēng)赴叹。
歡迎打賞（微信請(qǐng)點(diǎn)擊“閱讀原文”）鸿染，也請(qǐng)關(guān)注微信公眾賬號(hào)“重度恐高癥”，精彩技術(shù)文章就在這里乞巧。
