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

原文發表于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競爭。

總結

以上是生活随笔為你收集整理的java服务器gc停顿_如何避免后台IO高负载造成的长时间JVM GC停顿(转)的全部內容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網站內容還不錯，歡迎將生活随笔推薦給好友。