介面偶爾超時，竟又是JVM停頓的鍋！

扣釘日記發表於2022-06-19
JVM

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

簡介

繼上次我們JVM停頓十幾秒的問題解決後，我們系統終於穩定了，再也不會無故重啟了！
這是之前的文章：耗時幾個月，終於找到了JVM停頓十幾秒的原因

但有點奇怪的是，每隔一段時間，我們服務介面就會有一小波499超時，經過檢視gc日誌，又發現JVM停頓了好幾秒！

檢視safepoint日誌

有了上次JVM停頓排查經驗後，我馬上就檢查了gc日誌與safepoint日誌，發現如下日誌：

$ cat gc-*.log | awk '/application threads were stopped/ && $(NF-6)>1'|tail
2022-05-08T16:40:53.886+0800: 78328.993: Total time for which application threads were stopped: 9.4917471 seconds, Stopping threads took: 9.3473059 seconds
2022-05-08T17:40:32.574+0800: 81907.681: Total time for which application threads were stopped: 3.9786219 seconds, Stopping threads took: 3.9038683 seconds
2022-05-08T17:41:00.063+0800: 81935.170: Total time for which application threads were stopped: 1.2607608 seconds, Stopping threads took: 1.1258499 seconds

$ cat safepoint.log | awk '/vmop/{title=$0;getline;if($(NF-2)+$(NF-4)>1000){print title;print $0}}'
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
78319.500: G1IncCollectionPause             [     428          0              2    ]      [     0  9347  9347     7   137    ]  0
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
81903.703: G1IncCollectionPause             [     428          0              4    ]      [     0  3903  3903    14    60    ]  0
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
81933.906: G1IncCollectionPause             [     442          0              1    ]      [     0  1125  1125     8   126    ]  0

從日誌上可以看到，JVM停頓也是由safepoint導致的，而safepoint耗時主要在block階段！

通過新增JVM引數-XX:+SafepointTimeout -XX:SafepointTimeoutDelay=1000後，可列印出哪些執行緒超過1000ms沒有到達safepoint，如下：
image_2022-06-11_20220611122458
可以看到都是一些http或grpc的worker執行緒沒走到safepoint，但為啥沒到達safepoint，看不出關鍵，只好又去網上搜尋了。

深入safepoint機制

  • safepoint機制：
    JVM在做某些特殊操作時(如gc、jmap等)，需要看到一致的記憶體狀態，而執行緒執行過程中會一直修改記憶體，所以JVM做這些特殊操作前，需要等待這些執行緒停下來，而停下來的機制就是safepoint。

在上面的safepoint日誌中，spin與block都是等待執行緒進入safepoint的耗時，而vmop就是需要在安全點執行的JVM操作耗時，遺憾的是，網上講safepoint的文章雖多，但基本沒有將block階段與spin階段區別講清楚的！

沒辦法，只能去看看JVM內部safepoint的實現程式碼了，在閱讀了safepoint.cpp後，對spin與block的區別也大致有點理解了，如下：

  1. jvm中其實執行緒狀態主要有3種thread_in_Java、thread_in_vm、thread_in_native。
  2. 執行緒執行到jvm管控以外的程式碼時(如核心程式碼)，執行緒狀態會變為thread_in_native，jvm會認為它已經在安全區域(Safe Region)，故不需要等待其到達safepoint，當它從thread_in_native狀態返回時，會自行掛起。
  3. 執行緒在執行java程式碼時，執行緒狀態是thread_in_Java，這種執行緒jvm需要等待它執行到safepoint後，將其掛起或自行掛起。
  4. 執行緒在執行jvm內部程式碼時，執行緒狀態是thread_in_vm，比如執行緒執行System.arraycopy，由於jvm內部並沒有放置safepoint，jvm必須等待其轉換到thread_in_native或thread_in_Java才能將其掛起或自行掛起。

而spin階段實際在做兩件事情，一是將thread_in_native狀態的執行緒刨除掉，這並不會太耗時，二是輪詢各執行緒狀態，等待thread_in_Java狀態的執行緒變為其它狀態(如走到了safepoint)，這也是為什麼counted loop這種程式碼會導致spin階段耗時高，因為它是thread_in_Java狀態的。

