基础：为什么磁盘IO延迟很高

我就是我 2022-09-17 04:27 245阅读 0赞

这次案例是⼀个基于 Python Flask 框架的 Web 应⽤，它提供了⼀个查询单词热度的 API，  
但是API 的响应速度并不让⼈满意

## 准备 ##

*  机器配置：2 CPU，8GB 内存
 *  预先安装 docker、sysstat 等⼯具，如 apt install docker.io sysstat

今天的案例需要两台虚拟机，其中⼀台是案例分析的⽬标机器，运⾏ Flask 应⽤，它的 IP 地址是 192.168.0.10；⽽另⼀台作为客户端，请求单词的热度。如下所示：

![在这里插入图片描述][watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBAT2NlYW4mJlN0YXI_size_13_color_FFFFFF_t_70_g_se_x_16]  
接下来，打开两个终端，分别 SSH 登录到这两台虚拟机中，并在第⼀台虚拟机中，安装上述⼯具。

## 操作和分析 ##

⾸先，我们在第⼀个终端中执⾏下⾯的命令，运⾏本次案例要分析的⽬标应⽤：

$ docker run --name=app -p 10000:80 -itd feisky/word-pop

然后，在第⼆个终端中运⾏ curl 命令，访问 http://192.168.0.10:1000/，确认案例正常启动。你应该可以在 curl 的输出界⾯⾥，看到⼀个 hello world 的输出：

$ curl http://192.168.0.10:10000/
    hello world

接下来，在第⼆个终端中，访问案例应⽤的单词热度接⼝，也就是http://192.168.0.10:1000/popularity/word。

$ curl http://192.168.0.10:1000/popularity/word

稍等⼀会⼉，你会发现，这个接⼝居然这么⻓时间都没响应，究竟是怎么回事呢？我们先回到终端⼀来分析⼀下。

我们试试在第⼀个终端⾥，随便执⾏⼀个命令，⽐如执⾏ df 命令，查看⼀下⽂件系统的使⽤情况。奇怪的是，这么简单的命令，居然也要等好久才有输出。

$ df
    Filesystem 1K-blocks Used Available Use% Mounted on
    udev 4073376 0 4073376 0% /dev
    tmpfs 816932 1188 815744 1% /run
    /dev/sda1 30308240 8713640 21578216 29% /

通过fd我们知道，系统还有足够多的磁盘空间。那为什么响应会变慢呢？看来还是得观察一下，系统的资源使用情况，像是CPU、内存和磁盘IO等的具体使用情况。

我们可以先⽤ top 来观察 CPU 和内存的使⽤情况，然后再⽤ iostat 来观察磁盘的I/O 情况。

为了避免分析过程中curl 请求突然结束，我们回到终端⼆，按 Ctrl+C 停⽌刚才的应⽤程序；然后，把curl 命令放到⼀个循环⾥执⾏；这次我们还要加⼀个 time 命令，观察每次的执⾏时间：

$ while true; do time curl http://192.168.0.10:10000/popularity/word; sleep 1; done

继续回到终端⼀来分析性能。我们在终端⼀中运⾏ top 命令，观察 CPU 和内存的使⽤情况：  
![在这里插入图片描述][watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBAT2NlYW4mJlN0YXI_size_16_color_FFFFFF_t_70_g_se_x_16]

*  观察top的输出可以发现，两个CPU的iowait都非常高，特别是CPU0，iowait已经高达94%，而剩余内存还有3GB，看起来也是充足的。
 *  进程部分有一个python进程的CPU使用率有点高，达到了14%。虽然14%并不能成为性能瓶颈，不过优点嫌疑----可能跟iowait的升高有关

那这个PID 号为 12280 的 python 进程，到底是不是我们的案例应⽤呢？

我们在第⼀个终端中，按下 Ctrl+C，停⽌ top 命令；然后执⾏下⾯的 ps 命令，查找案例应⽤app.py 的 PID 号：

$ ps aux | grep app.py
    root 12222 0.4 0.2 96064 23452 pts/0 Ss+ 14:37 0:00 python /app.py
    root 12280 13.9 0.3 102424 27904 pts/0 Sl+ 14:37 0:09 /usr/local/bin/python /app.py

