一次死鎖導致CPU異常飄高的整個故障排查過程

自由早晚亂餘生發表於2021-04-23

一、問題詳情

linux一切皆檔案

2021年4月2號，晚上10.45分左右，線上業務異常，後排查線上伺服器CPU 異常高，機器是 16核 64G的。但是實際負載已經達到了 140左右。

top 命令截圖

聯絡騰訊雲排查

虛擬機器所屬於物理機是否有故障。
虛擬機器所用的資源是否有抖動或者變更。(網路/儲存等)

騰訊雲回覆暫無異常。

檢查系統日誌發現異常

Apr  2 22:45:22 docker-machine systemd: Reloading.
Apr  2 22:46:37 docker-machine systemd-logind: Failed to start session scope session-175098.scope: Connection timed out
Apr  2 22:47:26 docker-machine systemd-logind: Failed to start session scope session-175101.scope: Connection timed out
Apr  2 22:47:51 docker-machine systemd-logind: Failed to start session scope session-175102.scope: Connection timed out
Apr  2 22:48:26 docker-machine systemd-logind: Failed to start session scope session-175104.scope: Connection timed out
Apr  2 22:48:51 docker-machine systemd-logind: Failed to start session scope session-175105.scope: Connection timed out
Apr  2 22:49:06 docker-machine kernel: INFO: task systemd:1 blocked for more than 120 seconds.
Apr  2 22:49:06 docker-machine kernel:      Not tainted 4.4.108-1.el7.elrepo.x86_64 #1
Apr  2 22:49:06 docker-machine kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Apr  2 22:49:06 docker-machine kernel: systemd         D ffff880fd8bebc68     0     1      0 0x00000000
Apr  2 22:49:06 docker-machine kernel: ffff880fd8bebc68 ffff880fd5e69c00 ffff880fd8be0000 ffff880fd8bec000
Apr  2 22:49:06 docker-machine kernel: ffff880fd8bebdb8 ffff880fd8bebdb0 ffff880fd8be0000 ffff88039c6a9140
Apr  2 22:49:06 docker-machine kernel: ffff880fd8bebc80 ffffffff81700085 7fffffffffffffff ffff880fd8bebd30
Apr  2 22:49:06 docker-machine kernel: Call Trace:
Apr  2 22:49:06 docker-machine kernel: [<ffffffff81700085>] schedule+0x35/0x80
Apr  2 22:49:06 docker-machine kernel: [<ffffffff81702d97>] schedule_timeout+0x237/0x2d0
Apr  2 22:49:06 docker-machine kernel: [<ffffffff813392cf>] ? idr_remove+0x17f/0x260
Apr  2 22:49:06 docker-machine kernel: [<ffffffff81700b81>] wait_for_completion+0xf1/0x130
Apr  2 22:49:06 docker-machine kernel: [<ffffffff810aa6a0>] ? wake_up_q+0x80/0x80
Apr  2 22:49:06 docker-machine kernel: [<ffffffff810e2804>] __synchronize_srcu+0xf4/0x130
Apr  2 22:49:06 docker-machine kernel: [<ffffffff810e1c70>] ? trace_raw_output_rcu_utilization+0x60/0x60
Apr  2 22:49:06 docker-machine kernel: [<ffffffff810e2864>] synchronize_srcu+0x24/0x30
Apr  2 22:49:06 docker-machine kernel: [<ffffffff81249b3b>] fsnotify_destroy_group+0x3b/0x70
Apr  2 22:49:06 docker-machine kernel: [<ffffffff8124b872>] inotify_release+0x22/0x50
Apr  2 22:49:06 docker-machine kernel: [<ffffffff81208b64>] __fput+0xe4/0x210
Apr  2 22:49:06 docker-machine kernel: [<ffffffff81208cce>] ____fput+0xe/0x10
Apr  2 22:49:06 docker-machine kernel: [<ffffffff8109c1e6>] task_work_run+0x86/0xb0
Apr  2 22:49:06 docker-machine kernel: [<ffffffff81079acf>] exit_to_usermode_loop+0x73/0xa2
Apr  2 22:49:06 docker-machine kernel: [<ffffffff81003bcd>] syscall_return_slowpath+0x8d/0xa0
Apr  2 22:49:06 docker-machine kernel: [<ffffffff81703d8c>] int_ret_from_sys_call+0x25/0x8f
Apr  2 22:49:06 docker-machine kernel: INFO: task fsnotify_mark:135 blocked for more than 120 seconds.
Apr  2 22:49:06 docker-machine kernel:      Not tainted 4.4.108-1.el7.elrepo.x86_64 #1
Apr  2 22:49:06 docker-machine kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Apr  2 22:49:06 docker-machine kernel: fsnotify_mark   D ffff880fd4993c88     0   135      2 0x00000000
Apr  2 22:49:06 docker-machine kernel: ffff880fd4993c88 ffff880fdf597648 ffff880fd8375900 ffff880fd4994000
Apr  2 22:49:06 docker-machine kernel: ffff880fd4993dd8 ffff880fd4993dd0 ffff880fd8375900 ffff880fd4993e40
Apr  2 22:49:06 docker-machine kernel: ffff880fd4993ca0 ffffffff81700085 7fffffffffffffff ffff880fd4993d50
Apr  2 22:49:06 docker-machine kernel: Call Trace:
Apr  2 22:49:06 docker-machine kernel: [<ffffffff81700085>] schedule+0x35/0x80
Apr  2 22:49:06 docker-machine kernel: [<ffffffff81702d97>] schedule_timeout+0x237/0x2d0
Apr  2 22:49:06 docker-machine kernel: [<ffffffff81062aee>] ? kvm_clock_read+0x1e/0x20
Apr  2 22:49:06 docker-machine kernel: [<ffffffff81700b81>] wait_for_completion+0xf1/0x130
Apr  2 22:49:11 docker-machine kernel: INFO: task java:12560 blocked for more than 120 seconds.
Apr  2 22:49:11 docker-machine kernel:      Not tainted 4.4.108-1.el7.elrepo.x86_64 #1
Apr  2 22:49:11 docker-machine kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Apr  2 22:49:11 docker-machine kernel: java            D ffff880bfbdc7b00     0 12560   4206 0x00000180
Apr  2 22:49:11 docker-machine kernel: ffff880bfbdc7b00 ffff880bfbdc7b40 ffff880bfbdac2c0 ffff880bfbdc8000
Apr  2 22:49:11 docker-machine kernel: ffff8809beb142d8 ffff8809beb14200 0000000000000000 0000000000000000
Apr  2 22:49:11 docker-machine kernel: ffff880bfbdc7b18 ffffffff81700085 ffff880b155adfc0 ffff880bfbdc7b98
Apr  2 22:49:11 docker-machine kernel: Call Trace:
Apr  2 22:49:11 docker-machine kernel: [<ffffffff81700085>] schedule+0x35/0x80
Apr  2 22:49:11 docker-machine kernel: [<ffffffff8124ca55>] fanotify_handle_event+0x1b5/0x2f0
Apr  2 22:49:11 docker-machine kernel: [<ffffffff810c2b50>] ? prepare_to_wait_event+0xf0/0xf0
Apr  2 22:49:11 docker-machine kernel: [<ffffffff8124933f>] fsnotify+0x26f/0x460
Apr  2 22:49:11 docker-machine kernel: [<ffffffff810a1fd1>] ? in_group_p+0x31/0x40
Apr  2 22:49:11 docker-machine kernel: [<ffffffff812111fc>] ? generic_permission+0x15c/0x1d0
Apr  2 22:49:11 docker-machine kernel: [<ffffffff812b355b>] security_file_open+0x8b/0x90
Apr  2 22:49:11 docker-machine kernel: [<ffffffff8120484f>] do_dentry_open+0xbf/0x320
Apr  2 22:49:11 docker-machine kernel: [<ffffffffa02cb552>] ? ovl_d_select_inode+0x42/0x110 [overlay]
Apr  2 22:49:11 docker-machine kernel: [<ffffffff81205e15>] vfs_open+0x55/0x80
Apr  2 22:49:11 docker-machine kernel: [<ffffffff81214143>] path_openat+0x1c3/0x1300