而block階段實際就是在等待thread_in_vm狀態的執行緒走到safepoint，與spin不同的是，safepoint執行緒將自己掛起，以等待最後一個thread_in_vm執行緒到達safepoint後將其喚醒。

如果看完我的描述，還是無法理解，強烈建議大家自己去閱讀下safepoint原始碼，要看懂大概脈絡還是不難的，而網上文章用來了解一些基礎知識即可，不必費力看太多。
safepoint原始碼：http://hg.openjdk.java.net/jdk8u/jdk8u/hotspot/file/818b1963f7a2/src/share/vm/runtime/safepoint.cpp
主要方法：SafepointSynchronize::begin, SafepointSynchronize::block,SafepointSynchronize::end

回到之前遇到的問題，我們是block階段耗時長，這是在等待thread_in_vm狀態的執行緒到達safepoint，而執行緒處於thread_in_vm狀態則說明執行緒在執行JVM內部程式碼。

難道我們什麼程式碼用法，導致執行緒在jvm內部執行耗時過長？特別是在jvm社群找到一個提議，即建議在System.arraycopy中新增safepoint，讓我也有點懷疑它了，但如何證明呢？
提議連結：https://bugs.openjdk.org/browse/JDK-8233300。

async-profiler分析safepoint

經過一段時間瞭解，發現目前分析safepoint主流工具如下：

  1. JFR：由oracle提供，在jdk11才完全可用，由於我們是jdk8，故放棄之。
  2. async-profiler：一款開源的JVM分析工具，提供了分析safepoint的選項，選它！

async-profiler提供了--ttsp的選項，用來分析safepoint事件，如下：

# 下載async-profiler
$ wget https://github.com/jvm-profiling-tools/async-profiler/releases/download/v2.8/async-profiler-2.8-linux-x64.tar.gz && tar xvf async* && cd async*

# 啟動async-profiler採集safepoint時的執行緒棧
$ ./profiler.sh start -e wall -t -o collapsed -f /tmp/tts.collased --ttsp jps

# 發現safepoint問題產生後，停止採集並匯出執行緒棧
$ ./profiler.sh stop  -e wall -t -o collapsed -f /tmp/tts.collased --ttsp jps

# 執行緒棧轉換為火焰圖工具
$ wget https://github.com/jvm-profiling-tools/async-profiler/releases/download/v2.8/converter.jar
$ java -cp converter.jar FlameGraph /tmp/tts.collapsed tts.html

最開始，抓到的火焰圖是這樣的，如下：
image_2022-06-11_20220611140928
由於我使用的是-e wall選項，這會把等待狀態的執行緒棧也抓取下來，而safepoint發生時，大多數執行緒都會等待，所以火焰圖中包含了太多無效資訊。

於是，我調整為使用--all-user選項，這會只抓取在CPU上跑著的執行緒棧，同時將--ttsp調整為--begin SafepointSynchronize::print_safepoint_timeout --end RuntimeService::record_safepoint_synchronized，以使得async-profiler僅在發生超時safepoint時才採集執行緒棧，因為safepoint超時的時候會呼叫SafepointSynchronize::print_safepoint_timeout方法列印上面介紹過的超時未到safepoint執行緒的日誌。

調整後，抓到的火焰圖是這樣的，如下：
image_2022-06-11_20220611142141
發現沒有到達safepoint的執行緒在執行getLoadAverage方法，這是java整合的prometheus監控元件，用來獲取機器負載的，這能有什麼問題？

我又發現，最後一個到達safepoint的執行緒會呼叫Monitor::notify_all喚醒safepoint協調執行緒，那使用-e Monitor::notify_all抓取的執行緒棧會更加準確，如下：
image_2022-06-11_20220611143152
如上，最後一個到達safepoint的執行緒，確實就在執行getLoadAverage方法，可這個方法能有什麼問題呢？我用strace看了一下，這個方法也就是從/proc/loadavg偽檔案中讀取負載資訊而已。
image_2022-06-11_20220611143404

