菜鸟笔记
提升您的技术认知

Linux性能优化实战之iowait分析

阅读 : 3963

一、环境准备

1、在第6节的基础上安装dstat

wget http://mirror.centos.org/centos/7/os/x86_64/Packages/dstat-0.7.2-12.el7.noarch.rpm
rpm -ivh dstat-0.7.2-12.el7.noarch.rpm  

2、故障现象

# 按下数字 1 切换到所有 CPU 的使用情况,观察一会儿按 Ctrl+C 结束
$ top
top - 05:56:23 up 17 days, 16:45,  2 users,  load average: 2.00, 1.68, 1.39
Tasks: 247 total,   1 running,  79 sleeping,   0 stopped, 115 zombie
%Cpu0  :  0.0 us,  0.7 sy,  0.0 ni, 38.9 id, 60.5 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu1  :  0.0 us,  0.7 sy,  0.0 ni,  4.7 id, 94.6 wa,  0.0 hi,  0.0 si,  0.0 st
...

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 4340 root      20   0   44676   4048   3432 R   0.3  0.0   0:00.05 top
 4345 root      20   0   37280  33624    860 D   0.3  0.0   0:00.01 app
 4344 root      20   0   37280  33624    860 D   0.3  0.4   0:00.01 app
    1 root      20   0  160072   9416   6752 S   0.0  0.1   0:38.59 systemd
...

①iowait太高,导致平均负载升高,并且达到了系统CPU的个数
②僵尸进程不断增多

二、iowait升高的原因分析

1、用dstat 命令同时查看cpu和i/o对比情况

(如 dstat 1 10 间隔1秒输出10组数据),通过结果可以发现iowait升高时,磁盘读请求(read)升高所以推断iowait升高是磁盘读导致

# 间隔 1 秒输出 10 组数据
$ dstat 1 10
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
  0   0  96   4   0|1219k  408k|   0     0 |   0     0 |  42   885
  0   0   2  98   0|  34M    0 | 198B  790B|   0     0 |  42   138
  0   0   0 100   0|  34M    0 |  66B  342B|   0     0 |  42   135
  0   0  84  16   0|5633k    0 |  66B  342B|   0     0 |  52   177
  0   3  39  58   0|  22M    0 |  66B  342B|   0     0 |  43   144
  0   0   0 100   0|  34M    0 | 200B  450B|   0     0 |  46   147
  0   0   2  98   0|  34M    0 |  66B  342B|   0     0 |  45   134
  0   0   0 100   0|  34M    0 |  66B  342B|   0     0 |  39   131
  0   0  83  17   0|5633k    0 |  66B  342B|   0     0 |  46   168
  0   3  39  59   0|  22M    0 |  66B  342B|   0     0 |  37   134

实际测试截图如下

2、定位磁盘读的进程

使用top命令查看处于不可中断状态(D)的进程PID

# 观察一会儿按 Ctrl+C 结束
$ top
...
  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 4340 root      20   0   44676   4048   3432 R   0.3  0.0   0:00.05 top
 4345 root      20   0   37280  33624    860 D   0.3  0.0   0:00.01 app
 4344 root      20   0   37280  33624    860 D   0.3  0.4   0:00.01 app
...

实际测试截图

3、查看对应进程的磁盘读写情况

使用pidstat命令,加上-d参数,可以看到i/o使用情况(如 pidstat -d -p 1 3),发现处于不可中断状态的进程都没有进行磁盘读写

# -d 展示 I/O 统计数据,-p 指定进程号,间隔 1 秒输出 3 组数据
$ pidstat -d -p 4344 1 3
06:38:50      UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command
06:38:51        0      4344      0.00      0.00      0.00       0  app
06:38:52        0      4344      0.00      0.00      0.00       0  app
06:38:53        0      4344      0.00      0.00      0.00       0  app

实际测试截图

4、使用pidstat命令查看所有进程的i/o情况

