如何快速排查Linux磁盘IO故障
在我之前的文章中，谈到了“Linux 的磁盘 I/O 性能监测”，让我们今天做一些练习，并享受高磁盘 I/O 故障排除用例的乐趣。
案例准备
我们在 Linux 主机上运行以下 docker 容器来模拟磁盘 I/O 场景：
$ docker run --name=app -p 80:80 -itd tonylixu/word-pop
9bc4614419bc606064b3d35c5ba86be3fb55617dcd0e61791b4326f6df7c8c37
$ docker ps
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
9bc4614419bc feisky/word-pop "python /app.py" 6 minutes ago Up 6 minutes 0.0.0.0:80->80/tcp, :::80->80/tcp app
容器启动运行后，我们使用curl命令访问 url “http://127.0.0.1”：
$ curl http://127.0.0.1
hello world
我们可以看到实例正常启动。现在我们确认一下：
$ time curl http://127.0.0.1/popularity/word
{
"popularity": 0.0,
"word": "word"
}
real 0m44.134s
user 0m0.000s
sys 0m0.008s
从上面的输出你可以看到它用44秒来获取结果！这是怎么回事？为什么查询需要这么长时间？
案例疑难解答
您可能认为它与网络有关，但在我们深入研究之前，我们使用top命令来观察系统性能：
查看top的输出，可以看到两个CPU的iowait都很高【上图的wa指标】。尤其是CPU1，iowait已经达到了80%，还有2.2GB的剩余内存，似乎已经足够了。
再往下看，进程部分PID为3920的python进程的CPU使用率略高，达到28%。虽然 28% 不是性能瓶颈，但有点可疑——可能与iowait有关。
我们执行一下ps命令：
$ ps aux | grep 3920
root 3920 13.1 0.7 103860 29232 pts/0 Sl+ 15:14 2:46 /usr/local/bin/python /app.py
从 ps 的输出可以看出，这个 CPU 使用率很高的进程正是我们的案例应用。但是先不要急于分析CPU问题，因为此时CPU使用率并不高，iowait已经达到90%是我们应该首先要解决的。
接下来，让我们使用iostat命令继续我们的 I/O 分析：
-
-d: I/O 性能指标
-
-x：显示扩展统计信息
从iostat的输出结果，我们观察到wKB/s相当高，62MB/秒，磁盘xvda的 I/O 使用率为100%。显然，磁盘IO已经饱和。此外，发出的写请求的平均队列长度为 34.85，也是一个很高的数字。
所以现在的问题是，我们如何知道哪个进程导致了 I/O 问题？我们有一个可疑的 PID 为 3920 的 Python 进程，但是我们如何确保 Python 进程就是占用了大部分IO呢？
让我们pidstat来检查一下进程：
从上面的输出中，我们可以看出是 3920 Python 进程造成了 I/O 性能瓶颈。
此时，就简单了。我们可以直接用strace来确认是否在写文件，然后用lsof来查找文件描述符对应的文件。然后我们修复我们的代码并重新部署应用程序。
想法没问题，让我们尝试一下：
$ strace -p 3920 2>&1 | grep write
...hangs
遗憾的是，没有与任何write系统调用相关的输出。这时，你可能会问，这是怎么回事？为什么根本没有write系统调用？如果没有write系统调用，这个进程 3920 怎么会导致 I/O 问题？这不是很奇怪吗？
对于文件写入，应该有相应的write系统调用，但是用现有的工具找不到。这时候就该考虑换工具的问题了。我怎么知道文件被写在哪里？
让我们使用filetop工具（https://github.com/iovisor/bcc/blob/master/tools/filetop.py），一个用于跟踪内核中文件读写的新工具。您可以上面的链接中找到安装说明。
安装后，让我们运行filetop：
$ filetop -C
15:57:06 loadavg: 2.22 2.20 1.77 1/193 21777
TID COMM READS WRITES R_Kb W_Kb T FILE
21776 python 0 1 0 4882 R 594.txt
21776 python 0 1 0 4736 R 583.txt
21776 python 0 1 0 4589 R 582.txt
21776 python 0 1 0 4394 R 580.txt
21776 python 0 1 0 3857 R 576.txt
21776 python 0 1 0 3808 R 592.txt
21776 python 0 1 0 3271 R 579.txt
21776 python 0 1 0 2978 R 593.txt
21776 python 0 1 0 2929 R 575.txt
21776 python 0 1 0 2929 R 573.txt
21776 python 0 1 0 2880 R 577.txt
21776 python 0 1 0 2832 R 586.txt
21776 python 0 1 0 2587 R 574.txt
21776 python 0 1 0 2441 R 578.txt
21776 python 0 1 0 2441 R 587.txt
21776 python 0 1 0 2392 R 585.txt
21776 python 0 1 0 2343 R 590.txt
21776 python 0 1 0 2294 R 591.txt
21776 python 0 1 0 2246 R 572.txt
21776 python 0 1 0 2246 R 584.txt
....
你会看到filetop输出了8列，分别是线程ID、线程命令行、读写次数、读写大小（KB）、文件类型、读写的文件名。
观察一会你会发现，每隔一段时间，线程号为21776的python应用就会先写入大量的txt文件，然后再大量读取。
线程号 21776 的线程属于哪个进程？我们可以使用以下ps命令进行检查：
$ ps -efT | grep 21776
root 3920 21776 3888 30 15:59 pts/0 00:00:07 /usr/local/bin/python /app.py
我们看到这个线程正是案例应用程序 3920 的线程。
现在我们如何知道它正在写入哪个文件？
我们可以使用opensnoop（https://github.com/iovisor/bcc/blob/master/tools/opensnoop.py）命令：
PID COMM FD ERR PATH
3920 python 6 0 /tmp/2ec58410-919d-11ec-aa6a-0242ac110002/657.txt
3920 python 6 0 /tmp/2ec58410-919d-11ec-aa6a-0242ac110002/658.txt
3920 python 6 0 /tmp/2ec58410-919d-11ec-aa6a-0242ac110002/659.txt
3920 python 6 0 /tmp/2ec58410-919d-11ec-aa6a-0242ac110002/660.txt
3920 python 6 0 /tmp/2ec58410-919d-11ec-aa6a-0242ac110002/661.txt
3920 python 6 0 /tmp/2ec58410-919d-11ec-aa6a-
...
3920 python 6 0 /tmp/2ec58410-919d-11ec-aa6a-0242ac110002/667.txt
3920 python 6 0 /tmp/2ec58410-919d-11ec-aa6a-0242ac110002/668.txt
3920 python 6 0 /tmp/2ec58410-919d-11ec-aa6a-0242ac110002/669.txt
3920 python 6 0 /tmp/2ec58410-919d-11ec-aa6a-0242ac110002/670.txt
通过opensnoop的输出，我们基本可以判断python应用会动态生成一批文件来临时存储数据，用完就删除，导致处理很慢。
我们检查一下ppy.py内容：
$ docker cp 9bc4614419bc:app.py ./
$ cat app.y
@app.route("/popularity/<word>")
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 延迟的情况进行了故障排除。首先，我们使用top和iostat命令分析了系统的 CPU 和磁盘使用情况。我们找到了磁盘I/O瓶颈，也知道瓶颈是由案例应用造成的。
接下来，我们使用strace观察系统调用和filetop+opensnoop命令来识别正在写入的线程和文件。
（全文完）
推荐阅读
干货 | PXE+kickstart无人值守批量装机（原理与架构）
干货 | PXE+kickstart无人值守批量装机（实战部署）
ifconfig已淘汰，ip登场
40个简单而有效的Shell脚本，想不起来的时候一看就懂（下）Linux 云计算 学习路线（建议收藏）放后台的Linux任务没有了，试试这个命令
Linux 网络状态工具 ss 命令详解
这次终于搞明白VLAN技术了
除每周二、四、六定期更新的《Linux云计算一站式教程》以外，其余时间雷哥会推送一些工作中遇到的小知识、实战经验总结的文章。后续都会收录在“实战经验”合集中。