诊断实验室二文件IO

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