cpu iowait 升高分析以及僵尸进程

摘要:

本文首先介绍了不可中断睡眠状态产生的原因,以及僵尸进程相关的概念,并通过一个简单的案例分析了cpu iowait 升高的 性能定位分析问题的场景。

不可中断睡眠状态

不可中断状态睡眠(Uninterruptible Sleep),一般表示进程正在跟硬件交互,并且交互过程不允许被其他进程或中断打断。

不可中断状态,其实是为了保证进程数据与硬件状态一致,并且正常情况下,不可中断状态在很短时间内就会结束。所以,短时的不可中断状态进程,一般可以忽略。

但如果系统或硬件发生了故障,进程可能会在不可中断状态保持很久,甚至导致系统中出现大量不可中断进程。此时就需要排查系统是不是出现了 I/O 等性能问题?

僵尸进程

正常情况下,当一个进程创建了子进程后,应该通过系统调用 wait() 或者 waitpid() 等待子进程结束,回收子进程的资源;而子进程在结束时,会向它的父进程发送 SIGCHLD 信号,所以,父进程还可以注册 SIGCHLD 信号的处理函数,异步回收资源。如果父进程没进行资源回收,或是子进程执行太快,父进程还没来得及处理子进程状态,子进程就已经提前退出,那这时的子进程就会变成僵尸进程。

正常,僵尸进程持续的时间都比较短,在父进程回收它的资源后就会消亡;或者在父进程退出后,由 init 进程回收后也会消亡。一旦父进程没有处理子进程的终止,还一直保持运行状态,那么子进程就会一直处于僵尸状态。

大量的僵尸进程会用尽 PID 进程号,导致新进程不能创建,所以这种情况一定要避免。

僵尸进程的问题相对容易排查:使用 pstree 找出父进程后,去查看父进程的代码,检查 wait() / waitpid() 的调用,或是 SIGCHLD 信号处理函数的注册就行了。

案例

yine@ubuntu:~$ ps -aux | grep app
root      425349  0.0  0.0   2488   460 ?        Ss+  22:30   0:00 /app
root      425385  7.1  0.0      0     0 ?        Z+   22:30   0:01 [app] <defunct>
root      425386  4.8  0.0      0     0 ?        Z+   22:30   0:00 [app] <defunct>
root      425388 26.6  0.0      0     0 ?        Z+   22:31   0:03 [app] <defunct>
root      425389 25.7  0.0      0     0 ?        Z+   22:31   0:03 [app] <defunct>
root      425390 21.5  3.2  68028 65708 ?        R+   22:31   0:01 /app
root      425391 12.8  3.2  68028 65708 ?        R+   22:31   0:01 /app
yine      425397  0.7  0.0   8900   732 pts/7    S+   22:31   0:00 grep --color=auto app
root      425398  4.0  3.2  68028 65700 ?        D+   22:31   0:00 /app
root      425399  3.5  3.2  68028 65696 ?        D+   22:31   0:00 /app

s 表示这个进程是一个会话的领导进程,而 + 表示前台进程组。
进程组和会话。它们用来管理一组相互关联的进程,意思其实很好理解。

  • 进程组表示一组相互关联的进程,比如每个子进程都是父进程所在组的成员;
  • 而会话是指共享同一个控制终端的一个或多个进程组。
  1. top 观察平均负载
top - 22:41:36 up 3 min,  1 user,  load average: 3.20, 1.32, 0.15
Tasks: 371 total,   1 running, 340 sleeping,   0 stopped,  30 zombie

平均负载正在升高,同时僵尸进程数量在增多, 同时各个cpu 的iowait 升高

  1. dstat 监控
dstat 1 20
You did not select any stats, using -cdngy by default.
--total-cpu-usage-- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai stl| read  writ| recv  send|  in   out | int   csw 
  2  13  72  12   0| 744M   45k|   0     0 |1755B   10k|1269  1068 
  6  22  64   9   0|1218M    0 |   0     0 |   0     0 |1758   922 
  4  28  42  26   0|1593M    0 |   0     0 |   0     0 |2367  1275 
  5  31  35  30   0|1664M    0 | 129B    0 |   0     0 |2180  1018 
  6  27  39  28   0|1629M    0 |   0    70B|   0     0 |2391   961 
  0   1  99   0   0|  45M    0 |   0     0 |   0     0 | 329   468 
  4  21  56  19   0|1199M    0 |   0     0 |   0     0 |1796  1005 
  4  27  41  29   0|1643M    0 |   0     0 |   0     0 |2372  1138 
  5  31  33  31   0|1637M    0 | 120B   60B|   0     0 |2157   912 
  5  26  38  30   0|1670M    0 |   0     0 |   0     0 |2601  1028 
  0   0 100   0   0|   0     0 |   0     0 |   0     0 | 210   361 

可发现 iowait 在升高的时候,磁盘读请求在升高。

  1. pidstat 找出磁盘读的进程 确定时app 进程在进行磁盘读
pidstat -d 1 10
Linux 5.4.0-54-generic (ubuntu)     12/07/2020  _x86_64_    (4 CPU)

10:56:18 PM   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command
10:56:19 PM     0      3217     -1.00     -1.00     -1.00      25  app
10:56:19 PM     0      3218     -1.00     -1.00     -1.00      35  app

10:56:19 PM   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command
10:56:20 PM     0      3217     -1.00     -1.00     -1.00     104  app
10:56:20 PM     0      3218     -1.00     -1.00     -1.00      82  app

