一次高IO下的GC分析之旅

起因：收到GC STW報警

【監控系統】Total time for which application threads were stopped: 67.7651070 seconds, Stopping threads took: 0.0000240 seconds

快速分析原因

此處不分析具體GC日誌，主要分析方法:

• 從線上拷貝日誌到本地

• 打包成gc.zip格式

• 上傳到gceasy.io

• image

找到原因

找到是因為缺IO或內存資源導致高IO，並不是GC本身過程耗時太多(上一步GC的報告中獲得)：

通過監控系統，找到當時機器IO飆升(公司內部監控機器的平臺，zabbix實時收集機器的一些狀態)：

深層次原因

整個應用程序的停頓主要由兩部分組成：由於JVM GC行為造成的停頓(T1->T2)，以及為了記錄JVM GC日誌(T3->T4)，系統調用write()被OS阻塞的時間。下面這張圖展示了二者之間的關系。

解決方案

首先，JVM實現完全可以解決掉這個問題。顯然，如果將寫GC日誌的操作與可能會導致STW停頓的JVM GC處理過程分開，這個問題自然就不存在了。例如，JVM可以將記錄GC日誌的功能放到另一個線程中，獨立來處理日誌文件的寫入，這樣就不會增加STW停頓的時間了。但是，這種采用其他線程來處理的方式，可能會導致在JVM崩潰時丟失最後的GC日誌信息。最好的方式，可能是提供一個JVM選項，讓用戶來選擇適合的方式,但這個方法基本沒辦法我們自己來處理。

我們最後的解決辦法是將GC日誌文件放到其他低IO磁盤上，把gc日誌放到圖中的/data2,很明顯從iostat來看它的磁盤IO壓力很小。

一次高IO下的GC分析之旅