这篇我们来看下如何定位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
