诊断实验室二文件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就是我们的应用程序,而且大于5毫秒的应用都是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


评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值