如何快速排查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命令来识别正在写入的线程和文件。

（全文完）

推荐阅读

除每周二、四、六定期更新的《Linux云计算一站式教程》以外，其余时间雷哥会推送一些工作中遇到的小知识、实战经验总结的文章。后续都会收录在“实战经验”合集中。