檢視日誌，覺得很大可能性是： cache 落盤故障，有可能是 io 的問題。通過 iotop 進行排查，未發現異常。

當時我們認為是騰訊雲底層儲存或者網路出現問題導致的。

在排查了近一個小時，機器上面的cpu 還是沒有降低。我們對機器進行了重啟。重啟後，一些恢復了正常。

二、問題解析

認為是儲存的問題

首先上面的故障是同時出現在兩臺機器(A和B)的, 詢問騰訊雲 A 的系統盤和A的資料盤以及B的資料盤都是在同一個遠端儲存的，所以這更加深了我們認為是儲存導致的問題，有可能是到物理機到儲存之間的網路，也有可能是儲存本身的效能問題。

騰訊雲排查後說這兩個機器，所用的儲存和儲存網路沒有問題，所以儲存問題不成立。
系統的殭屍程式很多

在上面top 命令我們可以看到有僵死程式，後面也是一直在增加僵死程式。

僵死程式的來源：
1. 上面的僵死程式來源是我們的定時任務導致的，我們定時任務指令碼執行的程式變成的僵死程式。
如何看僵死程式
```
ps -A -o stat,ppid,pid,cmd | grep -e '^[Zz]'
```
/var/log/message 異常資訊

我們再看看 /var/log/message 的日誌，我們可以看到一個很關鍵的資訊 kernel: INFO: task systemd:1 blocked for more than 120 seconds.

