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

最新推荐文章于 2023-12-01 14:05:29 发布

OceanStar的学习笔记

最新推荐文章于 2023-12-01 14:05:29 发布

阅读量3.1k

点赞数 1

分类专栏：计算机理论与基础文章标签： flask python 后端

原文链接：https://time.geekbang.org/

版权

计算机理论与基础专栏收录该内容

310 篇文章 69 订阅

订阅专栏

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

准备

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

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

在这里插入图片描述
接下来，打开两个终端，分别 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 和内存的使⽤情况：
在这里插入图片描述

观察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，
在这里插入图片描述
源码中可以看到，这个案例应用，在每个请求的处理过程中，都会生成一批临时文件，然后读入内存难处理，最后再把整个目录删除掉。

这是一种常见的利用磁盘空间处理大量数据的技巧。不过，这次案例中的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 树等各种算法，进⼀步优化单词处理的效率。

OceanStar的学习笔记

关注

1
点赞
踩
1

收藏

觉得还不错? 一键收藏
0
评论
基础：为什么磁盘IO延迟很高

这次案例是⼀个基于 Python Flask 框架的 Web 应⽤，它提供了⼀个查询单词热度的 API，但是API 的响应速度并不让⼈满意准备机器配置：2 CPU，8GB 内存预先安装 docker、sysstat 等⼯具，如 apt install docker.io sysstat今天的案例需要两台虚拟机，其中⼀台是案例分析的⽬标机器，运⾏ Flask 应⽤，它的 IP 地址是 192.168.0.10；⽽另⼀台作为客户端，请求单词的热度。如下所示：接下来，打开两个终端，分别 SSH
复制链接

扫一扫