但是去掉进程号,查看所有进程的i/o情况(pidstat -d 1 20),可以定位到进行磁盘读写的进程。我们知道进程访问磁盘,需要使用系统调用,
下面的重点就是找到该进程的系统调用

# 间隔 1 秒输出多组数据 (这里是 20 组)
$ pidstat -d 1 20
...
06:48:46      UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command
06:48:47        0      4615      0.00      0.00      0.00       1  kworker/u4:1
06:48:47        0      6080  32768.00      0.00      0.00     170  app
06:48:47        0      6081  32768.00      0.00      0.00     184  app

06:48:47      UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command
06:48:48        0      6080      0.00      0.00      0.00     110  app

06:48:48      UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command
06:48:49        0      6081      0.00      0.00      0.00     191  app

06:48:49      UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command

06:48:50      UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command
06:48:51        0      6082  32768.00      0.00      0.00       0  app
06:48:51        0      6083  32768.00      0.00      0.00       0  app

06:48:51      UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command
06:48:52        0      6082  32768.00      0.00      0.00     184  app
06:48:52        0      6083  32768.00      0.00      0.00     175  app

06:48:52      UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command
06:48:53        0      6083      0.00      0.00      0.00     105  app
...

实际测试命令如下

[root@luoahong ~]# pidstat -d 1 20
Linux 3.10.0-957.5.1.el7.x86_64 (luoahong)  05/05/2019  _x86_64_    (2 CPU)

11:01:21 AM   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command

11:01:22 AM   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command
11:01:23 AM     0     12174  82431.50      0.00      0.00       0  app
11:01:23 AM     0     12175  30207.50      0.00      0.00       0  app
......

11:01:35 AM   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command

11:01:36 AM   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command

11:01:37 AM   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command
11:01:38 AM     0     12180  47103.50      0.00      0.00       0  app
11:01:38 AM     0     12181  37375.50      0.00      0.00       0  app

11:01:38 AM   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command
11:01:39 AM     0     12180 768512.00      0.00      0.00      51  app
11:01:39 AM     0     12181 552448.50      0.00      0.00      49  app
......
Average:        0     12179  65307.42      0.00      0.00       0  app
Average:        0     12180  65307.42      0.00      0.00      28  app
Average:        0     12181  65307.42      0.00      0.00      29  app

5、使用strace查看进程的系统调用 strace -p

strace -p 6082
strace: attach: ptrace(PTRACE_SEIZE, 6082): Operation not permitted

实际测试截图

发现报了 strace:attach :ptrace(PTRACE_SIZE,6028):Operation not peritted,说没有权限,我是使用的root权限,所以这个时候就要查看进程的状态是否正常

6、ps aux | grep 发现进程处于Z状态,已经变成了僵尸进程

所以不能进行系统调用分析了

ps aux | grep 6082
root      6082  0.0  0.0      0     0 pts/0    Z+   13:43   0:00 [app] 

实际测试截图

7、既然top和pidstat都不能找出问题,使用基于事件记录的动态追踪工具

perf record -g
$ perf report

要是你是centos系统,在容器外面把分析记录保存,到容器里面查看结果
操作:
(1)在centos系统上运行 perf record -g ,执行一会儿按ctrl+c停止
(2)把生成的perf.data(通常文件生成在命令执行的当前目录下,当然可以通过find | grep perf.data或 find / -name perf.data查看路径)文件拷贝到容器里面分析:

docker cp perf.data app:/tpm
docker exec -i -t app bash
cd /tmp/
apt-get update && apt-get install -y linux-perf linux-tools procps
perf_4.9 report

8、看来罪魁祸首是app内部进行了磁盘的直接I/O啊!

open(disk, O_RDONLY|O_DIRECT|O_LARGEFILE, 0755)

然后观察调用栈信息,检查是否有磁盘读操作,这个案例是定位到了进行磁盘的直接读,当然也可以查看源码进行验证。因为我的centos系统用老师的 iowait镜像iowait升高不明显,所以使用的是iowait-new2镜像,可以得到想要的结果,但是这个镜像把我的系统能搞崩溃,所以我只能执行到cd /tmp/这步,下面那部就执行不下去了。但是整个分析过程还是理解了。

