前言：
有关于磁盘IO过高导致CPU iowait比较高的问题，笔者一直没有在产线遇到过。
所以想去通过写代码来模拟这个操作，但是无奈笔者的Mac机器性能太强了，所以一直压不出来想要的效果。
既然有些效果没法出来，我们就先方法论一下，先用工具了解当前服务及进程的状态，然后逐个分析。
准备工作：
1.代码准备，（笔者会在最后贴出，模拟写磁盘动作），最终打成war包，在docker tomcat中启动
2.工具准备，需要的验证工具，iostat、strace、lsof、pidstat，需要提前安装好
1.问题排查全过程
启动docker tomcat后，在发起http请求后，验证I/O情况
1.1 top查看进程基本情况
top - 01:45:17 up 1 day, 1:27, 0 users, load average: 0.23, 0.10, 0.07
Tasks: 5 total, 0 running, 4 sleeping, 0 stopped, 0 zombie
%Cpu(s): 24.7 us, 1.5 sy, 0.0 ni, 73.5 id, 0.2 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem: 2036420 total, 2004040 used, 32380 free, 23924 buffers
KiB Swap: 1048572 total, 117648 used, 930924 free. 716924 cached Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
1 root 20 0 3046980 821692 5948 S 102.2 40.3 0:57.69 java
54 root 20 0 169404 10112 3020 S 0.0 0.5 0:00.13 bash
62 root 20 0 169212 10508 3000 S 0.0 0.5 0:00.06 bash
74 root 20 0 297616 14220 5328 S 0.0 0.7 0:00.08 curl
79 root 0 0 170660 9752 3176 0 0.0 0.5 0:00.00 top 可以看到PID=1的进程，CPU使用率102%，内存使用率40.3%。这时只能看出CPU使用率高，还不知道具体问题
注意：
实际正常的话，应该能看到%Cpu(s)行的 wa（也就是wait）会很高，能很明确的看出是IO的相关问题
笔者这里代码没有模拟出来
1.2 iostat查看磁盘io信息
root@91230cc467cc:/tmp# iostat -x -d -m 3
Linux 5.10.76-linuxkit (91230cc467cc) 03/28/22 _x86_64_ (4 CPU)
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
vda 0.56 3.56 2.93 1.12 0.09 0.51 305.35 0.00 0.54 0.17 1.48 0.40 0.16
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
vda 0.00 14.00 4.33 262.67 0.06 259.60 1991.67 0.35 1.32 1.15 1.32 0.23 6.17
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
vda 0.00 15.00 1.33 308.00 0.01 308.06 2039.62 0.78 2.10 0.25 2.10 0.26 8.07
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
vda 0.00 6.67 2.00 259.00 0.01 258.58 2029.08 0.36 1.38 0.17 1.38 0.24 6.23
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
vda 0.00 14.67 3.00 297.67 0.01 302.69 2061.84 0.71 1.95 0.44 1.97 0.24 7.33
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
vda 0.00 14.33 3.33 271.33 0.02 271.52 2024.68 0.37 1.33 0.30 1.34 0.21 5.90由于笔者的Mac磁盘比较强劲，所以这了的%util不算很高。
但是可以很明显的看出来wMB/s，每秒的写达到了271M，这个还是很高的。
我们需要找出是哪个进程在做这种写操作。
1.3 pidstat查看进程信息
root@91230cc467cc:/usr/local/tomcat# pidstat -d 2
Linux 5.10.76-linuxkit (91230cc467cc) 03/28/22 _x86_64_ (4 CPU)
02:28:02 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
02:28:04 0 1 0.00 307232.00 0.00 0 java
02:28:04 0 72 0.00 2.00 2.00 0 pidstat
02:28:04 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
02:28:06 0 1 11.94 254752.24 0.00 0 java
02:28:06 0 72 0.00 1.99 1.99 0 pidstat
02:28:06 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
02:28:08 0 1 0.00 307242.00 0.00 0 java
02:28:08 0 72 0.00 2.00 2.00 0 pidstat
02:28:08 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
02:28:10 0 1 0.00 307240.00 0.00 0 java
02:28:10 0 72 0.00 2.00 2.00 0 pidstat
02:28:10 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
02:28:12 0 1 0.00 287554.00 0.00 0 java
02:28:12 0 72 0.00 2.00 2.00 0 pidstat通过 pidstat -d模式，只查看I/O情况。
很明显的看出来PID=1的java进程，每秒写kB_wr/s达到了307240KB/s，大概300M左右。
那么我们就可以确定就是PID=1的这个java进程的问题
1.4 通过strace命令跟踪进程操作
root@91230cc467cc:/usr/local/tomcat# strace -p 1笔者在docker容器中启动strace命令直接报错
root@91230cc467cc:/usr/local/tomcat# strace -p 1
/usr/bin/strace: test_ptrace_setoptions_for_all: PTRACE_TRACEME doesn't work: Function not implemented
/usr/bin/strace: test_ptrace_setoptions_for_all: unexpected exit status 1如上所示，到现在还没有找到具体的问题点，希望读者知道原因的可以回复下，感谢。
1.5 lsof查看进程打开的文件
root@91230cc467cc:/usr/local/tomcat# lsof -p 1
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
java 1 root cwd DIR 0,164 4096 1183913 /usr/local/tomcat
java 1 root rtd DIR 0,164 4096 1184675 /
java 1 root txt REG 0,62 2709992 1310738 /usr/bin/qemu-x86_64
java 1 root mem REG 254,1 1310738 /usr/bin/qemu-x86_64 (stat: No such file or directory)
java 1 root mem REG 254,1 1056726 /usr/lib/jvm/java-7-openjdk-amd64/jre/bin/java (path dev=0,164)
java 1 root mem REG 254,1 1048612 /lib/x86_64-linux-gnu/ld-2.19.so (path dev=0,164)
java 1 root mem REG 254,1 1048694 /lib/x86_64-linux-gnu/libpthread-2.19.so (path dev=0,164)
...
java 1 root 45r CHR 1,8 0t0 6 /dev/random
java 1 root 46r CHR 1,9 0t0 10 /dev/urandom
java 1 root 47u IPv4 2162977 0t0 TCP *:http-alt (LISTEN)
java 1 root 48u unix 0x0000000000000000 0t0 2162978 socket
java 1 root 49r FIFO 0,11 0t0 2162980 pipe
java 1 root 50w FIFO 0,11 0t0 2162980 pipe
java 1 root 51u 0000 0,12 0 12341 anon_inode
java 1 root 52u IPv4 2162981 0t0 TCP *:8009 (LISTEN)
java 1 root 53r FIFO 0,11 0t0 2162982 pipe
java 1 root 54w FIFO 0,11 0t0 2162982 pipe
java 1 root 55u 0000 0,12 0 12341 anon_inode
java 1 root 56w REG 0,164 685 1184727 /usr/local/tomcat/logs/localhost_access_log.2022-03-28.txt
java 1 root 57r CHR 1,8 0t0 6 /dev/random
java 1 root 58w REG 0,164 3844 1184789 /tmp/testlog.log
java 1 root 59w REG 0,164 104857600 1186298 /tmp/test.log (deleted)
java 1 root 60w REG 0,164 5242880000 1185856 /tmp/test.log (deleted)
java 1 root 61w REG 0,164 5242880000 1185857 /tmp/test.log (deleted)
java 1 root 62w REG 0,164 5242880000 1185862 /tmp/test.log (deleted)
java 1 root 63w REG 0,164 5242880000 1185979 /tmp/test.log (deleted)
java 1 root 64w REG 0,164 5242880000 1185980 /tmp/test.log (deleted)
java 1 root 65w REG 0,164 5242880000 1185987 /tmp/test.log (deleted)
java 1 root 66w REG 0,164 5242880000 1185989 /tmp/test.log (deleted)
java 1 root 67w REG 0,164 5242880000 1186285 /tmp/test.log (deleted)
java 1 root 68r FIFO 0,11 0t0 2160501 pipe
java 1 root 69w FIFO 0,11 0t0 2160501 pipe
java 1 root 70u 0000 0,12 0 12341 anon_inode
...
java 1 root 80u IPv4 2162151 0t0 TCP 91230cc467cc:http-alt->172.17.0.1:62718 (ESTABLISHED)
java 1 root 82u IPv4 2160507 0t0 TCP localhost:8005 (LISTEN)
java 1 root 84u unix 0x0000000000000000 0t0 2163124 socket
java 1 root 85r REG 0,164 2150368 1056781 /usr/lib/jvm/java-7-openjdk-amd64/jre/lib/charsets.jar
java 1 root 86w REG 0,164 5242880000 1186286 /tmp/test.log (deleted)
java 1 root 87w REG 0,164 358440960 1186297 /tmp/test.log通过lsof命令，可以看到进程打开的那些文件，这里有一个文件/tmp/test.log被频繁的打开删除
如最后一行，正在写入/tmp/test.log，目前文件大小为358440960
倒数第二行，删除了一个/tmp/test.log的文件，大小为5242880000
所以通过这些信息，基本可以确定这个/tmp/test.log的文件应该就是我们要找的那个文件
1.6 代码查询
我们通过test.log来去代码中查看
public class JvmTest {
@RequestMapping(path = "/testlog", method = RequestMethod.GET)
public String testlog() {
StringBuilder sb = new StringBuilder();
int length = 100 * 1024 * 1024;
byte[] bytes = new byte[length];
for (int j = 0; j < length; j++) {
bytes[j] = 'a';
}
String s = sb.toString();
FileOutputStream outputStream = null;
File f = null;
try {
f = new File("/tmp/test.log");
outputStream = new FileOutputStream(f);
} catch (FileNotFoundException e) {
e.printStackTrace();
}
for (int i = 0; i < 1000; i++) {
try {
outputStream.write(bytes);
if (i % 50 == 0) {
f.delete();
f = new File("/tmp/test.log");
outputStream = new FileOutputStream(f);
}
} catch (IOException e) {
e.printStackTrace();
}
try {
Thread.sleep(200);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
return "success";
}
}可以看出，我们最开始触发的这个方法，每200ms写入到/tmp/test.log文件中100M的内容，每50 * 200 = 10秒钟删除一次/tmp/test.log文件。
基本验证了lsof的展示结果。
总结：
有点失败的一次问题排查过程，与标准的验证方式还是有点区别的。
当然，在碰到真正的iowait相关问题时，我们还是可以按照这个标准方式来查询问题。
希望了解完整正确过程的同学可以参考：
极客时间 <<Linux性能优化实战>> 之 案例篇：如何找出狂打日志的“内鬼”？
591
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
