耗時幾個月，終於找到了JVM停頓十幾秒的原因

原創：打碼日記（微信公眾號ID：codelogs），歡迎分享，轉載請保留出處。

簡介

最近我們系統出現了一些奇怪的現象，系統每隔幾個星期會在大半夜重啟一次，分析過程花費了很長時間，令人印象深刻，故在此記錄一下。

第一次排查

由於重啟后，進程現場信息都丟失了，所以這個問題非常難以排查，像常規的jstack、jmap、arthas等都派不上用場，能用得上的只有機器監控數據與日志。

在看機器監控時，發現重啟時間點的CPU、磁盤io使用都會升高，但很快我們就確認了這個信息無任何幫助，因為jvm啟動會由於類加載、GIT編譯等導致CPU、磁盤io升高，所以這個升高是重啟本身導致的，並不是導致問題的原因。

然后就是分析業務日志、內核日志，經過一段時間分析，結論如下：

1. 在重啟的時間點，系統流量並沒有明顯上升。
2. 在dmesg日志中並沒有找到oom-killer的痕跡，雖然這經常是導致進程莫名重啟的原因。
3. 由於部署平台也可能會kill掉進程(當進程不響應健康檢查請求時)，我們也懷疑是它們的誤殺，但運維同學認為不可能誤殺。

問題沒有任何進一步的進展了，由於沒有任何進程現場，為了排查問題，我開發了一個腳本，主要邏輯就是監控CPU、內存使用率，達到一個閾值后自動收集jstack、jmap信息，腳本部署之后就沒繼續排查了。

第二次排查

部署了腳本之后，過了幾個小時，進程又重啟了，但這次不是在大半夜，而是白天，又開始了排查的過程...

在這次排查過程中，我突然發現之前漏掉了對gc日志的檢查，我趕緊打開gc日志看了起來，發現了下面這種輸出：

Heap after GC invocations=15036 (full 0):
 garbage-first heap   total 10485760K, used 1457203K [0x0000000540800000, 0x0000000540c05000, 0x00000007c0800000)
  region size 4096K, 9 young (36864K), 9 survivors (36864K)
 Metaspace       used 185408K, capacity 211096K, committed 214016K, reserved 1236992K
  class space    used 21493K, capacity 25808K, committed 26368K, reserved 1048576K
}
 [Times: user=0.15 sys=0.04, real=0.06 secs] 
2021-03-06T09:49:25.564+0800: 914773.820: Total time for which application threads were stopped: 0.0585911 seconds, Stopping threads took: 0.0001795 seconds
2021-03-06T09:49:25.564+0800: 914773.820: [GC concurrent-string-deduplication, 7304.0B->3080.0B(4224.0B), avg 52.0%, 0.0000975 secs]
2021-03-06T09:50:31.544+0800: 914839.800: Total time for which application threads were stopped: 18.9777012 seconds, Stopping threads took: 18.9721235 seconds

啥，這代表什么意思，jvm暫停了18秒？但看上面那次gc只花了0.06秒呀！

不知道application threads were stopped: 18.9777012 seconds這個日志的具體含義，只好去網上搜索了，結論如下：

1. 這行日志確實代表了jvm暫停了18秒，即常說的STW。
2. 之所以會有這行日志，是因為有-XX:+PrintGCApplicationStoppedTime -XX:+PrintGCDetails這兩個jvm參數。
3. 這個18秒並不是由gc造成的，在jvm中除了gc，還有safepoint機制會讓jvm進入STW，比如jstack、jmap等操作就會觸發safepoint機制，使得所有線程進入safepoint等待操作完成。
4. 一般來說，如果是gc造成的STW，會在上面有[Times: user=0.15 sys=0.04, real=0.06 secs]這樣一行，所以你看上面那個gc造成的STW實際是0.0585911秒，四舍五入成了0.06秒。

什么是safepoint機制

簡單來說，就是JVM在做某些特殊操作時，必須要所有線程都暫停起來，所以設計了safepoint這個機制，當JVM做這些特殊操作時(如Full GC、jstack、jmap等)，會讓所有線程都進入安全點阻塞住，待這些操作執行完成后，線程才可恢復運行。
並且，jvm會在如下位置埋下safepoint，這是線程有機會停下來的地方：

1. 方法調用返回處會埋safepoint
2. 非counted loop(非有界循環)，即while(true)死循環這種，每次循環回跳之前會埋safepoint
3. 有界循環，如循環變量是long類型，有safepoint，循環變量是int類型，需要添加-XX:+UseCountedLoopSafepoints才有safepoint

經過一段時間的排查與思考，確認了這次STW是我自己開發的腳本導致的！因為隨着jvm運行時間越來越長，老年代使用率會越來越高，但會在Full GC后降下來，而我的腳本直接檢測老年代占用大於90%就jmap，導致觸發了jvm的safepoint機制使所有線程需等待jmap完成，導致進程不響應請求，進而部署平台kill了進程。