三、iowait升高解决方案

1、运行修改后的镜像包

# 首先删除原来的应用
$ docker rm -f app
# 运行新的应用
$ docker run --privileged --name=app -itd feisky/app:iowait-fix1

2、在用top查看一下

top
top - 14:59:32 up 19 min,  1 user,  load average: 0.15, 0.07, 0.05
Tasks: 545 total,   1 running, 130 sleeping,   0 stopped, 414 zombie
%Cpu(s):  0.3 us, 25.9 sy,  0.0 ni, 65.5 id,  0.5 wa,  0.0 hi,  7.7 si,  0.0 st
KiB Mem :  8056840 total,  6620396 free,   686076 used,   750368 buff/cache
KiB Swap:  2097148 total,  2097148 free,        0 used.  7029968 avail Mem

   PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 12967 root      20   0       0      0      0 Z  35.2  0.0   0:01.28 app
 12968 root      20   0       0      0      0 Z  31.6  0.0   0:01.20 app
 12961 root      20   0  162416   2728   1596 R   1.3  0.0   0:00.26 top
  7473 root      20   0  227160   6356   4944 S   0.3  0.1   0:14.91 vmtoolsd
  9369 root      20   0  851800  64620  25608 S   0.3  0.8   0:11.29 dockerd
  9379 root      20   0  452964  36060  15040 S   0.3  0.4   0:12.83 containerd
  9779 mysql     20   0 1119708 186364   5796 S   0.3  2.3   0:14.60 mysqld
 10061 polkitd   20   0 1267680 210772   9336 S   0.3  2.6   0:15.74 mysqld
 11341 root      20   0       0      0      0 S   0.3  0.0   0:06.97 kworker/0:1
     1 root      20   0   43640   3952   2552 S   0.0  0.0   0:03.90 systemd

四、僵尸进程分析

1、找出父进程、然后在父进程里解决

# -a 表示输出命令行选项
# p 表 PID
# s 表示指定进程的父进程
[root@luoahong ~]# pstree -aps 12582
systemd,1 --switched-root --system --deserialize 22
  └─containerd,9379
      └─containerd-shim,12484 -namespace moby -workdir...
          └─app,12502
              └─(app,12582

2、查看修复后的源码文件

int status = 0;
  for (;;) {
    for (int i = 0; i < 2; i++) {
      if(fork()== 0) {
        sub_process();
      }
    }
    sleep(5);
  }

  while(wait(&status)>0);

五、僵尸进程解决方案

1、运行修复后文件打包的镜像

# 先停止产生僵尸进程的 app
$ docker rm -f app
# 然后启动新的 app
$ docker run --privileged --name=app -itd feisky/app:iowait-fix2

2、top命令查看

top
top - 13:36:25 up  2:27,  2 users,  load average: 0.44, 0.23, 0.11
Tasks: 134 total,   2 running, 132 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0.0 us, 12.5 sy,  0.0 ni, 83.2 id,  0.7 wa,  0.0 hi,  3.6 si,  0.0 st
KiB Mem :  8056840 total,  5975080 free,   832016 used,  1249744 buff/cache
KiB Swap:  2097148 total,  2097148 free,        0 used.  6880292 avail Mem
...

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 3198 root      20   0    4376    840    780 S   0.3  0.0   0:00.01 app
    2 root      20   0       0      0      0 S   0.0  0.0   0:00.00 kthreadd
    3 root      20   0       0      0      0 I   0.0  0.0   0:00.41 kworker/0:0
...

僵尸进程出现的原因是父进程没有回收子进程的资源出现的。解决办法是找到父进程,在父进程中处理,使用pstree查父进程,然后查看父进程的源码检查wait()/waitpid()的调用或SIGCHLD信号处理函数的注册