網上大多數時是說 vm.dirty_ratio 和vm.dirty_background_ratio 這兩個引數設定的有問題。

我們檢視了我們這兩個核心引數的配置，都是正常合理的。
```
$ sysctl -a|grep -E  'vm.dirty_background_ratio|vm.dirty_ratio'
vm.dirty_background_ratio = 10  # 
vm.dirty_ratio = 30
```
具體的引數詳解，見下文。

我們再看看 /var/log/message 的日誌，我們可以看到一個很關鍵的資訊

Apr  2 22:45:22 docker-machine systemd: Reloading.
Apr  2 22:49:06 docker-machine kernel: INFO: task systemd:1 blocked for more than 120 seconds.
Apr  2 22:49:06 docker-machine kernel: systemd         D ffff880fd8bebc68     0     1      0 0x00000000
Apr  2 22:49:06 docker-machine kernel: INFO: task fsnotify_mark:135 blocked for more than 120 seconds.
Apr  2 22:49:06 docker-machine kernel: fsnotify_mark   D ffff880fd4993c88     0   135      2 0x00000000
Apr  2 22:49:11 docker-machine kernel: INFO: task java:12560 blocked for more than 120 seconds.
Apr  2 22:49:11 docker-machine kernel: java            D ffff880bfbdc7b00     0 12560   4206 0x00000180

就是 systemd 在 Reloading, systemd 和 fsnotify_mark 都被block了，那麼被鎖了原因是什麼，按道理來說應該 io 的問題啊，就是寫得慢啊，但是我們忽略了一個問題，如果要寫的檔案加鎖了，那麼也是會出現這個情況的啊。

尋找加鎖的原因：騰訊雲主機安全產品雲鏡，沒錯就很大可能性是它導致的。具體內容見下文。

三、問題原因

為什麼會定位到雲鏡產品，首先是我們認為如果底層 io 沒有問題的話，那麼就只能是檔案可能被鎖了，並且如果你細心的話，你會發現僵死程式裡面，有云鏡的身影

為什麼雲鏡會變成僵死程式，是因為雲鏡啟動失敗了，一直在啟動。

