对于btt的结果分析十分的困难,我和同事花了很多的时间在网上查找btt输出的每一项参数的意义,试图更好的分析bio的统计信息,但网上文章一大抄,翻来覆去就是那几篇文章。
本文中内容参考了以下网址:
1.btt官方网址:http://git.kernel.dk/cgit/blktrace/tree/btt/doc/btt.tex
在(centos7.4)/usr/share/doc/blktrace-1.0.5/README中32行提到http://git.kernel.dk/
本文中对btt的分析很多参考自btt.tex
2.http或者git上的blktrace最新版本
http://brick.kernel.dk/snaps/
dd if=/dev/zero of=/dev/sdb bs=1M count=200
mount -t debugfs none /sys/kernel/debug/
blktrace -d /dev/sdb blkparse -i sdb -d sdb.blktrace.bin btt -i sdb.blktrace.bin
conv=fdatasync conv=fsync conv=sync oflag=dsyn oflag=syn oflag=direct
dd默认是buffer io, 页面是pdflush刷的。自己加上去这些参数看看分析结果,会让你大吃一惊的。
btt结果如下:
btt -i sdb.blktrace.bin | grep -A 100 "All Devices"
==================== All Devices ==================== ALL MIN AVG MAX N --------------- ------------- ------------- ------------- ----------- Q2Q 0.000000479 0.007676882 5.711474239 1553 Q2A 0.000080329 0.000887075 0.029918892 1521 Q2G 0.000000441 0.000296168 0.029764843 1535 S2G 0.014563643 0.021455586 0.029762593 21 G2I 0.000000837 0.001079771 0.017816477 1535 Q2M 0.000000134 0.000000299 0.000001491 19 I2D 0.000019345 0.055941845 0.106661743 1535 M2D 0.000029110 0.000044429 0.000053098 19 D2C 0.000176810 0.023186230 0.053523069 1554 Q2C 0.000327039 0.079803764 0.146987975 1554 ==================== Device Overhead ==================== DEV | Q2G G2I Q2M I2D D2C ---------- | --------- --------- --------- --------- --------- ( 8, 17) | 0.3666% 1.3365% 0.0000% 69.2422% 29.0541% ---------- | --------- --------- --------- --------- --------- Overall | 0.3666% 1.3365% 0.0000% 69.2422% 29.0541% ==================== Device Merge Information ==================== DEV | #Q #D Ratio | BLKmin BLKavg BLKmax Total ---------- | -------- -------- ------- | -------- -------- -------- -------- ( 8, 17) | 1554 1535 1.0 | 8 1021 1024 1567392 ==================== Device Q2Q Seek Information ==================== DEV | NSEEKS MEAN MEDIAN | MODE ---------- | --------------- --------------- --------------- | --------------- ( 8, 17) | 1554 1667079.8 0 | 0(1550) ---------- | --------------- --------------- --------------- | --------------- Overall | NSEEKS MEAN MEDIAN | MODE Average | 1554 1667079.8 0 | 0(1550) ==================== Device D2D Seek Information ==================== DEV | NSEEKS MEAN MEDIAN | MODE ---------- | --------------- --------------- --------------- | --------------- ( 8, 17) | 1535 1687714.7 0 | 0(1531) ---------- | --------------- --------------- --------------- | --------------- Overall | NSEEKS MEAN MEDIAN | MODE Average | 1535 1687714.7 0 | 0(1531) ==================== Plug Information ==================== DEV | # Plugs # Timer Us | % Time Q Plugged ---------- | ---------- ---------- | ---------------- ( 8, 17) | 95( 3) | 1.348107347% DEV | IOs/Unp IOs/Unp(to) ---------- | ---------- ---------- ( 8, 16) | 0.0 0.0 ( 8, 17) | 14.8 10.7 ---------- | ---------- ---------- Overall | IOs/Unp IOs/Unp(to) Average | 14.8 10.7 ==================== Active Requests At Q Information ==================== DEV | Avg Reqs @ Q ---------- | ------------- ( 8, 17) | 71.0 ==================== I/O Active Period Information ==================== DEV | # Live Avg. Act Avg. !Act % Live ---------- | ---------- ------------- ------------- ------ ( 8, 16) | 0 0.000000000 0.000000000 0.00 ( 8, 17) | 9 0.134758122 1.351199997 10.09 ---------- | ---------- ------------- ------------- ------ Total Sys | 9 0.134758122 1.351199997 10.09 # Total System # Total System : q activity 0.000001613 0.0 0.000001613 0.4 0.124339757 0.4 0.124339757 0.0 0.301083076 0.0 0.301083076 0.4 0.400630592 0.4 0.400630592 0.0 0.573512380 0.0 0.573512380 0.4 0.680941099 0.4 0.680941099 0.0 0.855548103 0.0 0.855548103 0.4 0.954668973 0.4 0.954668973 0.0 4.983438230 0.0 4.983438230 0.4 4.983900171 0.4 4.983900171 0.0 5.964745346 0.0 5.964745346 0.4 6.210325030 0.4 6.210325030 0.0 11.921799269 0.0 11.921799269 0.4 11.922199421 0.4 11.922199421 0.0 # Total System : c activity 0.002123105 0.5 0.002123105 0.9 1.057812876 0.9 1.057812876 0.5 4.983851980 0.5 4.983851980 0.9 5.080603626 0.9 5.080603626 0.5 5.966766526 0.5 5.966766526 0.9 6.311149346 0.9 6.311149346 0.5 11.922139935 0.5 11.922139935 0.9 11.922139935 0.9 11.922139935 0.5 12.022423074 0.5 12.022423074 0.9 12.022423074 0.9 12.022423074 0.5 # Per device # 8,17 : q activity 0.000001613 1.0 0.000001613 1.4 0.124339757 1.4 0.124339757 1.0 0.301083076 1.0 0.301083076 1.4 0.400630592 1.4 0.400630592 1.0 0.573512380 1.0 0.573512380 1.4 0.680941099 1.4 0.680941099 1.0 0.855548103 1.0 0.855548103 1.4 0.954668973 1.4 0.954668973 1.0 4.983438230 1.0 4.983438230 1.4 4.983900171 1.4 4.983900171 1.0 5.964745346 1.0 5.964745346 1.4 6.210325030 1.4 6.210325030 1.0 11.921799269 1.0 11.921799269 1.4 11.922199421 1.4 11.922199421 1.0 # 8,17 : c activity 0.002123105 1.5 0.002123105 1.9 1.057812876 1.9 1.057812876 1.5 4.983851980 1.5 4.983851980 1.9 5.080603626 1.9 5.080603626 1.5 5.966766526 1.5 5.966766526 1.9 6.311149346 1.9 6.311149346 1.5 11.922139935 1.5 11.922139935 1.9 11.922139935 1.9 11.922139935 1.5 12.022423074 1.5 12.022423074 1.9 12.022423074 1.9 12.022423074 1.5 # Per process # blktrace : q activity # blktrace : c activity 0.635480135 2.5 0.635480135 2.9 0.719490098 2.9 0.719490098 2.5 0.923163074 2.5 0.923163074 2.9 0.923163074 2.9 0.923163074 2.5 # dd : q activity # dd : c activity 0.644083682 3.5 0.644083682 3.9 0.656542273 3.9 0.656542273 3.5 0.878359453 3.5 0.878359453 3.9 0.901143153 3.9 0.901143153 3.5 # jbd2 : q activity 4.983438230 4.0 4.983438230 4.4 4.983900171 4.4 4.983900171 4.0 11.921799269 4.0 11.921799269 4.4 11.922199421 4.4 11.922199421 4.0 # jbd2 : c activity # ksoftirqd : q activity # ksoftirqd : c activity 0.113965122 5.5 0.113965122 5.9 0.198731512 5.9 0.198731512 5.5 0.307666215 5.5 0.307666215 5.9 0.409794955 5.9 0.409794955 5.5 0.616305736 5.5 0.616305736 5.9 0.676618319 5.9 0.676618319 5.5 0.912045716 5.5 0.912045716 5.9 0.952781433 5.9 0.952781433 5.5 6.020433404 5.5 6.020433404 5.9 6.061857376 5.9 6.061857376 5.5 # kworker : q activity 0.000001613 6.0 0.000001613 6.4 0.124339757 6.4 0.124339757 6.0 0.301083076 6.0 0.301083076 6.4 0.400630592 6.4 0.400630592 6.0 0.573512380 6.0 0.573512380 6.4 0.680941099 6.4 0.680941099 6.0 0.855548103 6.0 0.855548103 6.4 0.954668973 6.4 0.954668973 6.0 5.964745346 6.0 5.964745346 6.4 6.210325030 6.4 6.210325030 6.0 # kworker : c activity 0.002123105 6.5 0.002123105 6.9 0.123954697 6.9 0.123954697 6.5 0.303307770 6.5 0.303307770 6.9 0.398885246 6.9 0.398885246 6.5 0.578128551 6.5 0.578128551 6.9 0.680640684 6.9 0.680640684 6.5 0.857973954 6.5 0.857973954 6.9 0.866998251 6.9 0.866998251 6.5 5.966766526 6.5 5.966766526 6.9 6.189072144 6.9 6.189072144 6.5 # pid000000000 : q activity # pid000000000 : c activity 0.028265966 7.5 0.028265966 7.9 1.057812876 7.9 1.057812876 7.5 4.983851980 7.5 4.983851980 7.9 5.080603626 7.9 5.080603626 7.5 6.014711621 7.5 6.014711621 7.9 6.311149346 7.9 6.311149346 7.5 11.922139935 7.5 11.922139935 7.9 11.922139935 7.9 11.922139935 7.5 12.022423074 7.5 12.022423074 7.9 12.022423074 7.9 12.022423074 7.5 # rcu_sched : q activity # rcu_sched : c activity 0.916222959 8.5 0.916222959 8.9 0.916659526 8.9 0.916659526 8.5
每一段详细分析:
ALL MIN AVG MAX N --------------- ------------- ------------- ------------- ----------- Q2Q 0.000000479 0.007676882 5.711474239 1553 Q2A 0.000080329 0.000887075 0.029918892 1521 Q2G 0.000000441 0.000296168 0.029764843 1535 S2G 0.014563643 0.021455586 0.029762593 21 G2I 0.000000837 0.001079771 0.017816477 1535 Q2M 0.000000134 0.000000299 0.000001491 19 I2D 0.000019345 0.055941845 0.106661743 1535 M2D 0.000029110 0.000044429 0.000053098 19 D2C 0.000176810 0.023186230 0.053523069 1554 Q2C 0.000327039 0.079803764 0.146987975 1554
我们需要关注的是红色部分,单位是秒s,N表示个数。
==================== Device Overhead ==================== DEV | Q2G G2I Q2M I2D D2C ---------- | --------- --------- --------- --------- --------- ( 8, 17) | 0.3666% 1.3365% 0.0000% 69.2422% 29.0541% ---------- | --------- --------- --------- --------- --------- Overall | 0.3666% 1.3365% 0.0000% 69.2422% 29.0541%
在此次测试IO中,I2D(IO请求在IO调度中所耗费的时间)
平均花费了69%的时间,属于最耗时的部分,其次是D2C(IO请求在硬件设备中耗费的时间)
花费了29%的时间。
==================== Device Merge Information ==================== DEV | #Q #D Ratio | BLKmin BLKavg BLKmax Total ---------- | -------- -------- ------- | -------- -------- -------- -------- ( 8, 17) | 1554 1535 1.0 | 8 1021 1024 1567392
对此部分的解释如下:
A key measurement when making changes in the system (software \emph{or} hardware) is to understand the block IO layer ends up merging incoming requests into fewer, but larger, IOs to the underlying driver. In this section, we show the number of incoming requests (Q), the number of issued requests (D) and the resultant ratio. We also provide values for the minimum, average and maximum IOs generated.
IO合并请求信息,Q表示传入的IO请求,D表示合并后发出的请求,D越小证明数据包越大,合并请求比例越高(越高越好)。
==================== Device Q2Q Seek Information ==================== DEV | NSEEKS MEAN MEDIAN | MODE ---------- | --------------- --------------- --------------- | --------------- ( 8, 17) | 1554 1667079.8 0 | 0(1550) ---------- | --------------- --------------- --------------- | --------------- Overall | NSEEKS MEAN MEDIAN | MODE Average | 1554 1667079.8 0 | 0(1550) ==================== Device D2D Seek Information ==================== DEV | NSEEKS MEAN MEDIAN | MODE ---------- | --------------- --------------- --------------- | --------------- ( 8, 17) | 1535 1687714.7 0 | 0(1531) ---------- | --------------- --------------- --------------- | --------------- Overall | NSEEKS MEAN MEDIAN | MODE Average | 1535 1687714.7 0 | 0(1531)
# Total System # Total System : q activity # Total System : c activity # Per device # 8,17 : q activity # 8,17 : c activity # Per process # blktrace : q activity # blktrace : c activity # dd : q activity # dd : c activity # jbd2 : q activity # jbd2 : c activity # ksoftirqd : q activity # ksoftirqd : c activity # kworker : q activity # kworker : c activity # pid000000000 : q activity # pid000000000 : c activity # rcu_sched : q activity # rcu_sched : c activity
kworker(KWorker is in process ...At the moment there is not active source code to download because the project is in very early version. The only active place on this page is the bug tracking page that keeps my current list of bugs-tracks open. When the project hits the 0.1 release (see bug tracking) it will be available to the public (and maybe to some volunteers).)
jbd2(journaling block driver)这个进程实现的是文件系统的日志功能,磁盘使用日志功能来保证数据的完整性
RCU(Read-Copy Update)
ksoftirqd软中断处理线程
对于activity的定义可以参见http://git.kernel.dk/cgit/blktrace/tree/btt/output.c
部分代码如下:
int output_regions(FILE *ofp, char *header, struct region_info *reg, float base) { if (list_len(®->qranges) == 0 && list_len(®->cranges) == 0) return 0; fprintf(ofp, "# %16s : q activity\n", header); __output_ranges(ofp, ®->qranges, base); fprintf(ofp, "\n"); fprintf(ofp, "# %16s : c activity\n", header); __output_ranges(ofp, ®->cranges, base + 0.5); fprintf(ofp, "\n"); return 1; }
本文参考
http://git.kernel.dk/cgit/blktrace/tree/btt/doc/btt.tex