譯者著：其實(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ū)拥倪壿?、也無(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完成的工作總量（例如，回收的堆大?。┮矡o(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)題，我們開(kāi)始嘗試在實(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開(kāi)始運(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日志文件在異步模式下打開(kāi)，并且沒(méi)有觀察到fsync()調(diào)用。
16:25:35.411993 open("gc.log", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3 <0.000073>
所捕獲的用于打開(kāi)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開(kāi)始了，并且經(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ò)程分開(kāi)，這個(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ù)文章就在這里。