从 ps 的输出，你可以看到，这个 CPU 使⽤率较⾼的进程，正是我们的案例应⽤。不过先别着急分析 CPU 问题，毕竟 iowait已经⾼达 94%， I/O 问题才是我们⾸要解决的。

接下来，我们在终端⼀中，运⾏下⾯的 iostat 命令，其中:

*  \-d 选项是指显示出 I/O 的性能指标；
 *  \-x 选项是指显示出扩展统计信息（即显示所有I/O指标）。

$ iostat -d -x 1
    Device r/s w/s rkB/s wkB/s rrqm/s wrqm/s %rrqm %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm %util
    loop0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
    sda 0.00 71.00 0.00 32912.00 0.00 0.00 0.00 0.00 0.00 18118.31 241.89 0.0

*  具体观察 iostat 的输出。你可以发现，磁盘 sda 的 I/O 使⽤率已经达到 98% ，接近饱和了。
 *  ⽽且，写请求的响应时间⾼达 18 秒，每秒的写数据为 32 MB，显然写磁盘碰到了瓶颈。

那要怎么知道，这些 I/O请求到底是哪些进程导致的呢？可以在在终端⼀中，运⾏下⾯的 pidstat 命令，观察进程的 I/O 情况：

$ pidstat -d 1
    14:39:14 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
    14:39:15 0 12280 0.00 335716.00 0.00 0 python

从 pidstat 的输出，我们再次看到了PID 号为 12280的结果。这说明，正是案例应⽤引发I/O 的性能瓶颈。

⾛到这⼀步，你估计觉得，接下来就很简单了，上⼀个案例不刚刚学过吗？⽆⾮就是，先⽤ strace 确认它是不是在写⽂件，再⽤ lsof 找出⽂件描述符对应的⽂件即可。

到底是不是这样呢？我们不妨来试试。还是在终端⼀中，执⾏下⾯的 strace 命令：

$ strace -p 12280
    strace: Process 12280 attached
    select(0, NULL, NULL, NULL, {
        tv_sec=0, tv_usec=567708}) = 0 (Timeout)
    stat("/usr/local/lib/python3.7/importlib/_bootstrap.py", {
        st_mode=S_IFREG|0644, st_size=39278, ...}) = 0
    stat("/usr/local/lib/python3.7/importlib/_bootstrap.py", {
        st_mode=S_IFREG|0644, st_size=39278, ...}) = 0

*  从strace，可以看到大量的stat系统调用，并且大都为python的文件
 *  但是，这里并没有任何write系统调用

由于 strace 的输出⽐较多，我们可以⽤ grep ，来过滤⼀下 write，⽐如：

$ strace -p 12280 2>&1 | grep write

遗憾的是，这⾥仍然没有任何输出。

难道此时已经没有性能问题了吗？重新执⾏刚才的 top 和 iostat 命令，你会不幸地发现，性能问题仍然存在。

我们只好综合 strace、pidstat 和 iostat 这三个结果来分析了。很明显，你应该发现了这⾥的⽭盾：iostat 已经证明磁盘 I/O 有性能瓶颈，⽽ pidstat 也证明了，这个瓶颈是由 12280 号进程导致的，但 strace 跟踪这个进程，却没有找到任何 write 系统调⽤。

> 这就奇怪了。难道因为案例使⽤的编程语⾔是 Python ，⽽Python 是解释型的，所以找不到？还是说，因为案例运⾏在Docker 中呢？

文件写，明明应该有相应的write系统调用，但用现有工具却找不到痕迹，这时就该想想换⼯具的问题了。怎样才能知道哪⾥在写⽂件呢？

*  可以使用filetop。file是bcc软件包的一部分，基于Linux内核的eBPF机制，主要跟踪内核中文件的读写情况，并输出线程ID（TID）、读写⼤⼩、读写类型以及⽂件名称。
 *  ⾄于bcc 的安装⽅法，可以参考它的 Github ⽹站https://github.com/iovisor/bcc。⽐如在 Ubuntu 16 以上的版本中，你可以运⾏下⾯的命令来安装它

