如何避免後臺IO高負載形成的長時間JVM GC停頓(轉)

時間 2019-12-16

原文原文鏈接

譯者著：其實本文的中心意思很是簡單，沒有耐心的讀者建議直接拉到最後看結論部分，有興趣的讀者能夠詳細閱讀一下。

原文發表於Linkedin Engineering，做者 Zhenyun Zhuang是Linkedin的一名Staff Software Engineer，聯合做者Cuong Tran是Linkedin的一名Sr. Staff Engineer。php

在咱們的生產環境中，咱們不斷髮現一些運行在JVM上的應用程序，偶爾會由於記錄JVM的GC日誌，而被後臺的IO操做（例如OS的頁緩存回寫）阻塞，出現長時間的STW（Stop-The-World）停頓。在這些STW停頓的過程當中，JVM會暫停全部的應用程序線程，此時應用程序會中止對用戶請求的響應，這對於要求低延遲的系統來講，所以所致使的高延遲是不可接受的。html

咱們的調查代表，致使這些停頓的緣由，是當JVM GC（垃圾回收）在寫GC日時，因爲write()系統調用所形成的。對於這些日誌的寫入操做，即便是採用異步寫模式（例如，帶緩存的IO或者非阻塞IO），仍然會被OS的頁緩存回寫等機制阻塞至關長的一段時間。linux

咱們將討論解決這個問題的各類方式。對於要求低延遲的Java應用程序來講，咱們建議將Java日誌文件移動到一個單獨的、或者高性能的磁盤驅動上（例如SSD，tmpfs）。git

生產環境中的問題

當JVM管理的Java堆空間進行垃圾回收後，JVM可能會停頓，並對應用程序形成STW停頓。根據在啓動Java實例時指定的JVM選項，GC日誌文件會記錄不一樣類型的GC和JVM行爲。github

雖然某些由於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停頓bash

另外一個例子，下面的GC日誌顯示了另外一次11.45秒的STW停頓。此次使用的垃圾回收器是CMS（Concurrent Mark Sweep (譯者注：原文中筆誤寫成了Concurrent Mode Sweep，已聯繫原做者修改)）。其中「user」/「sys」的時間幾乎能夠忽略，可是「real」表示的GC時間卻超過了11秒。經過最後一行，咱們能夠肯定應用程序發生了11.45秒的停頓。app

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

在實驗環境中重現問題

對於這個致使沒法解釋的長時間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行爲。