其實腳本監控邏輯應該是在Full GC后，發現內存占用還是很高，才算內存異常case。

在了解到safepoint這個知識點后，在網上搜索了大量文章，主要提到了5組jvm參數，如下：

# 打開safepoint日志，日志會輸出到jvm進程的標准輸出里
-XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1  
# 當有線程進入Safepoint超過2000毫秒時，會認為進入Safepoint超時了，這時會打印哪些線程沒有進入Safepoint
-XX:+SafepointTimeout -XX:SafepointTimeoutDelay=2000  
# 沒有這個選項，JIT編譯器可能會優化掉for循環處的safepoint，那么直到循環結束線程才能進入safepoint，而加了這個參數后，每次for循環都能進入safepoint了，建議加上此選項
-XX:+UseCountedLoopSafepoints  
# 在高並發應用中，偏向鎖並不能帶來性能提升，反而會觸發很多沒必要的Safepoint，建議加上此選項關閉偏向鎖
-XX:-UseBiasedLocking
# 避免jvm定時進入safepoint，就如safepoint中的no vm operation操作就是jvm定時觸發的safepoint
-XX:+UnlockDiagnosticVMOptions -XX:GuaranteedSafepointInterval=0

注：默認情況下，jvm將safepoint日志加到標准輸出流里，由於我們使用的resin服務器，它有watchdog機制，導致safepoint日志寫到了watchdog進程的${RESIN_HOME}/log/jvm-app-0.log中。

並且我發現網上有很多關於-XX:+UseCountedLoopSafepoints與-XX:-UseBiasedLocking導致長時間STW的問題案例，我當時幾乎都覺得我加上這2個參數后，問題就解決了。

於是我並沒有進一步去優化監控腳本，而是下掉了它，直接加上了這些jvm參數。

safepoint日志格式

加入以上jvm參數后，立即查看safepoint日志，格式如下：

$ less jvm-app-0.log
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
24.692: ForceSafepoint                   [      77          0              1    ]      [     0     0     0     0     0    ]  0   
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
25.607: G1IncCollectionPause             [      77          0              0    ]      [     0     0     0     0   418    ]  0   
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
26.947: Deoptimize                       [      77          0              0    ]      [     0     0     0     0     1    ]  0   
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
27.136: ForceSafepoint                   [      77          0              1    ]      [     0     0     0     0     0    ]  0   
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
28.137: no vm operation                  [      77          0              1    ]      [     0     0     0     0     0    ]  0

其中：

• 第一列是當前打印日志時間點，它是相對於進程啟動后經過的秒數。
• 第二列是觸發safepoint機制的操作，比如G1IncCollectionPause，看名稱就知道是G1GC操作導致的暫停。
• 第三列是當前jvm線程情況
  total：STW發生時，當前jvm的線程數量
  initially_running ：STW發生時，仍在運行的線程數，這項是Spin階段的時間來源
  wait_to_block ： STW需要阻塞的線程數目，這項是block階段的時間來源
• 第四列是safepoint各階段的耗時
  Spin：因為jvm在決定進入全局safepoint的時候，有的線程在安全點上，而有的線程不在安全點上，這個階段是等待未在安全點上的線程進入安全點的時間。
  Block：即使進入safepoint，后進入safepoint的部分線程可能仍然是running狀態，這是等待它們阻塞起來花費的時間。
  Sync：等於Spin + Block + 其它活動耗時，gc的STW日志最后的Stopping threads took等於Spin + Block。
  Cleanup：這個階段是JVM做的一些內部的清理工作。
  vmop：實際safepoint操作花費的時間，如G1IncCollectionPause(GC暫停),Deoptimize(代碼反優化),RevokeBias(偏向鎖撤銷)，PrintThreads(jstack)，GC_HeapInspection(jmap -histo)，HeapDumper(jmap -dump)。

第三次排查

過了幾個星期后，問題又出現了，接下來就是檢查gc與safepoint日志了，一看日志發現，果然有很長時間的STW，且不是gc造成的，如下：

1. 首先查看gc日志，發現有超過16s的STW，並且不是gc造成的，如下：

# 發現有16s的STW
$ less gc-*.log
Heap after GC invocations=1 (full 0):
 garbage-first heap   total 10485760K, used 21971K [0x0000000540800000, 0x0000000540c05000, 0x00000007c0800000)
  region size 4096K, 6 young (24576K), 6 survivors (24576K)
 Metaspace       used 25664K, capacity 26034K, committed 26496K, reserved 1073152K
  class space    used 3506K, capacity 3651K, committed 3712K, reserved 1048576K
}
 [Times: user=0.13 sys=0.02, real=0.04 secs] 