sudo apt-key adv --keyserver keyserver.ubuntu.com --recv-keys 4052245BD4284CDD
    echo "deb https://repo.iovisor.org/apt/$(lsb_release -cs) $(lsb_release -cs) main" | sudo tee /etc/apt/sources.list.d/iovisor.list
    sudo apt-get update
    sudo apt-get install bcc-tools libbcc-examples linux-headers-$(uname -r)

安装后，bcc 提供的所有⼯具，就全部安装到了 /usr/share/bcc/tools 这个⽬录中。接下来我们就⽤这个⼯具，观察⼀下⽂件的读写情况。

⾸先，在终端⼀中运⾏下⾯的命令：

# 切换到⼯具⽬录
    $ cd /usr/share/bcc/tools
    # -C 选项表示输出新内容时不清空屏幕
    $ ./filetop -C
    TID COMM READS WRITES R_Kb W_Kb T FILE
    514 python 0 1 0 2832 R 669.txt
    514 python 0 1 0 2490 R 667.txt
    514 python 0 1 0 2685 R 671.txt
    514 python 0 1 0 2392 R 670.txt
    514 python 0 1 0 2050 R 672.txt
    ...
    TID COMM READS WRITES R_Kb W_Kb T FILE
    514 python 2 0 5957 0 R 651.txt
    514 python 2 0 5371 0 R 112.txt
    514 python 2 0 4785 0 R 861.txt
    514 python 2 0 4736 0 R 213.txt
    514 python 2 0 4443 0 R 45.txt

*  你会看到，filetop 输出了 8 列内容，分别是线程ID、线程命令⾏、读写次数、读写的⼤⼩（单位KB）、⽂件类型以及读写的⽂件名称。
 *  这些内容⾥，你可能会看到很多动态链接库，不过这不是我们的重点，暂且忽略即可。我们的重点，是⼀个 python 应⽤，所以要特别关注 python 相关的内容。
 *  多观察⼀会⼉，你就会发现，每隔⼀段时间，线程号为 514 的 python 应⽤就会先写⼊⼤量的 txt ⽂件，再⼤量地读。

线程号为 514 的线程，属于哪个进程呢？我们可以⽤ ps 命令查看。先在终端⼀中，按下 Ctrl+C ，停⽌ filetop ；然后，运⾏下⾯的 ps 命令。这个输出的第⼆列内容，就是我们想知道的进程号：

$ ps -efT | grep 514
    root 12280 514 14626 33 14:47 pts/0 00:00:05 /usr/local/bin/python /app.py

我们看到，这个线程正是案例应⽤ 12280的线程。不过还没完，filetop 只给出了⽂件名称，却没有⽂件路径，应该怎么找文件路径呢？

*  通过opensnoop 。它同属于 bcc 软件包，可以动态跟踪内核中的 open 系统调⽤。。这样，我们就可以找出这些 txt ⽂件的路径

接下来，在终端⼀中，运⾏下⾯的 opensnoop 命令：

$ opensnoop
    12280 python 6 0 /tmp/9046db9e-fe25-11e8-b13f-0242ac110002/650.txt
    12280 python 6 0 /tmp/9046db9e-fe25-11e8-b13f-0242ac110002/651.txt
    12280 python 6 0 /tmp/9046db9e-fe25-11e8-b13f-0242ac110002/652.txt

这次，通过 opensnoop 的输出，你可以看到，这些 txt 路径位于 /tmp ⽬录下。你还能看到，它打开的⽂件数量，按照数字编号，从 0.txt 依次增⼤到 999.txt，这可远多于前⾯⽤ filetop 看到的数量。

综合 filetop 和 opensnoop ，我们就可以进⼀步分析了。我们可以⼤胆猜测，案例应⽤在写⼊ 1000 个txt⽂件后，⼜把这些内容读到内存中进⾏处理。我们来检查⼀下，这个⽬录中是不是真的有 1000 个⽂件：

$ ls /tmp/9046db9e-fe25-11e8-b13f-0242ac110002 | wc -l
    ls: cannot access '/tmp/9046db9e-fe25-11e8-b13f-0242ac110002': No such file or directory
    0

