诊断实验室二文件IO-CSDN博客

这篇我们来看下如何定位IO 瓶颈问题，并找出个别慢速的IO操作。

测试源码如下：

https://github.com/kernel-z/linux-tracing-workshop/blob/master/logger.c

编译如下：

#gcc -g -fno-omit-frame-pointer -O0 -pthread logger.c -o logger

其中-fno-omit-frame-pointer是取消编译优化的参数。

这个logger.c文件中有两种IO，小IO是1KB,大IO是1MB。

其中的代码主要逻辑是这样，先使用pthread_create创建子线程,然后主线程20ms写一次小IO(1KB)，子线程200ms写一次大IO(1MB),不断循环执行。

运行程序开始诊断。

1. 基本诊断

先使用top命令进行监控，发现如下，wait相对其他是最高的，说明存在等待，IO延时较大。

top - 16:33:03 up 19 min, 3 users, load average: 0.31, 0.08, 0.04

Tasks: 112 total, 1 running, 111 sleeping, 0 stopped, 0 zombie

%Cpu(s): 0.7 us, 2.1 sy, 0.0 ni, 89.3 id, 6.9 wa, 0.0 hi, 1.0 si, 0.0 st

KiB Mem : 1009372 total, 359584 free, 291132 used, 358656 buff/cache

KiB Swap: 1046524 total, 1046524 free, 0 used. 535876 avail Mem

2638 root 20 0 80252 732 644 S 1.0 0.1 0:00.83 logger

2. 深入调查

接着，使用biolatency来观察IO延时：

usecs : count distribution

32 -> 63 : 0 | |

64 -> 127 : 10 |**** |

128 -> 255 : 88 |****************************************|

256 -> 511 : 1 | |

512 -> 1023 : 0 | |

1024 -> 2047 : 3 |* |

2048 -> 4095 : 12 |***** |

4096 -> 8191 : 19 |******** |

8192 -> 16383 : 15 |****** |

16384 -> 32767 : 2 | |

图形上有两柱山峰，一柱高一柱低（可能是由两种IO模型，这个可能是因为我们自己知道问题原因），另外，因为延时本身是存在波动的，所以一种延时一般都会有跨度的。

知道了延时后，需要知道IO的实际操作，使用biosnoop。

biosnoop会把每次ip延时给抓下来，便于展示这里只复制其中一部分：

TIME(s) COMM PID DISK T SECTOR BYTES LAT(ms)

3.960609000 logger 2892 sda W 39509344 4096 0.17

3.960791000 jbd2/sda1-8 246 sda W 33968280 8192 0.12

3.961516000 jbd2/sda1-8 246 sda W 33968296 4096 0.13

3.982633000 logger 2892 sda W 39509344 4096 0.17

3.982820000 jbd2/sda1-8 246 sda W 33968304 8192 0.12

3.983509000 jbd2/sda1-8 246 sda W 33968320 4096 0.13

4.005046000 logger 2892 sda W 39509344 4096 0.17

4.005228000 jbd2/sda1-8 246 sda W 33968328 8192 0.12

4.006046000 jbd2/sda1-8 246 sda W 33968344 4096 0.17

4.027720000 logger 2892 sda W 39509352 4096 0.17

4.027929000 jbd2/sda1-8 246 sda W 33968352 20480 0.14

4.028837000 jbd2/sda1-8 246 sda W 33968392 4096 0.19

4.050525000 logger 2892 sda W 39509352 4096 0.36

4.050930000 jbd2/sda1-8 246 sda W 33968400 8192 0.26

4.052484000 jbd2/sda1-8 246 sda W 33968416 4096 0.29

4.073984000 logger 2892 sda W 39509352 4096 0.19

4.074249000 jbd2/sda1-8 246 sda W 33968424 8192 0.18

4.075483000 jbd2/sda1-8 246 sda W 33968440 4096 0.16

4.098321000 logger 2893 sda W 39467008 688128 2.03

4.101989000 logger 2893 sda W 39468352 360448 5.58

4.102365000 logger 2892 sda W 39509352 4096 5.15

4.103039000 logger 2893 sda W 39561216 692224 5.79

4.103718000 logger 2893 sda W 39562568 356352 6.39

4.104328000 logger 2893 sda W 39563264 688128 6.98

4.105226000 logger 2893 sda W 39564608 360448 7.80

4.106383000 logger 2893 sda W 39565312 688128 8.94

4.106753000 logger 2893 sda W 39566656 360448 9.23

4.107970000 logger 2893 sda W 39567360 688128 10.43

4.107998000 jbd2/sda1-8 246 sda W 33968448 8192 5.31

其中jbd2是系统的日志相关进，而且其延时很小所以不需要管他。

上面的logger就是我们的应用程序，而且大于５毫秒的应用都是logger发起的，这样就知道了是logger进程。

注意：去看倒数第二列中的字节数，计算一下发现都是4096的倍数，因为操作系统的页大小为4096。

有时候不需要显示延时很低的io，可以使用fileslower工具,该工具是抓取文件fio的，其实针对本篇问题是最针对的工具，但是绝多大多数问题在最开始时候并不能一次性找到针对工具的，都是一步一步分析判断的过程。其执行如下，还能看到是写到哪个文件。

# ./fileslower.py 1

Tracing sync read/writes slower than 1 ms

TIME(s) COMM TID D BYTES LAT(ms) FILENAME

0.022 logger 2892 W 1024 1.48 log.data

0.044 logger 2892 W 1024 1.67 log.data

0.067 logger 2892 W 1024 1.89 log.data

0.091 logger 2892 W 1024 3.98 log.data

0.113 logger 2892 W 1024 1.88 log.data

0.137 logger 2892 W 1024 2.82 log.data

0.185 logger 2893 W 10485760 28.46 flush.data

0.207 logger 2892 W 1024 1.64 log.data

0.230 logger 2892 W 1024 1.81 log.data

0.252 logger 2892 W 1024 2.07 log.data