柳暗花明

問題一直沒有排查出來，直到有一天，我突然發現，當一臺容器上的jvm出現safepoint超時問題後，會不固定的每隔幾小時出現一次，而同時間裡，不出現問題的容器則穩得一批！

很顯然，這個問題大概率和底層宿主機有關，我懷疑是部署在同一宿主機上的其它容器搶佔了cpu導致，但在我詢問運維宿主機情況時，運維一直說宿主機正常，也不知道他們是否認真看了！

又過了很久，有一次和隔壁組同事聊天，發現他們也遇到了超時問題，說是運維為了降機器成本，在宿主機上部署的容器越來越多！

再次出現問題後，我直接找運維要了宿主機的監控，我要自己確認，如下：
image_2022-06-11_20220611144808
可以發現宿主機負載在11點到12點之間，多次飆升到100以上，而我們JVM發生暫停的時間與之基本吻合。

至此，問題原因已經找到，執行緒到不了safepoint，是因為它得不到CPU啊，和thread_in_vm狀態無關，和getLoadAverage也無關，他們只是湊巧或執行頻率較高而已，得不到CPU資源時，執行緒能停在任何位置上！

可是我有一個想法，如果運維死活說宿主機沒有問題，不給監控，那在容器中的我們，是否能有證據證明問題在宿主機呢？

於是，我又嘗試在容器內找證據了！

排程延遲與記憶體不足

在Linux中可以無形拖慢執行緒執行速度的地方，主要有2點：

  1. 排程延遲：一瞬間有大量執行緒需要執行，導致執行緒在CPU佇列上等待時間過長。
  2. direct reclaim：分配記憶體時直接回收記憶體，一般情況下，Linux通過kswapd非同步回收記憶體，但當kswapd回收來不及時，會在分配時直接回收，但如果回收過程涉及page swap out、dirty page writeback時，會阻塞當前執行緒。

direct reclaim可以通過cat /proc/vmstat|grep -E "pageoutrun|allocstall"來測量，其中allocstall就是direct reclaim發生的次數。
而執行緒排程延遲可以通過觀測/proc/<pid>/task/<tid>/schedstat來測量，如下：

$ cat /proc/1/task/1/schedstat 
55363216 1157776 75

解釋如下：

  • 第一列：執行緒在CPU上執行的時間，單位納秒(ns)
  • 第二列：執行緒在CPU執行佇列上等待的時間，單位納秒(ns)
  • 第三列：執行緒的上下文切換次數。

而由於我需要分析整個程式，上述資訊是單個執行緒的，於是我寫了一個指令碼，彙總了各個執行緒的排程資料，以採集程式排程延遲資訊，執行效果如下：

