kikimo

ps 指令 hang 死原因分析(一)

一台服务器出了问题, 登陆上去执行ps aux命令没有响应, ctrl+c也无法退出。 重新登陆机器执行ps aux又挂住没法操作了。 只能再登陆机器, 跑strace ps aux观察,又卡住了:

# strace ps aux
stat("/proc/180944", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
open("/proc/180944/stat", O_RDONLY)     = 6
read(6, "180944 (ps) D 1 180804 31034 0 -"..., 2048) = 330
close(6)                                = 0
open("/proc/180944/status", O_RDONLY)   = 6
read(6, "Name:\tps\nUmask:\t0022\nState:\tD (d"..., 2048) = 1205
close(6)                                = 0
open("/proc/180944/cmdline", O_RDONLY)  = 6
read(6, "ps\0-ef\0", 131072)            = 7
read(6, "", 131065)                     = 0
close(6)                                = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=388, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=388, ...}) = 0
write(1, "root     180944  0.0  0.0 155328"..., 73root     180944  0.0  0.0 155328   424 ?        D    Jan29   0:00 ps -ef
) = 73
stat("/proc/181134", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
open("/proc/181134/stat", O_RDONLY)     = 6
read(6, "181134 (java) D 1 177157 31034 0"..., 2048) = 333
close(6)                                = 0
open("/proc/181134/status", O_RDONLY)   = 6
read(6, "Name:\tjava\nUmask:\t0022\nState:\tD "..., 2048) = 1207
close(6)                                = 0
open("/proc/181134/cmdline", O_RDONLY)  = 6
read(6,

可以看到ps aux似乎是卡在/proc/181134/cmdline文件的读取上。 执行cat /proc/181134/cmdline,果然又卡住。 再登陆机器,执行top指令,谢天谢地,top没 hang 死, 搜索ps指令,看到ps进程处于D(uninterruptible sleep)状态, cat /proc/181134/cmdline命令也是:

...
   PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 38042 root      20   0  155328   1900   1484 D   0.0  0.0   0:00.09 ps
 38111 root      20   0  154624   5352   4036 S   0.0  0.0   0:00.22 sshd
 38116 tdops     20   0  154624   2876   1548 S   0.0  0.0   0:00.01 sshd
 38118 tdops     20   0  115436   1968   1600 S   0.0  0.0   0:00.02 bash
 38156 root      20   0  241112   4536   3376 S   0.0  0.0   0:00.01 sudo
 38159 root      20   0  193928   2412   1772 S   0.0  0.0   0:00.01 su
 38160 root      20   0  115436   2068   1656 S   0.0  0.0   0:00.05 bash
...

不过这里有一点比较奇怪的是:pscat会进入D状态,但是strace只是进入S(sleep)状态,它还能 kill,why?

检查cat 进程的堆栈,发现进程挂在内核中一个函数call_rwsem_down_read_failed()上:

# cat /proc/38042/stack
[<ffffffff81331ad8>] call_rwsem_down_read_failed+0x18/0x30
[<ffffffff812739d2>] proc_pid_cmdline_read+0xb2/0x560
[<ffffffff81200b9c>] vfs_read+0x9c/0x170
[<ffffffff81201a5f>] SyS_read+0x7f/0xe0
[<ffffffff816b4fc9>] system_call_fastpath+0x16/0x1b
[<ffffffffffffffff>] 0xffffffffffffffff

google 搜索 “读取/proc/pid/cmdline hang 死"的信息, 看到一个 2018 年出的内核补丁, 主题是 [PATCH] fs: proc: use down_read_killable in proc_pid_cmdline_read(), 看起来高度相关,

From	Yang Shi <>
Subject	[PATCH] fs: proc: use down_read_killable in proc_pid_cmdline_read()
Date	Wed, 21 Feb 2018 03:49:29 +0800
share
When running vm-scalability with large memory (> 300GB), the below hung
task issue happens occasionally.

INFO: task ps:14018 blocked for more than 120 seconds.
       Tainted: G            E 4.9.79-009.ali3000.alios7.x86_64 #1
 "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
 ps              D    0 14018      1 0x00000004
  ffff885582f84000 ffff885e8682f000 ffff880972943000 ffff885ebf499bc0
  ffff8828ee120000 ffffc900349bfca8 ffffffff817154d0 0000000000000040
  00ffffff812f872a ffff885ebf499bc0 024000d000948300 ffff880972943000
 Call Trace:
  [<ffffffff817154d0>] ? __schedule+0x250/0x730
  [<ffffffff817159e6>] schedule+0x36/0x80
  [<ffffffff81718560>] rwsem_down_read_failed+0xf0/0x150
  [<ffffffff81390a28>] call_rwsem_down_read_failed+0x18/0x30
  [<ffffffff81717db0>] down_read+0x20/0x40
  [<ffffffff812b9439>] proc_pid_cmdline_read+0xd9/0x4e0
  [<ffffffff81253c95>] ? do_filp_open+0xa5/0x100
  [<ffffffff81241d87>] __vfs_read+0x37/0x150
  [<ffffffff812f824b>] ? security_file_permission+0x9b/0xc0
  [<ffffffff81242266>] vfs_read+0x96/0x130
  [<ffffffff812437b5>] SyS_read+0x55/0xc0
  [<ffffffff8171a6da>] entry_SYSCALL_64_fastpath+0x1a/0xc5

When manipulating a large mapping, the process may hold the mmap_sem for
long time, so reading /proc/<pid>/cmdline may be blocked in
uninterruptible state for long time.

down_read_trylock() sounds too aggressive, and we already have killable
version APIs for semaphore, here use down_read_killable() to improve the
responsiveness.

Signed-off-by: Yang Shi <yang.shi@linux.alibaba.com>
Cc: Alexey Dobriyan <adobriyan@gmail.com>
---
 fs/proc/base.c | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/fs/proc/base.c b/fs/proc/base.c
index 9298324..44b6f8f 100644
--- a/fs/proc/base.c
+++ b/fs/proc/base.c
@@ -242,7 +242,9 @@ static ssize_t proc_pid_cmdline_read(struct file *file, char __user *buf,
 		goto out_mmput;
 	}

-	down_read(&mm->mmap_sem);
+	rv = down_read_killable(&mm->mmap_sem);
+	if (rv)
+		goto out_mmput;
 	arg_start = mm->arg_start;
 	arg_end = mm->arg_end;
 	env_start = mm->env_start;
--
1.8.3.1

看补丁,主要是把down_read()函数替换成down_read_killable(), 这个函数可以避免读取/proc/pid/cmdline文件时发生死锁, down_read(&mm->mmap_sem)看起来应该是和信号量相关的函数操作, 不过为什么down_read(&mm->mmap_sem)会死锁呢? mm->mmap_sem应该是个信号量,可能是这个信号量异常导致pscat指令都死锁了。 真正导致死锁的应该不是ps, cat指令,它们应该是受害者, 查看系统日志,发现有 Java 进程 hang 死的日志:

{timestamp} {hostname} kernel: INFO: task java:181134 blocked for more than 120 seconds.
{timestamp} {hostname} kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
{timestamp} {hostname} kernel: java            D ffff881269bd7c00     0 181134      1 0x00000084
{timestamp} {hostname} kernel: ffff881269bd7bd8 0000000000000082 ffff882037e04f10 ffff881269bd7fd8
{timestamp} {hostname} kernel: ffff881269bd7fd8 ffff881269bd7fd8 ffff882037e04f10 ffff882037e04f10
{timestamp} {hostname} kernel: ffff88203c9abef8 ffffffffffffffff ffff88203c9abf00 ffff881269bd7c00
{timestamp} {hostname} kernel: Call Trace:
{timestamp} {hostname} kernel: [<ffffffff816a94c9>] schedule+0x29/0x70
{timestamp} {hostname} kernel: [<ffffffff816aaafd>] rwsem_down_read_failed+0x10d/0x1a0
{timestamp} {hostname} kernel: [<ffffffff81331ad8>] call_rwsem_down_read_failed+0x18/0x30
{timestamp} {hostname} kernel: [<ffffffff816a8760>] down_read+0x20/0x40
{timestamp} {hostname} kernel: [<ffffffff8108d8b9>] do_exit+0x189/0xa40
{timestamp} {hostname} kernel: [<ffffffff81327a16>] ? plist_del+0x46/0x70
{timestamp} {hostname} kernel: [<ffffffff810f49fc>] ? __unqueue_futex+0x2c/0x60
{timestamp} {hostname} kernel: [<ffffffff810f5d8f>] ? futex_wait+0x11f/0x280
{timestamp} {hostname} kernel: [<ffffffff8108e1ef>] do_group_exit+0x3f/0xa0
{timestamp} {hostname} kernel: [<ffffffff8109e31e>] get_signal_to_deliver+0x1ce/0x5e0
{timestamp} {hostname} kernel: [<ffffffff8102a467>] do_signal+0x57/0x6c0
{timestamp} {hostname} kernel: [<ffffffff810c4149>] ? wake_up_new_task+0x119/0x190
{timestamp} {hostname} kernel: [<ffffffff81086ac7>] ? do_fork+0x107/0x320
{timestamp} {hostname} kernel: [<ffffffff8102ab2f>] do_notify_resume+0x5f/0xb0
{timestamp} {hostname} kernel: [<ffffffff816b527d>] int_signal+0x12/0x17

可以看到 Java 进程java:181134 也卡死在rwsem_down_read_failed()函数上, 估计当前版本的内核存在死锁的 bug, google 发现centos 官方的 bug 记录,发现问题高度类似: 其中有个回复提及到修复补丁:

this issue seam is the resem wakeup loss, would be fix by patch below:
Wed Mar 20 2019 Jan Stancek <jstancek@redhat.com> [3.10.0-957.12.1.el7]
- [kernel] locking/rwsem: Fix (possible) missed wakeup (Waiman Long) [1690323 1547078]
- [kernel] futex: Fix (possible) missed wakeup (Waiman Long) [1690323 1547078]
- [kernel] futex: Use smp_store_release() in mark_wake_futex() (Waiman Long) [1690323 1547078]
- [kernel] sched/wake_q: Fix wakeup ordering for wake_q (Waiman Long) [1690323 1547078]
- [kernel] sched/wake_q: Document wake_q_add() (Waiman Long) [1690323 1547078]

还看到内核邮件组对rwsem(这个应该就是我们前面提到的信号量)死锁问题的讨论, 估计就是内核信号量的 bug 了(未完待续)。