10:56:20 PM   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command
10:56:21 PM     0      3217     -1.00     -1.00     -1.00      95  app
10:56:21 PM     0      3218     -1.00     -1.00     -1.00     106  app

10:56:21 PM   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command
10:56:22 PM     0      3217     -1.00     -1.00     -1.00      71  app
10:56:22 PM     0      3218     -1.00     -1.00     -1.00      83  app

10:56:22 PM   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command
10:56:23 PM     0      3217     -1.00     -1.00     -1.00      17  app
10:56:23 PM     0      3218     -1.00     -1.00     -1.00      19  app

10:56:23 PM   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command
10:56:24 PM     0      3219     -1.00     -1.00     -1.00      30  app
10:56:24 PM     0      3220     -1.00     -1.00     -1.00      39  app

10:56:24 PM   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command
10:56:25 PM     0      3219     -1.00     -1.00     -1.00     100  app
10:56:25 PM     0      3220     -1.00     -1.00     -1.00      85  app

4.perf 调用查看 app 调用链情况

发现有直接磁盘读的调用: blkdev_direct_IO

$ perf record -g
$ perf report
+    8.86%     8.36%  kworker/0:1H-kb  [kernel.kallsyms]                   [k] mpt_put_msg_frame   ▒
-    7.52%     0.00%  app              [kernel.kallsyms]                   [k] entry_SYSCALL_64_aft▒
     entry_SYSCALL_64_after_hwframe                                                                ▒
   - do_syscall_64                                                                                 ▒
      - 7.43% __x64_sys_read                                                                       ▒
         - ksys_read                                                                               ▒
            - 7.43% vfs_read                                                                       ▒
               - 7.43% __vfs_read                                                                  ▒
                    new_sync_read                                                                  ▒
                    blkdev_read_iter                                                               ▒
                  - generic_file_read_iter                                                         ▒
                     - 7.43% blkdev_direct_IO                                                      ▒
                        - 7.43% __blkdev_direct_IO                                                 ▒
                           + 5.68% submit_bio                                                      ▒
                           + 1.34% bio_iov_iter_get_pages                                          ▒
+    7.52%     0.00%  app              [kernel.kallsyms]                   [k] do_syscall_64       ▒
+    7.52%     0.00%  app              libc-2.31.so                        [.] __libc_start_main   ▒
-    7.52%     0.00%  app              app                                 [.] main                ▒
   - main                                                                                          ▒
      + 7.43% read                                                                                 ▒
+    7.43%     0.00%  app              libc-2.31.so                        [.] read                ▒
+    7.43%     0.00%  app              [kernel.kallsyms]                   [k] __x64_sys_read      ▒
+    7.43%     0.00%  app              [kernel.kallsyms]                   [k] ksys_read           ▒
+    7.43%     0.00%  app              [kernel.kallsyms]                   [k] vfs_read            ▒
+    7.43%     0.00%  app              [kernel.kallsyms]                   [k] __vfs_read          ▒
+    7.43%     0.00%  app              [kernel.kallsyms]                   [k] new_sync_read       ▒
+    7.43%     0.00%  app              [kernel.kallsyms]                   [k] blkdev_read_iter    ▒
+    7.43%     0.00%  app              [kernel.kallsyms]                   [k] generic_file_read_it▒
+    7.43%     0.00%  app              [kernel.kallsyms]                   [k] blkdev_direct_IO    ▒
+    7.43%     0.00%  app              [kernel.kallsyms]                   [k] __blkdev_direct_IO  

app 的确在通过系统调用 sys_read() 读取数据。并且从 new_sync_read 和 blkdev_direct_IO 能看出,进程正在对磁盘进行直接读,也就是绕过了系统缓存,每个读请求都会从磁盘直接读,这就可以解释我们观察到的 iowait 升高了。

优化

直接读写磁盘,对 I/O 敏感型应用(比如数据库系统)是很友好的,因为你可以在应用中,直接控制磁盘的读写。但在大部分情况下,最好还是通过系统缓存来优化磁盘 I/O,因此一般的应用删除 O_DIRECT 这个选项可以。

DIR *dirptr = opendir("/dev/");
perror("Failed to open dir");
int fd = open(disk, O_RDONLY | O_DIRECT | O_LARGEFILE, 0755);
perror("failed to open disk");

总结

虽然这个案例是磁盘 I/O 导致了 iowait 升高,不过, iowait 高不一定代表 I/O 有性能瓶颈。当系统中只有 I/O 类型的进程在运行时,iowait 也会很高,但实际上,磁盘的读写远没有达到性能瓶颈的程度。

因此,碰到 iowait 升高时,

  • 需要先用 dstat、pidstat 等工具,确认是不是磁盘 I/O 的问题,
  • 然后再找是哪些进程导致了 I/O。等待 I/O 的进程一般是不可中断状态,
  • 用 ps 命令找到的 D 状态(即不可中断状态)的进程,多为可疑进程。
  • 当不能用strace 直接分析 进程的系统调用时,可以通过perf 工具分析cpu时钟事件,找到对应的调用消耗,在源码中对应的系统调用部分,即可定位到实际的问题。
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 214,776评论 6 496
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 91,527评论 3 389
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 160,361评论 0 350
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 57,430评论 1 288
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 66,511评论 6 386
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 50,544评论 1 293
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 39,561评论 3 414
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 38,315评论 0 270
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 44,763评论 1 307
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 37,070评论 2 330
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 39,235评论 1 343
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 34,911评论 5 338
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 40,554评论 3 322
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 31,173评论 0 21
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,424评论 1 268
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 47,106评论 2 365
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 44,103评论 2 352

推荐阅读更多精彩内容