如何分析系统不响应或响应慢

自己遇到过系统不响应和响应慢的情况，但一直不知道如何分析。今天看到一篇：磁盘I/O延迟很高怎么回事，瞬间给了我思路，现拿过来等下次分析实践下。

背景：访问应用的某个接口，长时间都没响应，究竟是怎么回事呢？

保障：为了避免分析过程中 curl 请求突然结束，把 curl 命令放到一个循环里执行，然后加一个 time 命令，观察每次的执行时间：

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

套路：

1) 首先观察 CPU 和内存的使用情况：使用top命令，如果CPU和内存占用高则分别分析。

2) CPU和内存不高的情况下，然后再观察磁盘的 I/O 情况：使用iostat命令。

2.1) 查看进程的磁盘 I/O 情况：使用的pidstat命令

2.2) 确定造成磁盘io高的进程是否频繁写文件：使用strace或filetop/opensnoopm命令

CPU和内存不高的案例分析

1) top观察CPU 和内存的使用情况

$ 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

$ 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 的升高有关。

2) iostat 命令观察磁盘的 I/O 情况

-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.00  463.55  13.86  98.40

以发现，磁盘 sda 的 I/O 使用率已经达到 98% ，接近饱和了。而且，写请求的响应时间高达 18 秒，每秒的写数据为 32 MB，显然写磁盘碰到了瓶颈。

3) 确定造成磁盘 I/O高的进程

那要怎么知道这些 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

4) 确定造成磁盘io高的进程是否在频繁写文件

方法4.1) 先用 strace 确认是不是在写文件，再用 lsof 找出文件描述符对应的文件。

$ 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 -p 12280 2>&1 | grep write

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

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

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

方法4.2) 从内核中查看文件的读写情况

作者介绍filetop工具。它是 bcc 软件包的一部分，基于 Linux 内核的 eBPF（extended  Berkeley Packet Filters）机制，主要跟踪内核中文件的读写情况，并输出线程 ID （TID）、读写大小、读写类型以及文件名称。bcc 的安装方法，参考它的 Github 网站 https://github.com/iovisor/bcc。

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

filetop 输出了 8 列内容，分别是线程 ID、线程命令行、读写次数、读写的大小（单位 KB）、文件类型以及读写的文件名称。

多观察一会儿，你就会发现，每隔一段时间，线程号为 514 的 python 应用就会先写入大量的 txt 文件，再大量地读。

线程号为 514 的线程，属于哪个进程呢？我们可以用 ps 命令查看。

$ ps -efT | grep 514

root    12280  514 14626 33 14:47 pts/0    00:00:05 /usr/local/bin/python /app.py

这个线程正是案例应用 12280 的线程。

作者又介绍另外一个工具：opensnoop 。它同属于 bcc 软件包，可以动态跟踪内核中的 open 系统调用。这样，我们就可以找出这些 txt 文件的路径。

$ 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 个文件。

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

总结

磁盘io高的案例中使用strace没找到write系统调用。

因为写文件是由子线程执行的，所以直接strace跟踪进程没有看到write系统调用，可以通过pstree查看进程的线程信息，再用strace跟踪。或者通过strace -fp pid 跟踪所有线程。

在strace -p PID后加上-f，多进程和多线程都可以跟踪。

strace -p -f可以查看进程的所有线程信息，本例中python进程下可能同时存在两个线程，一个线程是socket相关，一个是跟文件读写相关，与文件读写相关的会频繁变化，只需跟踪进程树的最后一个线程就可以。

可以用pstree -p 查看Python的进程树，然后strace -p 线程号，不过本例中线程消失非常快，需要写个脚本才行 比如：Python进程号是13205

strace -p `pstree -p 13205 | tail -n 1 | -F '(' '{print NF}' | awk -F ')' '{print1}'

还好我平常习惯用 `pidstat -wut 1` 既可以看上下文切换 又可以看cpu使用统计 还可以看各线程.

今天又见识到了两个工具:

filetop:可以查看进程操作的文件名称等信息

opensnoop:甚至连操作的文件路径也有.

看评论还知道了 strace 可以追逐子线程.

` strace -p 3387 -f 2>&1 | grep write `

这样之后就可以搜索到很多系统调用了.

不用那么麻烦吧，一般看用户进程cpu高的，iowait显著的话，直接lsof -p就能找到了什么文件了

我一般用strace -cp 来看系统调用的统计信息，然后用-e 查看对应调用的详情

使用strace时，没有加-f选项查看线程