2021-04-02T00:00:00.192+0800: 384896.192: Total time for which application threads were stopped: 0.0423070 seconds, Stopping threads took: 0.0000684 seconds
2021-04-02T00:00:00.193+0800: 384896.193: Total time for which application threads were stopped: 0.0006532 seconds, Stopping threads took: 0.0000582 seconds
2021-04-02T00:00:00.193+0800: 384896.193: Total time for which application threads were stopped: 0.0007572 seconds, Stopping threads took: 0.0000582 seconds
2021-04-02T00:00:00.194+0800: 384896.194: Total time for which application threads were stopped: 0.0006226 seconds, Stopping threads took: 0.0000665 seconds
2021-04-02T00:00:00.318+0800: 384896.318: Total time for which application threads were stopped: 0.1240032 seconds, Stopping threads took: 0.0000535 seconds
2021-04-02T00:00:00.442+0800: 384896.442: Total time for which application threads were stopped: 0.1240013 seconds, Stopping threads took: 0.0007532 seconds
2021-04-02T00:00:16.544+0800: 384912.544: Total time for which application threads were stopped: 16.1020012 seconds, Stopping threads took: 0.0000465 seconds
2021-04-02T13:04:48.545+0800: 384912.545: Total time for which application threads were stopped: 0.0007232 seconds, Stopping threads took: 0.0000462 seconds

2. 再查看safepoint日志，發現有16s的safepoint操作，觸發事件是HeapWalkOperation，如下：

# safepoint日志也發現16s的HeapWalkOperation操作
$ less jvm-app-0.log
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
384896.193: FindDeadlocks                    [      96          0              0    ]      [     0     0     0     0     0    ]  0
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
384896.193: ForceSafepoint                   [      98          0              0    ]      [     0     0     0     0     0    ]  0
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
384896.194: ThreadDump                       [      98          0              0    ]      [     0     0     0     0    124    ]  0
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
384896.318: ThreadDump                       [      98          0              0    ]      [     0     0     0     0    124    ]  0
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
384896.442: HeapWalkOperation                [      98          0              0    ]      [     0     0     0     0   16102    ]  0
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
384912.545: no vm operation                  [      98          0              0    ]      [     0     0     0     0     0    ]  0

3. 對比兩個日志的時間點，發現時間點是吻合的，如下：

# 查看進程啟動時間點
$ ps h -o lstart -C java|xargs -i date -d '{}' +'%F %T'
2021-03-28 13:05:03  # watchdog進程
2021-03-28 13:05:04  # 這個才是服務進程

# 由於safepoint記錄的時間點是相對於進程啟動的秒數，而HeapWalkOperation對應的秒數是384896.442
# 用date給時間加上秒數，減的話用 xx seconds ago
$ date -d '2021-03-28 13:05:04 384896 seconds'  +'%F %T'
2021-04-02 00:00:00

可以發現gc日志中STW是2021-04-02T00:00:16，而safepoint中是2021-04-02 00:00:00，剛好差了16s，時間差值剛好等於STW時間，這是由於gc日志記錄的是STW發生之后的時間，而safepoint日志記錄的是STW發生之前的時間，所以這兩個日志時間點是吻合的，16s的STW正是由HeapWalkOperation導致的。

從名稱看起來像是在執行堆內存遍歷操作，類似jmap那種，但我的腳本已經下掉了呀，不可能還有jmap操作呀，機器上除了我的resin服務器進程，也沒有其它的進程了呀！

到這里，已經找到了一部分原因，但不知道是怎么造成的，苦苦尋找根因中...

第N次排查

已經記不得是第幾次排查了，反正問題又出現了好幾次，但這次咱把根因給找到了，過程如下：

1. 還是如上面過程一樣，檢查gc日志、safepoint日志，如下：

# gc日志中發現14s的STW
$ less gc-*.log
2021-05-16T00:00:14.634+0800: 324412.634: Total time for which application threads were stopped: 14.1570012 seconds, Stopping threads took: 0.0000672 seconds

# safepoint日志中同樣有14s的HeapWalkOperation操作
$ less jvm-app-0.log
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
324398.477: HeapWalkOperation                [      98          0              0    ]      [     0     0     0     0   14157    ]  0

現象和之前一模一樣，現在的關鍵還是不知道HeapWalkOperation是由什么原因導致的。

2. 源於最近一直在學習Linux命令，並且正在總結grep的用法，我隨手在resin目錄遞歸的grep了一下heap這個詞，如下：

# -i 忽略大小寫搜索
# -r 遞歸的搜索，在當前目錄/子目錄/子子目錄的所有文件中搜索heap
# -n 打印出匹配行的行號
$ grep -irn heap

我竟意外發現，resin中有HeapDump相關的配置，好像是resin中的一些健康檢查的機制。

