譯者著:其實本文的中心意思非常簡單,沒有耐心的讀者建議直接拉到最后看結論部分,有興趣的讀者可以詳細閱讀一下。
原文發表於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