为什么我的磁盘I/O延迟很高？

为什么我的磁盘I/O延迟很高？

实验案例：一个基于 Python Flask 框架的 Web 应用，它提供了一个查询单词热度的 API，但是 API 的响应速度并不让人满意。

一、案例准备

案例环境：

Ubuntu 18.04，同样适用于其他的Linux系统机器配置：2CPU、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 命令，访问 ​​​​curl 的输出界面里，看到一个 hello world 的输出：

$ curl hello world

接下来，在第二个终端中，访问案例应用的单词热度接口，也就是 curl 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% /

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

这里的思路其实跟上​​疯狂打日志案例​​比较类似，我们可以先用 top 来观察 CPU 和内存的使用情况，然后再用 iostat 来观察磁盘的 I/O 情况。

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

$ while true; do time curl sleep 1; done

继续回到终端一来分析性能。在终端一中运行 top 命令，观察 CPU 和内存的使用情况：

$ top top - 14:27:02 up 10:30, 1 user, load average: 1.82, 1.26, 0.76 Tasks: 129 total, 1 running, 74 sleeping, 0 stopped, 0 zombie %Cpu0 : 3.5 us, 2.1 sy, 0.0 ni, 0.0 id, 94.4 wa, 0.0 hi, 0.0 si, 0.0 st %Cpu1 : 2.4 us, 0.7 sy, 0.0 ni, 70.4 id, 26.5 wa, 0.0 hi, 0.0 si, 0.0 st KiB Mem : 8169300 total, 3323248 free, 436748 used, 4409304 buff/cache KiB Swap: 0 total, 0 free, 0 used. 7412556 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 12280 root 20 0 103304 28824 7276 S 14.0 0.4 0:08.77 python 16 root 20 0 0 0 0 S 0.3 0.0 0:09.22 ksoftirqd/1 1549 root 20 0 236712 24480 9864 S 0.3 0.3 3:31.38 python3

观察 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 1Device 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.00 463.55 13.86 98.40

从结果可以发现，磁盘 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​​​它是​​bcc​​软件包的一部分，基于Linux内核的eBPF（extended Berkeley Packet Filters）机制，主要跟踪内核中文件的读写情况，并输出线程 ID（TID）、读写大小、读写类型以及文件名称。

bcc安装方法，可以参考github网站​​​16以上版本，可以运行下面命令来安装：

sudo apt-key adv --keyserver keyserver.ubuntu.com --recv-keys 4052245BD4284CDD echo "deb -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 514root 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​​​

@app.route("/popularity/") def word_popularity(word): dir_path = '/tmp/{}'.format(uuid.uuid1()) count = 0 sample_size = 1000 def save_to_file(file_name, content): with open(file_name, 'w') as f: f.write(content) try: # initial directory firstly os.mkdir(dir_path) # save article to files for i in range(sample_size): file_name = '{}/{}.txt'.format(dir_path, i) article = generate_article() save_to_file(file_name, article) # count word popularity for root, dirs, files in os.walk(dir_path): for file_name in files: with open('{}/{}'.format(dir_path, file_name)) as f: if validate(word, f.read()): count += 1 finally: # clean files shutil.rmtree(dir_path, ignore_errors=True) return jsonify({'popularity': count / sample_size * 100, 'word': word})

​源码中可以看到，这个案例应用，在每个请求的处理过程中，都会生成一批临时文件，然后读入内存处理，最后再把整个目录删除掉。

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

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

​​可以检验一下，在终端二中分别访问 ​​​​和 ​​​​，对比前后的效果：

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

$ time curl "popularity": 0.0, "word": "word"}real 0m8.810suser 0m0.010ssys 0m0.000s

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

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

三

版权声明：本文内容由网络用户投稿，版权归原作者所有，本站不拥有其著作权，亦不承担相应法律责任。如果您发现本站中有涉嫌抄袭或描述失实的内容，请联系我们jiasou666@gmail.com 处理，核实后本网站将在24小时内删除侵权内容。