我們再說回為什麼會定位到雲鏡上面，主要是因為雲鏡會對系統上檔案有定期掃描的，為什麼會想到就是安全產品(https://access.redhat.com/solutions/2838901)。安全產品就是雲鏡。

我們觀察雲鏡的日誌，我們又發現了一個問題，原來在 22：45 左右，雲鏡在更新，這個很巧合啊，我們出問題的兩個機器都在這個時間段進行了更新，而沒有異常的機器，都沒有更新操作。

雲鏡更新的日誌
更新後一直沒有云鏡一直啟動失敗
redhat 官方文件

https://access.redhat.com/solutions/2838901

也是說到安全產品會可能觸發這個問題。

最終結論

最終讓騰訊雲排查雲鏡此次版本升級，得到答覆：

推測YDService在exit group退出的時未及時對fanotify/inotify進行適當的清理工作，導致其它程式阻塞等待，因此針對此點進行了優化。

問題1：針對為什麼只有兩臺機器在那個時間點進行更新，是因為那個雲鏡後端排程策略是分批升級。

四、擴充套件

程式的幾種狀態

https://liam.page/2020/01/10/the-states-of-processes-on-Linux/

程式通常處於以下兩種狀態之一：

在 CPU 上執行（此時，程式正在執行）在 ps 或是 top 中，狀態標識為 R 的程式，即處於正在執行狀態。
不在 CPU 上執行（此時，程式未在執行）

未在執行的程式可能處於不同狀態：
- 可執行狀態 (R)
  
  程式獲取了所有所需資源，正等待 CPU 時，就會進入可執行狀態。處於可執行狀態的程式在 ps 的輸出中，也已 R 標識。
  
  舉例來說，一個正在 I/O 的程式並不立即需要 CPU。當程式完成 I/O 操作後，就會觸發一個訊號，通知 CPU 和排程器將該程式置於執行佇列（由核心維護的可執行程式的列表）。當 CPU 可用時，該程式就會進入正在執行狀態。
- 可中斷之睡眠狀態 (S)
  
  可中斷之睡眠狀態表示程式在等待時間片段或者某個特定的事件。一旦事件發生，程式會從可中斷之睡眠狀態中退出。ps 命令的輸出中，可中斷之睡眠狀態標識為 S。
- 不可中斷之睡眠狀態(D)
  不可中斷之睡眠狀態的程式不會處理任何訊號，而僅在其等待的資源可用或超時時退出（前提是設定了超時時間）。
  
  不可中斷之睡眠狀態通常和裝置驅動等待磁碟或網路 I/O 有關。在核心原始碼 fs/proc/array.c 中，其文字定義為 "D (disk sleep)", /* 2 */。當程式進入不可中斷之睡眠狀態時，程式不會處理訊號，而是將訊號都積累起來，等程式喚醒之後再處理。在 Linux 中，ps 命令使用 D 來標識處於不可中斷之睡眠狀態的程式。
  
  系統會為不可中斷之睡眠狀態的程式設定程式執行狀態為：
```
p->state = TASK_UNINTERRUPTABLE;
```
  由於處於不可中斷之睡眠狀態的程式不會處理任何訊號，所以 kill -9 也殺不掉它。解決此類程式的辦法只有兩個:
  - 對於怨婦，你還能怎麼辦，只能滿足它啊：搞定不可中斷之睡眠狀態程式所等待的資源，使資源可用。
  - 如果滿足不了它，那就只能 kill the world——重啟系統。
- 僵死狀態(Z)
  
  程式可以主動呼叫 exit 系統呼叫來終止，或者接受訊號來由訊號處理函式來呼叫 exit 系統呼叫來終止。
  
  當程式執行 exit 系統呼叫後，程式會釋放相應的資料結構；此時，程式本身已經終止。不過，此時作業系統還沒有釋放程式表中該程式的槽位（可以形象地理解為，「父程式還沒有替子程式收屍」）；為解決這個問題，終止前，程式會向父程式傳送 SIGCHLD 訊號，通知父程式來釋放子程式在作業系統程式表中的槽位。這個設計是為了讓父程式知道子程式退出時所處的狀態。
  
  子程式終止後到父程式釋放程式表中子程式所佔槽位的過程，子程式進入殭屍狀態（zombie state）。如果在父程式因為各種原因，在釋放子程式槽位之前就掛掉了，也就是，父程式來不及為子程式收屍。那麼，子程式就會一直處於殭屍狀態。而考慮到，處於殭屍狀態的程式本身已經終止，無法再處理任何訊號，所以它就只能是孤魂野鬼，飄在作業系統程式表裡，直到系統重啟。
馬後炮

在前面的日誌中，也就是下面：
```
Apr  2 22:49:06 docker-machine kernel: systemd         D ffff880fd8bebc68     0     1      0 0x00000000
Apr  2 22:49:06 docker-machine kernel: INFO: task fsnotify_mark:135 blocked for more than 120 seconds.
Apr  2 22:49:06 docker-machine kernel: fsnotify_mark   D ffff880fd4993c88     0   135      2 0x00000000
```
我們部分程式處於 不可中斷之睡眠狀態(D)，在這個狀態的服務，前面也說到只能給他資源，或者重啟系統。也就可以說明：

解釋疑問:
1. 為什麼我們故障機器上面部分服務存在問題，部分服務正常。
  
  因為部分程式處於 不可中斷之睡眠狀態(D)。檔案(linux一切皆檔案)被鎖，導致了部分服務程式進入了不可中斷睡眠狀態。

如何快速清理殭屍程式(Z)

用top檢視系統中的殭屍程式情況
top
再看看這些殭屍是什麼程式來的
ps -A -o stat,ppid,pid,cmd | grep -e '^[Zz]'
 
kill -s SIGCHLD pid  (父程式pid)

核心引數相關

dirty_background_ratio 指當檔案系統快取髒頁數量達到系統記憶體百分之多少時（預設10%）喚醒核心的 flush 等程式，寫回磁碟。
dirty_ratio 為最大髒頁比例，當髒頁數達到該比例時，必須將所有髒資料提交到磁碟，同時所有新的 IO 都會被阻塞，直到髒資料被寫入磁碟，通常會造成 IO 卡頓。系統先會達到 vm.dirty_background_ratio 的條件然後觸發 flush 程式進行非同步的回寫操作，此時應用程式仍然可以進行寫操作，如果達到 vm.dirty_ratio 這個引數所設定的值，此時作業系統會轉入同步地處理髒頁的過程，阻塞應用程式。

如何檢視哪些檔案被哪些程式被鎖

http://blog.chinaunix.net/uid-28541347-id-5678998.html

cat /proc/locks
1: POSIX  ADVISORY  WRITE 3376 fd:10:805736756 0 EOF
2: FLOCK  ADVISORY  WRITE 1446 00:14:23843 0 EOF
3: FLOCK  ADVISORY  WRITE 4650 00:14:32551 0 EOF
4: POSIX  ADVISORY  WRITE 4719 fd:01:531689 1073741824 1073742335
5: OFDLCK ADVISORY  READ  1427 00:06:1028 0 EOF
6: POSIX  ADVISORY  WRITE 4719 00:14:26155 0 EOF
7: POSIX  ADVISORY  WRITE 4443 00:14:26099 0 EOF
8: FLOCK  ADVISORY  WRITE 4561 00:14:34870 0 EOF
9: POSIX  ADVISORY  WRITE 566 00:14:15509 0 EOF
10: POSIX  ADVISORY  WRITE 4650 fd:01:788600 0 EOF
11: OFDLCK ADVISORY  READ  1713 00:06:1028 0 EOF
12: FLOCK  ADVISORY  WRITE 1713 fd:10:268435553 0 EOF
13: FLOCK  ADVISORY  WRITE 1713 fd:10:268435528 0 EOF
14: POSIX  ADVISORY  WRITE 12198 fd:01:526366 0 EOF
15: POSIX  ADVISORY  WRITE 3065 fd:10:805736741 0 EOF
16: FLOCK  ADVISORY  WRITE 1731 fd:10:268435525 0 EOF
17: FLOCK  ADVISORY  WRITE 4459 00:14:37972 0 EOF
18: POSIX  ADVISORY  WRITE 1444 00:14:14793 0 EOF

我們可以看到/proc/locks下面有鎖的資訊：我現在分別敘述下含義：

POSIX FLOCK 這個比較明確，就是哪個型別的鎖。flock系統呼叫產生的是FLOCK，fcntl呼叫F_SETLK，F_SETLKW或者lockf產生的是POSIX型別，有次可見兩種呼叫產生的鎖的型別是不同的；
ADVISORY表明是勸告鎖；
WRITE顧名思義，是寫鎖，還有讀鎖；
18849 是持有鎖的程式ID。當然對於flock這種型別的鎖，會出現程式已經退出的狀況。
08:02:852674 表示的對應磁碟檔案的所在裝置的主裝置好，次裝置號，還有檔案對應的inode number。
0 表示的是所的其實位置
EOF表示的是結束位置。這兩個欄位對fcntl型別比較有用，對flock來是總是0 和EOF。

一次FGC導致CPU飆高的排查過程
2020-06-01
GC
一次詭異的線上資料庫的死鎖問題排查過程
2019-04-09
資料庫
記錄一次Flink作業異常的排查過程
2020-06-17
線上問題排查：記一次 Redis Cluster Pipeline 導致的死鎖問題
2023-12-04
Redis
PostgreSQL 死鎖異常
2024-01-05
SQL
記一次FreeBSD系統中mysql服務異常的排查過程
2022-07-13
MySql
故障分析 | 大量短時程式導致 cpu 負載過高案例一則
2022-05-31
負載
異常連線導致的記憶體洩漏排查
2019-08-03
記憶體
死鎖問題排查過程-間隙鎖的復現以及解決
2022-07-10
記一次神奇的Mysql死鎖排查
2019-02-27
MySql
解Bug之路-記一次中介軟體導致的慢SQL排查過程
2020-09-07
SQL
解Bug之路-記一次儲存故障的排查過程
2020-10-14
記一次排查線上MySQL死鎖過程，不能只會curd，還要知道加鎖原理
2022-06-29
MySql
記一次Oracle死鎖/阻塞排查
2019-01-15
Oracle
記一次詭異的故障排查經歷
2018-07-24
記錄一次資料庫CPU被打滿的排查過程
2022-08-31
資料庫
記一次排查CPU高的問題
2021-11-05
一次.net code中的placeholder導致的高cpu診斷
2023-03-18
JVM線上CPU 飈高故障排查基本操作
2019-04-10
JVM
記一次 gocode 在高版本 Go 高耗 CPU 導致的 LiteIDE 卡頓
2020-03-13
GoIDE
線上排查：記憶體異常使用導致full gc頻繁
2023-02-07
記憶體GC
詳述一條SQL引發的高CPU故障處理過程
2018-12-28
SQL
生產中遇到 cpu 過高排查
2022-12-29
故障解析丨一次死鎖問題的解決
2024-03-18
容器網路防火牆狀態異常導致丟包排查記錄
2020-09-03
防火牆
一次奇怪的的bug排查過程
2021-11-30
Oracle死鎖一例(ORA-00060)，鎖表導致的業務死鎖問題
2018-07-05
Oracle
MySQL 預插入的資料條數過多導致異常
2019-06-15
MySql
一次django記憶體異常排查
2020-07-30
Django記憶體
java應用CPU佔用率過高排查
2024-05-20
Java
線上的一次fullgc排查過程
2024-07-03
GC
一次線上CPU高的問題排查實踐
2019-06-23
ORA-19909(一次DataGuard Failover導致的故障
2020-06-10
AI
Java cpu 高排查
2024-08-07
Java
【故障公告】1個儲存過程拖垮整個資料庫
2022-02-21
儲存過程資料庫
效能分析（5）- 軟中斷導致 CPU 使用率過高的案例
2020-08-11
記一次棧溢位異常問題的排查
2024-04-16
MySQL死鎖系列-線上死鎖問題排查思路
2020-10-19
MySql