譯者著：其實本文的中心意思非常簡單，沒有耐心的讀者建議直接拉到最后看結論部分，有興趣的讀者可以詳細閱讀一下。
原文發表於Linkedin Engineering，作者 Zhenyun Zhuang是Linkedin的一名Staff Software Engineer，聯合作者Cuong Tran是Linkedin的一名Sr. Staff Engineer。
在我們的生產環境中，我們不斷發現一些運行在JVM上的應用程序，偶爾會因為記錄JVM的GC日志，而被后台的IO操作（例如OS的頁緩存回寫）阻塞，出現長時間的STW（Stop-The-World）停頓。在這些STW停頓的過程中，JVM會暫停所有的應用程序線程，此時應用程序會停止對用戶請求的響應，這對於要求低延遲的系統來說，因此所導致的高延遲是不可接受的。
我們的調查表明，導致這些停頓的原因，是當JVM GC（垃圾回收）在寫GC日時，由於write()系統調用所造成的。對於這些日志的寫入操作，即使是采用異步寫模式（例如，帶緩存的IO或者非阻塞IO），仍然會被OS的頁緩存回寫等機制阻塞相當長的一段時間。
我們將討論解決這個問題的各種方式。對於要求低延遲的Java應用程序來說，我們建議將Java日志文件移動到一個單獨的、或者高性能的磁盤驅動上（例如SSD，tmpfs）。
生產環境中的問題
當JVM管理的Java堆空間進行垃圾回收后，JVM可能會停頓，並對應用程序造成STW停頓。根據在啟動Java實例時指定的JVM選項，GC日志文件會記錄不同類型的GC和JVM行為。
雖然某些因為GC導致的STW停頓（掃描/標記/壓縮堆對象）已經被大家熟知，但是我們發現后台IO負載也會造成長時間的STW停頓。在我們的生產環境中曾經出現過，一些關鍵的Java應用程序發生許多無法解釋的長時間STW停頓（> 5秒） 。這些停頓既不能從應用程序層的邏輯、也無法從JVM GC行為的角度加以解釋。如下所示，我們展示了一個超過4秒的長時間STW停頓，以及一些GC信息。當時我們選擇的垃圾回收器是G1。在一個只有8GB堆內存和使用並行Young Garbage Collection的G1環境下，垃圾回收通常不需要1秒即可完成，並且GC日志的影響也微乎其微。但是應用程序線程卻停頓了超過4秒。所有GC完成的工作總量（例如，回收的堆大小）也無法解釋這個長達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收集器時一次4.17秒的GC STW停頓
另一個例子，下面的GC日志顯示了另一次11.45秒的STW停頓。這次使用的垃圾回收器是CMS（Concurrent Mark Sweep (譯者注：原文中筆誤寫成了Concurrent Mode Sweep，已聯系原作者修改)）。其中“user”/“sys”的時間幾乎可以忽略，但是“real”表示的GC時間卻超過了11秒。通過最后一行，我們可以確定應用程序發生了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收集器時一次11.45秒的GC STW停頓
由於應用程序要求非常低的延遲，所以我們花費了相當多的精力來調查這個問題。最后，我們成功重現了這個問題，發現了根本原因，以及相應的解決方案。
在實驗環境中重現問題
對於這個導致無法解釋的長時間JVM停頓的問題，我們開始嘗試在實驗環境中重現它。為了使該過程能夠得到更好的控制並重復重現，我們設計了一個簡單的壓測程序，來代替復雜的生產環境應用程序。
我們將在兩個場景下運行這個壓測程序：含有后台IO行為以及不含有后台IO行為。不含有后台IO的場景我們稱之為“基准線（baseline）”，而含有后台IO的場景用來重現問題。
Java壓測程序
我們這個Java壓測程序只是不斷地生成10KB的對象，並放到一個隊列中。當對象數量達到100000時，會從隊列中刪除一半的對象。因此堆中存放的對象最大數量就是100000個，大概會占用1GB的空間。這個過程會持續一段固定的時間（例如5分鍾）。
這個程序的源代碼和后台IO的生成腳本，都位於https://github.com/zhenyun/JavaGCworkload。我們考慮的主要性能指標是長時間JVM GC停頓的數量。
后台IO
后台IO我們通過一個bash腳本，不斷地復制大文件來模擬。后台程序會生成150MB/s的寫入負載，可以使一個普通磁盤的IO變得足夠繁忙。為了更好理解生成的IO負載的壓力大小，我們使用“sar -d -p 2”來收集await（磁盤處理IO請求的平均時間（以毫秒計）），tps（每秒發往物理設備的傳輸總數）和wr_sec-per-s（寫入設備的扇區數）。它們分別的平均數值為：await=421 ms, tps=305, wr_sec-per-s=302K。
系統准備
情景1 （不含后台IO負載）
運行基准線測試不需要有后台IO。所有JVM GC 停頓的時間序列數據如下圖所示。沒有觀察到超過250ms的停頓。
情景1（不含后台IO負載）中所有的JVM GC 停頓
情景2 （含有后台IO負載）
當后台IO開始運行后，在只有5分鍾的運行時間內，壓測程序就出現了一次超過3.6秒的STW停頓，以及3次超過0.5秒的停頓！
情景2（含有后台IO負載）中所有的JVM GC 停頓
調查
為了了解是哪個系統調用引起了STW停頓，我們使用了strace來分析JVM實例產生的系統調用。
我們首先確認了JVM將GC信息記錄到文件，使用的是異步IO的方式。我們又跟蹤了JVM從啟動后產生的所有系統調用。GC日志文件在異步模式下打開，並且沒有觀察到fsync()調用。
16:25:35.411993 open("gc.log", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3 <0.000073>所捕獲的用於打開GC日志文件的JVM系統調用open()
但是，跟蹤結果顯示，JVM發起的幾個異步系統調用write()出現了不同尋常的長時間執行情況。通過檢查系統調用和JVM停頓的時間戳，我們發現它們恰好吻合。在下圖中，我們分別對比展示了兩分鍾內系統調用和JVM停頓的時間序列。
時間序列對比（JVM STW停頓）
時間序列對比（系統調用write()）
我們集中注意來看，位於13:32:35秒時最長達1.59秒的這次停頓，相應的GC日志和strace輸出顯示如下：
GC日志和strace輸出
我們來試着理解一下發生了什么。
- 在35.04時（第2行），一次young GC開始了，並且經過0.12秒完成。
- 這次young GC完成於時間35.17，並且JVM試圖通過一次系統調用 write()（第4行），將young GC的統計信息輸出到gc日志文件中。
- write()調用被阻塞了1.47秒，最后於時間36.64（第5行）完成，花費了1.47秒的時間。
- 當write()調用於時間36.64返回JVM時，JVM記錄下這次用時1.59秒的STW停頓（例如，0.12+0.47）（第3行）。
換句話說，實際的STW停頓時間包含兩部分：（1） GC時間（例如，young GC）和 （2）GC記錄日志的時間（例如， 調用write()的時間）。
這些數據說明，GC記錄日志的過程發生在JVM的STW停頓過程中，並且記錄日志所用的時間也屬於STW停頓時間的一部分。特別需要說明，整個應用程序的停頓主要由兩部分組成：由於JVM GC行為造成的停頓，以及為了記錄JVM GC日志，系統調用write()被OS阻塞的時間。下面這張圖展示了二者之間的關系。
在記錄GC日志過程中JVM和OS之間的交互
如果記錄GC日志的過程（例如write()調用）被OS阻塞，阻塞時間也會被計算到STW的停頓時間內。新的問題是，為什么帶有緩存的寫入會被阻塞？在深入了解各種資料，包括操作系統內核的源代碼之后，我們意識到帶有緩存的寫入可能被內核代碼所阻塞。這里面有多重原因，包括：（1）“stable page write”和（2）“journal committing”。
Stable page write: JVM對GC日志文件的寫入，首先會使得相應的文件緩存頁“變臟”。即使緩存頁稍后會通過OS的回寫機制被持久化到磁盤文件，但是在內存中使緩存頁變臟的過程，由於“stable page write”仍然會受到頁競爭的影響。在“stable page write”下，如果某頁正處於OS回寫過程中，那么對該頁的write()調用就不得不等待回寫完成。為了避免只有一部分新頁被持久化到磁盤上，內核會鎖定該頁以確保數據一致性。
Journal committing: 對於帶有日志（journaling）的文件系統，在寫文件時都會生成相應的journal日志。當JVM向GC日志文件追加內容時，會產生新的塊，因此文件系統則需要先將journal日志數據提交到磁盤。在提交journal日志的過程中，如果OS還有其他的IO行為，則提交可能需要等待。如果后台的IO行為非常繁重，那么等待時間可能會非常長。注意，EXT4文件系統有一個“delayed allocation”功能，可以將journal數據提交延遲到OS回寫后再進行，從而降低等待時間。還要注意的是，將EXT4的數據模式從默認的“ordered”改成“writeback”並不能解決這個問題，因為journal數據需要在write-to-extend調用返回之前被持久化。
后台IO行為
從JVM垃圾回收的角度來看，通常的生產環境都無法避免后台的IO行為。這些IO行為有幾個來源：（1）OS活動；（2）管理和監控軟件；（3）其他共存的應用程序；（4）同一個JVM實例的IO行為。首先，OS包含許多機制（例如，”/proc“文件系統）會引起向底層磁盤寫入數據。其次，像CFEngine這樣的系統級軟件也會進行磁盤IO操作。第三，如果當前節點上還存在其他共享磁盤的應用程序，那么這些應用程序都會爭搶IO。第四，除了GC日志之外，JVM實例也可能以其他方式使用磁盤IO。
解決方案
由於當前HotSpot JVM實現（包括其他實現）中，GC日志會被后台的IO行為所阻塞，所以有一些解決方案可以避免寫GC日志文件的問題。
首先，JVM實現完全可以解決掉這個問題。顯然，如果將寫GC日志的操作與可能會導致STW停頓的JVM GC處理過程分開，這個問題自然就不存在了。例如，JVM可以將記錄GC日志的功能放到另一個線程中，獨立來處理日志文件的寫入，這樣就不會增加STW停頓的時間了。但是，這種采用其他線程來處理的方式，可能會導致在JVM崩潰時丟失最后的GC日志信息。最好的方式，可能是提供一個JVM選項，讓用戶來選擇適合的方式。
由於后台IO造成的STW停頓時間，與IO的繁重程度有關，所以我們可以采用多種方式來降低后台IO的壓力。例如，不要在同一節點上安裝其他IO密集型的應用程序，減少其他類型的日志行為，提高日志回滾頻率等等。
對於低延遲應用程序（例如需要提供用戶在線互動的程序），長時間的STW停頓（例如>0.25秒）是不可忍受的。因此，必須進行有針對性的優化。如果要避免因為OS導致的長時間STW停頓，首要措施就是要避免因為OS的IO行為導致寫GC日志被阻塞。
一個解決辦法是將GC日志文件放到tmpfs上（例如，-Xloggc:/tmpfs/gc.log）。因為tmpfs沒有磁盤文件備份，所以tmpfs文件不會導致磁盤行為，因此也不會被磁盤IO阻塞。但是，這種方法存在兩個問題：（1）當系統崩潰后，GC日志文件將會丟失；（2）它需要消耗物理內存。補救的方法是周期性的將日志文件備份到持久化存儲上，以減少丟失量。
另一個辦法是將GC日志文件放到SSD（固態硬盤，Solid-State Drives）上，它通常能提供更好的IO性能。根據IO負載情況，可以選擇專門為GC日志提供一個SSD作為存儲，或者與其他IO程序共用SSD。不過，這樣就需要將SSD的成本考慮在內。
與使用SSD這樣高成本的方案相比，更經濟的方式是將GC日志文件放在單獨一個HDD磁盤上。由於這塊磁盤上只有記錄GC日志的IO行為，所以這塊專有的HDD磁盤應該可以滿足低停頓的JVM性能要求。實際上，我們之前演示的場景一就可以看做為這一方案，因為在記錄GC日志的磁盤上沒有任何其他的IO行為。
將GC日志放到SSD和tmpfs的評估
我們采用了專有文件系統的解決方案，將GC日志文件分別放到SSD和tmpfs上。然后我們按照場景二中的后台IO負載，運行了相同的Java壓測程序。
對於SSD和tmpfs二者而言，我們觀察到了相似的結果，並且下圖展示了將GC日志放到SSD磁盤上的結果。我們注意到，JVM停頓的性能幾乎可以與場景一相媲美，並且所有停頓都小於0.25秒。二者的結果均表明后台的IO負載沒有影響到應用程序的性能。
將GC日志遷到SSD后的所有的JVM STW停頓
結論
有低延遲要求的Java應用程序需要極短的JVM GC停頓。但是，當磁盤IO壓力很大時，JVM可能被阻塞一段較長的時間。
我們對該問題進行了調查，並且發現如下原因：
- JVM GC需要通過發起系統調用write()，來記錄GC行為。
- write()調用可以被后台磁盤IO所阻塞。
- 記錄GC日志屬於JVM停頓的一部分，因此write()調用的時間也會被計算在JVM STW的停頓時間內。
我們提出了一系列解決該問題的方案。重要的是，我們的發現可以幫助JVM實現來改進該問題。對於低延遲應用程序來說，最簡單有效的措施是將GC日志文件放到單獨的HDD或者高性能磁盤（例如SSD）上，來避免IO競爭。
原文地址：http://www.itnose.net/detail/6455877.html