$ python -u <(curl -sS https://gitee.com/fmer/shell/raw/master/diagnosis/pidsched.py) `pgrep -n java`
2022-06-11T15:13:47  pid:1 total:1016.941ms idle:0.000ms    oncpu:( 1003.000ms max:51.000ms   cs:105  tid:23004  ) sched_delay:( 120.000ms  max:18.000ms   cs:36   tid:217    )
2022-06-11T15:13:48  pid:1 total:1017.327ms idle:415.327ms  oncpu:( 596.000ms  max:54.000ms   cs:89   tid:215    ) sched_delay:( 6.000ms    max:0.000ms    cs:255  tid:153    )
2022-06-11T15:13:49  pid:1 total:1017.054ms idle:223.054ms  oncpu:( 786.000ms  max:46.000ms   cs:117  tid:14917  ) sched_delay:( 8.000ms    max:0.000ms    cs:160  tid:63     )
2022-06-11T15:13:50  pid:1 total:1016.791ms idle:232.791ms  oncpu:( 767.000ms  max:75.000ms   cs:120  tid:9290   ) sched_delay:( 17.000ms   max:5.000ms    cs:290  tid:153    )

可以發現，正常情況下，排程延遲在10ms以下。

等到再次發生超時safepoint問題時，我檢查了相關日誌，如下：
image_2022-06-11_20220611151547
image_2022-06-11_20220611151613
我發現，在問題發生時，oncpu與sched_delay都是0，即執行緒即不在CPU上，也不在CPU佇列上，也就是說執行緒根本沒有被排程！它要麼在睡眠，要麼被限制排程！

cgroup機制

聯想到我們JVM是在容器中執行，而容器會通過cgroup機制限制程式的CPU使用量，經過一番瞭解，我發現在容器中，可以通過/sys/fs/cgroup/cpu,cpuacct/cpu.stat來了解程式被限制的情況，如下：

# cgroup週期的時間長度，一個週期是100ms
$ cat /sys/fs/cgroup/cpu,cpuacct/cpu.cfs_period_us 
100000

# 容器分配的時間配額，由於我們是4核容器，所以這裡是400ms
$ cat /sys/fs/cgroup/cpu,cpuacct/cpu.cfs_quota_us 
400000

$ cat /sys/fs/cgroup/cpu,cpuacct/cpu.stat
nr_periods 3216521
nr_throttled 1131
throttled_time 166214531184

cpu.stat解釋如下：

  • nr_periods：經歷的cgroup週期數
  • nr_throttled：容器發生排程限制的次數
  • throttled_time：容器被限制排程的時間，單位納秒(ns)

於是，我寫了一個小指令碼來採集這個資料，如下：

$ nohup bash -c 'while sleep 1;do echo `date +%FT%T` `cat /sys/fs/cgroup/cpu,cpuacct/cpu.stat`;done' cpustat > cpustat.log &

再等到safepoint超時問題發生時，gc日誌如下：

$ ps h -o pid --sort=-pmem -C java|head -n1|xargs -i ls -l /proc/{}/fd|awk '/gc-.*.log/{print $NF}'|xargs cat|awk '/application threads were stopped/ && $(NF-6)>1'|tail
2022-06-10T14:00:45.334+0800: 192736.429: Total time for which application threads were stopped: 1.1018709 seconds, Stopping threads took: 1.0070313 seconds
2022-06-10T14:11:12.449+0800: 193363.544: Total time for which application threads were stopped: 1.0257833 seconds, Stopping threads took: 0.9586368 seconds

cpustat.log如下：

cat cpustat.log |awk '{if(!pre)pre=$NF;delta=($NF-pre)/1000000;print delta,$0;pre=$NF}'|less

image_2022-06-11_20220611153904
image_2022-06-11_20220611153914
可以發現，在JVM停頓發生的時間點，容器被限制排程多次，總共限制的時間超3000ms！

在找到問題後，我通過cgroup與jvm stw關鍵字在google上搜尋，發現在k8s中，container_cpu_cfs_throttled_seconds_total指標也代表了容器CPU被限制的時間，於是我立馬將運維的監控皮膚改了改，如下：
image_2022-06-11_20220611154504
可見時間點也基本吻合，只是這個數值偏小很多，有知道原因的可以告知下。

此外我也搜尋到了問題類似的文章：https://heapdump.cn/article/1930426 ，可見很多時候，遇到的問題，別人早就遇到過並分享了，關鍵是這種文章被大量低質量文章給淹沒了，沒找到問題前，你根本搜尋不到！

哎，分享傳播了知識，同時也阻礙了知識傳播！

總結

排查這個問題的過程中，學到了不少新知識與新方法，總結如下：

  1. safepoint原理是什麼，spin與block階段耗時長代表了什麼。
  2. 使用async-profiler分析safepoint的方法。
  3. 容器內可通過/proc/<pid>/task/<tid>/schedstat測量程式排程延遲。
  4. 容器內可通過/sys/fs/cgroup/cpu,cpuacct/cpu.stat測量容器CPU受限情況。

往期內容

耗時幾個月，終於找到了JVM停頓十幾秒的原因
密碼學入門
神祕的backlog引數與TCP連線佇列
mysql的timestamp會存在時區問題？
真正理解可重複讀事務隔離級別
字元編碼解惑

相關文章