操作后却发现，⽬录居然不存在了。怎么回事呢？我们回到 opensnoop 再观察⼀会⼉：

$ opensnoop
    12280 python 6 0 /tmp/defee970-fe25-11e8-b13f-0242ac110002/261.txt
    12280 python 6 0 /tmp/defee970-fe25-11e8-b13f-0242ac110002/840.txt
    12280 python 6 0 /tmp/defee970-fe25-11e8-b13f-0242ac110002/136.txt

原来，这时的路径已经变成了另⼀个⽬录。这说明，这些⽬录都是应⽤程序动态⽣成的，⽤完就删了。

结合前⾯的所有分析，我们基本可以判断，案例应⽤会动态⽣成⼀批⽂件，⽤来临时存储数据，⽤完就会删除它们。但不幸的是，正是这些⽂件读写，引发了 I/O 的性能瓶颈，导致整个处理过程⾮常慢。

当然，我们还需要验证这个猜想。⽼办法，还是查看应⽤程序的源码 app.py，  
![在这里插入图片描述][watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBAT2NlYW4mJlN0YXI_size_14_color_FFFFFF_t_70_g_se_x_16]  
源码中可以看到，这个案例应用，在每个请求的处理过程中，都会生成一批临时文件，然后读入内存难处理，最后再把整个目录删除掉。

这是一种常见的利用磁盘空间处理大量数据的技巧。不过，这次案例中的IO请求太重，导致磁盘IO利用率过高。

要解决这⼀点，其实就是算法优化问题了。⽐如在内存充⾜时，就可以把所有数据都放到内存中处理，这样就能避免 I/O 的性能问题。

你可以检验⼀下，在终端⼆中分别访问http://192.168.0.10:10000/popularity/word 和 http://192.168.0.10:10000/popular/word，对⽐前后的效果：

$ time curl http://192.168.0.10:10000/popularity/word
    {
        
    "popularity": 0.0,
    "word": "word"
    }
    real 2m43.172s
    user 0m0.004s
    sys 0m0.007s

$ time curl http://192.168.0.10:10000/popular/word
    {
        
    "popularity": 0.0,
    "word": "word"
    }
    real 0m8.810s
    user 0m0.010s
    sys 0m0.000s

新的接⼝只要8秒就可以返回，明显⽐⼀开始的 3 分钟好很多。

当然，这只是优化的第⼀步，并且⽅法也不算完善，还可以做进⼀步的优化。不过，在实际系统中，我们⼤都是类似的做法，先⽤最简单的⽅法，尽早解决线上问题，然后再继续思考更好的优化⽅法。

## 小结 ##

今天，我们分析了⼀个响应过慢的单词热度案例。

⾸先，我们⽤ top、iostat，分析了系统的 CPU 和磁盘使⽤情况。我们发现了磁盘 I/O 瓶颈，也知道了这个瓶颈是案例应⽤导致的。

接着，我们试着照搬上⼀节案例的⽅法，⽤ strace 来观察进程的系统调⽤，不过这次很不⾛运，没找到任何 write 系统调⽤。

于是，我们⼜⽤了新的⼯具，借助动态追踪⼯具包 bcc 中的 filetop 和 opensnoop ，找出了案例应⽤的问题，发现这个根源是⼤量读写临时⽂件。

找出问题后，优化⽅法就相对⽐较简单了。如果内存充⾜时，最简单的⽅法，就是把数据都放在速度更快的内存中，这样就没有磁盘 I/O 的瓶颈了。当然，再进⼀步，你可以还可以利⽤ Trie 树等各种算法，进⼀步优化单词处理的效率。

[watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBAT2NlYW4mJlN0YXI_size_13_color_FFFFFF_t_70_g_se_x_16]: /images/20220828/7e3c3433475f41b390201d24fd0bde91.png
[watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBAT2NlYW4mJlN0YXI_size_16_color_FFFFFF_t_70_g_se_x_16]: /images/20220828/09fe26545d4943aca9de9bd0e6dcb674.png
[watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBAT2NlYW4mJlN0YXI_size_14_color_FFFFFF_t_70_g_se_x_16]: /images/20220828/d2efab19986543fda9ed736214de1adf.png