經過一翻resin官網的學習，確認了resin有各種健康檢查機制，比如，每個星期的0點，會生成一份pdf報告，這個報告的數據就來源於類似jstack、jmap這樣的操作，只是它是通過調用jdk的某些方法實現的。
resin健康檢查機制的介紹：http://www.caucho.com/resin-4.0/admin/health-checking.xtp

  <health:PdfReport>
    <path>${resin.root}/doc/admin/pdf-gen.php</path>
    <report>Summary</report>
    <period>7D</period>
    <snapshot/>
    <mail-to>${email}</mail-to>
    <mail-from>${email_from}</mail-from>
    <!-- <profile-time>60s</profile-time> -->

    <health:IfCron value="0 0 * * 0"/>
  </health:PdfReport>

此機制會在${RESIN_HOME}/log目錄下生成pdf報告，如下：

$ ls -l
-rw-r--r-- 1 work work 2539860 2021-05-02 00:00:26 app-0-Summary-20210502T0000.pdf
-rw-rw-r-- 1 work work 3383712 2021-05-09 00:00:11 app-0-Summary-20210509T0000.pdf
-rw-rw-r-- 1 work work 1814296 2021-05-16 00:00:16 app-0-Summary-20210516T0000.pdf

由於堆遍歷這樣的操作，耗時時間完全和當時jvm的內存占用情況有關，內存占用高遍歷時間長，占用低則遍歷時間短，因此有時暫停時間會觸發部署平台kill進程的時間閾值，有時又不會，所以我們的重啟現象也不是每周的0點，使得沒有注意到0點的這個時間規律。

於是我直接找到resin的health.xml，將健康檢查相關機制全關閉了，如下：

<health:ActionSequence>
    <health:IfHealthCritical time="2m"/>

    <health:FailSafeRestart timeout="10m"/>
    <health:DumpJmx/>
    <!-- <health:DumpThreads/> -->     <!-- 注釋掉這個 -->
    <health:ScoreboardReport/>
    <!-- <health:DumpHeap/> -->        <!-- 注釋掉這個 -->
    <!-- <health:DumpHeap hprof="true" hprof-path="${resin.logDirectory}/heap.hprof"/> -->   <!-- 注釋掉這個 -->
    <health:StartProfiler active-time="2m" wait="true"/> 
    <health:Restart/>
</health:ActionSequence>

<health:MemoryTenuredHealthCheck>
    <enabled>false</enabled>            <!-- 添加這個 -->
    <memory-free-min>1m</memory-free-min>
</health:MemoryTenuredHealthCheck>
  
<health:MemoryPermGenHealthCheck>
    <enabled>false</enabled>            <!-- 添加這個 -->
    <memory-free-min>1m</memory-free-min>
</health:MemoryPermGenHealthCheck>
  
<health:CpuHealthCheck>
    <enabled>false</enabled>           <!-- 添加這個 -->
    <warning-threshold>95</warning-threshold>
    <!--  <critical-threshold>99</critical-threshold> -->
</health:CpuHealthCheck>

<health:DumpThreads>
    <health:Or>
      <health:IfHealthWarning healthCheck="${cpuHealthCheck}" time="2m"/>
      <!-- <health:IfHealthEvent regexp="caucho.thread"/> -->  <!-- 注釋掉這個，這個event由<health:AnomalyAnalyzer>定義 -->
    </health:Or>
    <health:IfNotRecent time="15m"/>
</health:DumpThreads>

<health:JvmDeadlockHealthCheck>
    <enabled>false</enabled>            <!-- 添加這個 -->
<health:JvmDeadlockHealthCheck/>

<health:DumpJmx async="true">       <!-- 刪除這種節點 -->
    <health:OnStart/>
</health:DumpJmx>

<health:Snapshot>   <!-- 刪除這種節點 -->
    <health:OnAbnormalStop/>
</health:Snapshot>

<health:AnomalyAnalyzer>  <!-- 刪除這種節點 -->

<health:PdfReport>  <!-- 刪除這種節點 -->

這樣配置以后，過了2個月，再也沒出現重啟現象了，確認了問題已解決。

總結

這次問題排查有一定的思路，但最后排查出根因的契機，還是有點像撞大運似的，自己隨機grep了一把發現線索，但下次就不知道會不會碰到這種運氣了。

后面想了想，這種問題常規的排查思路還是要掛腳本，運行追蹤程序perf、bpftrace等，在jvm執行safepoint操作的入口函數加入探針probe，當發現safepoint操作時間超長時，打印出相關jvm原生調用棧與java調用棧即可，關於追蹤工具，之前有過這方面的介紹，感興趣可以看下：
Linux命令拾遺-動態追蹤工具
Linux命令拾遺-剖析工具

往期內容

字符編碼解惑
hex,base64,urlencode編碼方案對比
mysql的timestamp會存在時區問題？
真正理解可重復讀事務隔離級別
不容易自己琢磨出來的正則表達式用法