Skip to content

Latest commit

 

History

History
632 lines (502 loc) · 27 KB

20231129_01.md

File metadata and controls

632 lines (502 loc) · 27 KB

Linux 调试利器 gcore, gdb, pstack, gstack, strace, pstree, lsof, blktrace, blkparse, btt, blkiomon, iowatcher

作者

digoal

日期

2023-11-29

标签

PostgreSQL , PolarDB , linux , gcore , gdb , pstack , gstack , strace , pstree , lsof , blktrace , blkparse , btt , blkiomon , iowatcher


背景

Linux 调试利器 gcore, gdb, pstack, gstack, strace, pstree, lsof, blktrace, blkparse, btt, blkiomon, iowatcher

1、pstree - display a tree of processes

root@3fa69f8a9104:~# pstree -lpstZgac  
su,1,1,`' - postgres -c /usr/lib/postgresql/14/bin/postgres -D "/var/lib/postgresql/14/pgdata"  
  └─postgres,7,7,`' -D /var/lib/postgresql/14/pgdata  
      ├─postgres,9,9,`'  
      ├─postgres,11,11,`'  
      ├─postgres,12,12,`'  
      ├─postgres,13,13,`'  
      ├─postgres,14,14,`'  
      ├─postgres,15,15,`'  
      ├─postgres,16,16,`'  
      └─postgres,32,32,`'  

2、strace - trace system calls and signals

root@3fa69f8a9104:~# strace -CvTt -p 32  
strace: Process 32 attached  
07:23:44 epoll_pwait(4, [{EPOLLIN, {u32=3417277192, u64=187650538439432}}], 1, -1, NULL, 8) = 1 <2.013785>  
07:23:46 recvfrom(10, "Q\0\0\0+select count(*) from pg_sta"..., 8192, 0, NULL, NULL) = 44 <0.000082>  
07:23:46 lseek(31, 0, SEEK_END)         = 8192 <0.000109>  
07:23:46 lseek(7, 0, SEEK_END)          = 16384 <0.000022>  
07:23:46 lseek(32, 0, SEEK_END)         = 16384 <0.000023>  
07:23:46 lseek(34, 0, SEEK_END)         = 8192 <0.000019>  
07:23:46 lseek(5, 0, SEEK_END)          = 16384 <0.000013>  
07:23:46 lseek(6, 0, SEEK_END)          = 16384 <0.000242>  
07:23:46 brk(0xaaaacbd49000)            = 0xaaaacbd49000 <0.000068>  
07:23:46 brk(0xaaaacbd89000)            = 0xaaaacbd89000 <0.000013>  
07:23:46 brk(0xaaaacbf84000)            = 0xaaaacbf84000 <0.000010>  
07:23:46 brk(0xaaaacc025000)            = 0xaaaacc025000 <0.000009>  
07:23:46 brk(0xaaaacc046000)            = 0xaaaacc046000 <0.000180>  
07:23:46 brk(0xaaaacbc2f000)            = 0xaaaacbc2f000 <0.000127>  
07:23:46 sendto(9, "\2\0\0\0@\0\0\0\2755\0\0\0\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 64, 0, NULL, 0) = 64 <0.000157>  
07:23:46 sendto(10, "T\0\0\0\36\0\1count\0\0\0\0\0\0\0\0\0\0\24\0\10\377\377\377\377\0\0D"..., 63, 0, NULL, 0) = 63 <0.000045>  
07:23:46 recvfrom(10, 0xaaaac78cce98, 8192, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) <0.000009>  
07:23:46 epoll_pwait(4, [{EPOLLIN, {u32=3417277192, u64=187650538439432}}], 1, -1, NULL, 8) = 1 <4.538657>  
07:23:50 recvfrom(10, "Q\0\0\0+select count(*) from pg_sta"..., 8192, 0, NULL, NULL) = 44 <0.000092>  
07:23:50 brk(0xaaaacbc6f000)            = 0xaaaacbc6f000 <0.000073>  
07:23:50 lseek(31, 0, SEEK_END)         = 8192 <0.000193>  
07:23:50 lseek(7, 0, SEEK_END)          = 16384 <0.000171>  
07:23:50 lseek(32, 0, SEEK_END)         = 16384 <0.000027>  
07:23:50 lseek(34, 0, SEEK_END)         = 8192 <0.000022>  
07:23:50 lseek(5, 0, SEEK_END)          = 16384 <0.000021>  
07:23:50 lseek(6, 0, SEEK_END)          = 16384 <0.000018>  
07:23:50 brk(0xaaaacbd49000)            = 0xaaaacbd49000 <0.000025>  
07:23:50 brk(0xaaaacbd89000)            = 0xaaaacbd89000 <0.000070>  
07:23:50 brk(0xaaaacbf84000)            = 0xaaaacbf84000 <0.000058>  
07:23:50 brk(0xaaaacc025000)            = 0xaaaacc025000 <0.000096>  
07:23:50 brk(0xaaaacc046000)            = 0xaaaacc046000 <0.000058>  
07:23:50 brk(0xaaaacbc2f000)            = 0xaaaacbc2f000 <0.000184>  
07:23:50 sendto(9, "\2\0\0\0@\0\0\0\2755\0\0\0\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 64, 0, NULL, 0) = 64 <0.000349>  
07:23:50 sendto(10, "T\0\0\0\36\0\1count\0\0\0\0\0\0\0\0\0\0\24\0\10\377\377\377\377\0\0D"..., 63, 0, NULL, 0) = 63 <0.000333>  
07:23:50 recvfrom(10, 0xaaaac78cce98, 8192, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) <0.000181>  
07:23:50 epoll_pwait(4, ^Cstrace: Process 32 detached  
 <detached ...>  
% time     seconds  usecs/call     calls    errors syscall  
------ ----------- ----------- --------- --------- ----------------  
 26.85    0.000286          23        12           lseek  
 26.67    0.000284          21        13           brk  
 18.31    0.000195          48         4           sendto  
 16.06    0.000171          42         4         2 recvfrom  
 12.11    0.000129          64         2           epoll_pwait  
------ ----------- ----------- --------- --------- ----------------  
100.00    0.001065          30        35         2 total  

3、gcore - Generate core files for running processes

root@3fa69f8a9104:~# gcore 32  
[Thread debugging using libthread_db enabled]  
Using host libthread_db library "/lib/aarch64-linux-gnu/libthread_db.so.1".  
0x0000ffffa8bf311c in epoll_pwait () from /lib/aarch64-linux-gnu/libc.so.6  
Saved corefile core.32  
[Inferior 1 (process 32) detached]  
root@3fa69f8a9104:~# ll  
total 235M  
...   
-rw-r--r-- 1 root root 235M Nov 29 07:24 core.32  

4、lsof - list open files

删除文件后, 空间未释放, 使用lsof查看是否还有pid打开了文件? kill pid.

5、gdb, pstack, gstack

pstack是个脚本, 指向gstack, 最终还是调用gdb.

[root@JiekeXu ~]# cat /usr/bin/gstack    
#!/bin/sh    
    
if test $# -ne 1; then    
    echo "Usage: `basename $0 .sh` <process-id>" 1>&2    
    exit 1    
fi    
    
if test ! -r /proc/$1; then    
    echo "Process $1 not found." 1>&2    
    exit 1    
fi    
    
# GDB doesn't allow "thread apply all bt" when the process isn't    
# threaded; need to peek at the process to determine if that or the    
# simpler "bt" should be used.    
    
backtrace="bt"    
if test -d /proc/$1/task ; then    
    # Newer kernel; has a task/ directory.    
    if test `/bin/ls /proc/$1/task | /usr/bin/wc -l` -gt 1 2>/dev/null ; then    
    backtrace="thread apply all bt"    
    fi    
elif test -f /proc/$1/maps ; then    
    # Older kernel; go by it loading libpthread.    
    if /bin/grep -e libpthread /proc/$1/maps > /dev/null 2>&1 ; then    
    backtrace="thread apply all bt"    
    fi    
fi    
    
GDB=${GDB:-/usr/bin/gdb}    
    
# Run GDB, strip out unwanted noise.    
# --readnever is no longer used since .gdb_index is now in use.    
$GDB --quiet -nx $GDBARGS /proc/$1/exe $1 <<EOF 2>&1 |    
set width 0    
set height 0    
set pagination no    
$backtrace    
EOF    
/bin/sed -n     
    -e 's/^((gdb) )*//'     
    -e '/^#/p'     
    -e '/^Thread/p'    

例如:

gdb -p 8089 --batch -ex "bt"    
    
    
gdb -p 8089 --batch -ex "thread apply all bt full"    
root@d40da947f60f:~# gdb -p 8089 --batch -ex "thread apply all bt full"    
[Thread debugging using libthread_db enabled]    
Using host libthread_db library "/lib/aarch64-linux-gnu/libthread_db.so.1".    
0x0000ffffa566011c in __GI_epoll_pwait (epfd=4, events=0xaaaafe49b300, maxevents=1, timeout=-1, set=0x0) at ../sysdeps/unix/sysv/linux/epoll_pwait.c:42    
42  ../sysdeps/unix/sysv/linux/epoll_pwait.c: No such file or directory.    
    
Thread 1 (Thread 0xffffa2d66010 (LWP 8089) "postgres"):    
#0  0x0000ffffa566011c in __GI_epoll_pwait (epfd=4, events=0xaaaafe49b300, maxevents=1, timeout=-1, set=0x0) at ../sysdeps/unix/sysv/linux/epoll_pwait.c:42    
        _sys_result = 18446744073709551612    
        sc_ret = <optimized out>    
#1  0x0000aaaae7961e74 in WaitEventSetWait ()    
No symbol table info available.    
#2  0x0000aaaae784d9fc in secure_read ()    
No symbol table info available.    
#3  0x0000aaaae7854d04 in ?? ()    
No symbol table info available.    
#4  0x0000aaaae785593c in pq_getbyte ()    
No symbol table info available.    
#5  0x0000aaaae798bff4 in PostgresMain ()    
No symbol table info available.    
#6  0x0000aaaae78fd180 in ?? ()    
No symbol table info available.    
#7  0x0000aaaae78fe060 in PostmasterMain ()    
No symbol table info available.    
#8  0x0000aaaae764fb70 in main ()    
No symbol table info available.    
[Inferior 1 (process 8089) detached]    
    
    
root@d40da947f60f:~# gdb -p 8089 --batch -ex "thread apply all bt"    
[Thread debugging using libthread_db enabled]    
Using host libthread_db library "/lib/aarch64-linux-gnu/libthread_db.so.1".    
0x0000ffffa566011c in __GI_epoll_pwait (epfd=4, events=0xaaaafe49b300, maxevents=1, timeout=-1, set=0x0) at ../sysdeps/unix/sysv/linux/epoll_pwait.c:42    
42  ../sysdeps/unix/sysv/linux/epoll_pwait.c: No such file or directory.    
    
Thread 1 (Thread 0xffffa2d66010 (LWP 8089) "postgres"):    
#0  0x0000ffffa566011c in __GI_epoll_pwait (epfd=4, events=0xaaaafe49b300, maxevents=1, timeout=-1, set=0x0) at ../sysdeps/unix/sysv/linux/epoll_pwait.c:42    
#1  0x0000aaaae7961e74 in WaitEventSetWait ()    
#2  0x0000aaaae784d9fc in secure_read ()    
#3  0x0000aaaae7854d04 in ?? ()    
#4  0x0000aaaae785593c in pq_getbyte ()    
#5  0x0000aaaae798bff4 in PostgresMain ()    
#6  0x0000aaaae78fd180 in ?? ()    
#7  0x0000aaaae78fe060 in PostmasterMain ()    
#8  0x0000aaaae764fb70 in main ()    
[Inferior 1 (process 8089) detached]    
    
    
root@d40da947f60f:~# gdb -p 8089 --batch -ex "bt"    
[Thread debugging using libthread_db enabled]    
Using host libthread_db library "/lib/aarch64-linux-gnu/libthread_db.so.1".    
0x0000ffffa566011c in __GI_epoll_pwait (epfd=4, events=0xaaaafe49b300, maxevents=1, timeout=-1, set=0x0) at ../sysdeps/unix/sysv/linux/epoll_pwait.c:42    
42  ../sysdeps/unix/sysv/linux/epoll_pwait.c: No such file or directory.    
#0  0x0000ffffa566011c in __GI_epoll_pwait (epfd=4, events=0xaaaafe49b300, maxevents=1, timeout=-1, set=0x0) at ../sysdeps/unix/sysv/linux/epoll_pwait.c:42    
#1  0x0000aaaae7961e74 in WaitEventSetWait ()    
#2  0x0000aaaae784d9fc in secure_read ()    
#3  0x0000aaaae7854d04 in ?? ()    
#4  0x0000aaaae785593c in pq_getbyte ()    
#5  0x0000aaaae798bff4 in PostgresMain ()    
#6  0x0000aaaae78fd180 in ?? ()    
#7  0x0000aaaae78fe060 in PostmasterMain ()    
#8  0x0000aaaae764fb70 in main ()    
[Inferior 1 (process 8089) detached]    

6、blktrace, blkparse, btt, blkiomon, iowatcher

blktrace - generate traces of the i/o traffic on block devices

blkparse - produce formatted output of event streams of block devices

btt - analyse block i/o traces produces by blktrace

blkiomon - monitor block device I/O based o blktrace data

iowatcher - Create visualizations from blktrace results

blkparse显示的各指标点示意:

 Q------->G------------>I--------->M------------------->D----------------------------->C  
 |-Q time-|-Insert time-|  
 |--------- merge time ------------|-merge with other IO|  
 |----------------scheduler time time-------------------|---driver,adapter,storagetime--|  
   
 |----------------------- await time in iostat output ----------------------------------|  

其中:

  • Q2Q — time between requests sent to the block layer
  • Q2G — time from a block I/O is queued to the time it gets a request allocated for it
  • G2I — time from a request is allocated to the time it is Inserted into the device's queue
  • Q2M — time from a block I/O is queued to the time it gets merged with an existing request
  • I2D — time from a request is inserted into the device's queue to the time it is actually issued to the device
  • M2D — time from a block I/O is merged with an exiting request until the request is issued to the device
  • D2C — service time of the request by the device
  • Q2C — total time spent in the block layer for a request
Q – 即将生成IO请求  
|  
G – IO请求生成  
|  
I – IO请求进入IO Scheduler队列  
|  
D – IO请求进入driver  
|  
C – IO请求执行完毕  
root@3fa69f8a9104:~# lsblk  
NAME   MAJ:MIN RM   SIZE RO TYPE MOUNTPOINT  
loop0    7:0    0 658.4M  1 loop   
vda    254:0    0  59.6G  0 disk   
└─vda1 254:1    0  59.6G  0 part /etc/hosts  
  
root@3fa69f8a9104:~# mount -t debugfs none /sys/kernel/debug  
  
root@3fa69f8a9104:~# pgbench -i -s 10  
  
root@3fa69f8a9104:~# pgbench -M prepared -n -r -P 1 -c 4 -j 4 -T 120  
.....  
  
  
root@3fa69f8a9104:~# blktrace -w 10 -d /dev/vda1  
=== vda1 ===  
  CPU  0:                 5560 events,      261 KiB data  
  CPU  1:                 2795 events,      132 KiB data  
  CPU  2:                 3037 events,      143 KiB data  
  CPU  3:                 2892 events,      136 KiB data  
  Total:                 14284 events (dropped 0),      670 KiB data  
  
  
root@3fa69f8a9104:~# blktrace -w 10 -d /dev/vda1 -o - | blkparse -i -  
...  
254,1    0     5683     9.985344005     0  C  FN 0 [0]  
254,1    0     5684     9.985344505     0  C  WS 0 [0]  
CPU0 (254,1):  
 Reads Queued:           0,        0KiB  Writes Queued:         418,    50496KiB  
 Read Dispatches:      159,        0KiB  Write Dispatches:      297,    50536KiB  
 Reads Requeued:         0     Writes Requeued:         0  
 Reads Completed:     1013,        0KiB  Writes Completed:     2208,   190596KiB  
 Read Merges:            0,        0KiB  Write Merges:            8,       68KiB  
 Read depth:            11           Write depth:            38  
 IO unplugs:           283           Timer unplugs:           0  
CPU1 (254,1):  
 Reads Queued:           0,        0KiB  Writes Queued:         548,    16088KiB  
 Read Dispatches:      279,        0KiB  Write Dispatches:      247,    16072KiB  
 Reads Requeued:         0     Writes Requeued:         0  
 Reads Completed:        0,        0KiB  Writes Completed:        0,        0KiB  
 Read Merges:            0,        0KiB  Write Merges:           22,       88KiB  
 Read depth:            11           Write depth:            38  
 IO unplugs:           231           Timer unplugs:           0  
CPU2 (254,1):  
 Reads Queued:           0,        0KiB  Writes Queued:         667,    90168KiB  
 Read Dispatches:      276,        0KiB  Write Dispatches:      388,    90164KiB  
 Reads Requeued:         0     Writes Requeued:         0  
 Reads Completed:        0,        0KiB  Writes Completed:        0,        0KiB  
 Read Merges:            0,        0KiB  Write Merges:           50,     1664KiB  
 Read depth:            11           Write depth:            38  
 IO unplugs:           338           Timer unplugs:           0  
CPU3 (254,1):  
 Reads Queued:           0,        0KiB  Writes Queued:         593,    33844KiB  
 Read Dispatches:      299,        0KiB  Write Dispatches:      274,    33824KiB  
 Reads Requeued:         0     Writes Requeued:         0  
 Reads Completed:        0,        0KiB  Writes Completed:        0,        0KiB  
 Read Merges:            0,        0KiB  Write Merges:           32,      128KiB  
 Read depth:            11           Write depth:            38  
 IO unplugs:           273           Timer unplugs:           0  
  
Total (254,1):  
 Reads Queued:           0,        0KiB  Writes Queued:        2226,   190596KiB  
 Read Dispatches:     1013,        0KiB  Write Dispatches:     1206,   190596KiB  
 Reads Requeued:         0     Writes Requeued:         0  
 Reads Completed:     1013,        0KiB  Writes Completed:     2208,   190596KiB  
 Read Merges:            0,        0KiB  Write Merges:          112,     1948KiB  
 IO unplugs:          1125           Timer unplugs:           0  
  
Throughput (R/W): 0KiB/s / 19088KiB/s  
Events (254,1): 14738 entries  
Skips: 0 forward (0 -   0.0%)  
  
  
root@3fa69f8a9104:~# umount /sys/kernel/debug  

实时查看:

blktrace只负责采集,blkparse 负责解析成适合人类看的文字:  
  
blktrace -o 指定输出.    
  
#blktrace -d /dev/sda -o - | blkparse -i -  

先采集,再查看:

1. 先采集,将会在当前目录获得一堆的文件,缺省的输出文件名是 sdb.blktrace.<cpu>,每个CPU对应一个文件。  
#blktrace /dev/sda /dev/sdb  
  
2. 给blkparse传递磁盘的名字,将会直接解析。  
#blkparse sda sdb  

blktrace产生的文件太零散怎么办?

生成采集文件  
#blktrace -d /dev/sda  
  
合并成一个二进制文件  
#blkparse -i sda -d sda.blktrace.bin  

嫌弃blkparse的输出太多,不方便查看,此时可以利用btt协助分析统计

#btt -i sda.blktrace.bin -l sda.d2c_latency  
  
# 这里就可以看到,每个阶段,消耗的时间  
  
  
[root@localhost2 /data/sandbox/blktrace_test]  
#btt -i sda.blktrace.bin -l sda.d2c_latency  
  
  
==================== All Devices ====================  
  
            ALL           MIN           AVG           MAX           N  
--------------- ------------- ------------- ------------- -----------  
  
Q2Q               0.000000238   0.126069031   5.007614945          40  
Q2G               0.000000556   0.000001765   0.000006022          11  
G2I               0.000000528   0.000003506   0.000015113          11  
Q2M               0.000000135   0.000000209   0.000001162          30  
I2D               0.000000396   0.000001240   0.000003602          11  
M2D               0.000002235   0.000007047   0.000014071          30  
D2C               0.003104665   0.015828304   0.028136240          41  
Q2C               0.003117684   0.015835360   0.028138401          41  
  
# 这里看到整个IO下来,每个阶段所消耗的时间,占用百分比  
  
  
==================== Device Overhead ====================  
  
       DEV |       Q2G       G2I       Q2M       I2D       D2C  
---------- | --------- --------- --------- --------- ---------  
 (  8,  0) |   0.0030%   0.0059%   0.0010%   0.0021%  99.9554%  
---------- | --------- --------- --------- --------- ---------  
   Overall |   0.0030%   0.0059%   0.0010%   0.0021%  99.9554%  
  
==================== Device Merge Information ====================  
  
       DEV |       #Q       #D   Ratio |   BLKmin   BLKavg   BLKmax    Total  
---------- | -------- -------- ------- | -------- -------- -------- --------  
 (  8,  0) |       41       11     3.7 |        8       29      144      328  
   
Q2I – time it takes to process an I/O prior to it being inserted or merged onto a request queue – Includes split, and remap time  
I2D – time the I/O is “idle” on the request queue  
D2C – time the I/O is “active” in the driver and on the device  
Q2I + I2D + D2C = Q2C  
Q2C: Total processing time of the I/O  

解释:

D2C: 表征块设备性能的关键指标  
Q2C: 客户发起请求到收到响应的时间  
D2C 平均时间:0.015828304 秒,即15.82毫秒  
Q2C 平均时间:0.015835360 秒,即15.83毫秒  
平均下来,D2C 阶段消耗时间占比 99.9554%  

上述命令其实还会产生一些.dat文件,可以看到iops信息

#ll *.dat  
-rw-r--r-- 1 root root    6 Nov 21 14:51 8,0_iops_fp.dat  
-rw-r--r-- 1 root root   11 Nov 21 14:51 8,0_mbps_fp.dat  
-rw-r--r-- 1 root root 3006 Nov 21 14:51 sda.d2c_latency_8,0_d2c.dat  
-rw-r--r-- 1 root root    6 Nov 21 14:51 sys_iops_fp.dat  
-rw-r--r-- 1 root root   11 Nov 21 14:51 sys_mbps_fp.dat  
  
5. btt -q   
  
#btt -i sda.blktrace.bin -q sda.q2c_latency  

以上文件解释:

sys_mbps_fs.dat: 本次统计中所有设备吞吐量    
  
sys_iops_fp.dat: 中是本次统计中所有设备的IOPS    

每个请求的d2c的latency详情:

sda.d2c_latency_8,0_d2c.dat  

修改blkparse的输出格式:

[root@localhost2 /data/sandbox]  
  
#blktrace -d /dev/sda -o - | blkparse -i - -f "%D %2c %8s %5T.%9t %5p %2a %3d\n"  
  8,0    9        1     0.000000000  8863  A   W  

一次IO的生命周期:direct read 附录见测试代码

[root@localhost /home/ahao.mah/sdc]  
  
#blktrace -d /dev/sdc  -o - | blkparse -i -  
  
  8,32   7        1     0.000000000  2923  Q   R 272208 + 2 [direct_io_read_]  
  8,32   7        2     0.000002526  2923  G   R 272208 + 2 [direct_io_read_]  
  8,32   7        3     0.000003142  2923  P   N [direct_io_read_]  
  8,32   7        4     0.000004575  2923  I   R 272208 + 2 [direct_io_read_]  
  8,32   7        5     0.000005402  2923  U   N [direct_io_read_] 1  
  8,32   7        6     0.000006775  2923  D   R 272208 + 2 [direct_io_read_]  
  8,32   7        7     0.000200150 32031  C   R 272208 + 2 [0]  
    
以上就是一次IO请求的生命周期,从actions看到,分别是QGPIUDC    
  
Q:先产生一个该位置的IO意向插入到io队列,此时并没有真正的请求  
G:发送一个实际的Io请求给设备  
P(plugging):插入:即等待即将到来的更多的io请求进入队列,以便系统能进行IO优化,减少执行IO请求时花的时间  
I:将IO请求进行调度,到这一步请求已经完全成型(formed)好了  
U (unplugging):拔出,设备决定不再等待其他的IO请求并使得系统必须响应当前IO请求,将该IO请求传给设备驱动器。可以看到,在P和U之间会等待IO,然后进行调度。这里会对IO进行一点优化,但是程度很低,因为等待的时间很短,是纳秒级别的  
D:发布刚才送入驱动器的IO请求  
C:结束IO请求,这里会返回一个执行状态:失败或者成功,在进程号处为0表示执行成功,反之则反  
  
到此一个IO的周期就结束了  

一次IO的生命周期:direct write 附录见测试代码

[root@localhost /home/ahao.mah/sdc]  
#taskset -c 1 ./direct_io_write_file_one &  
[1] 57376  
write success  
[1]+  Done                    taskset -c 1 ./direct_io_write_file_one  
[root@localhost /home/ahao.mah/blktrace/jiangyi]  
#time /usr/bin/blktrace  -w 100 -d /dev/sdc -o -  | /usr/bin/blkparse -w 100   -i -  
  
  8,32   1        1     0.000000000 57376  Q  WS 272208 + 2 [direct_io_write]  
  8,32   1        2     0.000005514 57376  G  WS 272208 + 2 [direct_io_write]  
  8,32   1        3     0.000006880 57376  P   N [direct_io_write]  
  8,32   1        4     0.000009793 57376  I  WS 272208 + 2 [direct_io_write]  
  8,32   1        5     0.000011264 57376  U   N [direct_io_write] 1  
  8,32   1        6     0.000013478 57376  D  WS 272208 + 2 [direct_io_write]  
  8,32   0        1     0.000281069     0  C  WS 272208 + 2 [0]  

blktrace -a 参数可以指定监控的动作:

1.     blktrace /dev/block/mmcblk0p1 -o /data/trace    
命令解析:监控mmcblk0p1块设备,将生成的文件存储在/data目录下,一共生成4个文件,文件以trace开头,分别为  
  trace.blktrace.0    
  trace.blktrace.1   
  trace.blktrace.2  
  trace.blktrace.3  
  分别对应cpu0、cpu1、cpu2、cpu3  
  
2.     blktrace /dev/block/mmcblk0p1 -D /data/trace    
命令解析:监控mmcblk0p1块设备,在/data目录下建立一个名字为trace的文件夹,trace文件夹下存放的是名字为  
  mmcblk0p1.blktrace.0   
  mmcblk0p1.blktrace.1   
  mmcblk0p1.blktrace.2   
  mmcblk0p1.blktrace.3  
  分别对应cpu0 cpu1 cpu2 cpu3  
  
3.     blktrace /dev/block/mmcblk0p1 -o /data/trace -w 10    
命令解析:-w 选项表示多长时间之后停止监控(单位:秒)  -w 10 表示10秒之后停止监控  
  
4.     blktrace /dev/block/mmcblk0p1 -o /data/trace -a WRITE     
命令解析:-a 代表只监控写操作  
  
选项 -a action 表示要监控的动作,action的动作有:  
READ (读)  
WRITE(写)  
BARRIER  
SYNC  
QUEUE  
REQUEUE  
ISSUE  
COMPLETE  
FS  
PC  

其他工具:blkiomon

对设备/dev/sda的io监控120秒,每2秒显示一次

# blktrace /dev/sda -a issue -a complete -w 120 -o - | blkiomon  -I 2 -h -  
  
  
[root@localhost2 /data/sandbox/blktrace_test]  
# blktrace /dev/sda -a issue -a complete -w 120 -o - | blkiomon  -I 2 -h -  
  
time: Tue Nov 21 14:04:48 2017  
device: 8,0  
sizes read (bytes): num 0, min -1, max 0, sum 0, squ 0, avg 0.0, var 0.0  
sizes write (bytes): num 2, min 4096, max 49152, sum 53248, squ 2432696320, avg 26624.0, var 507510784.0  
d2c read (usec): num 0, min -1, max 0, sum 0, squ 0, avg 0.0, var 0.0  
d2c write (usec): num 2, min 8322, max 10708, sum 19030, squ 183916948, avg 9515.0, var 1423249.0  
throughput read (bytes/msec): num 0, min -1, max 0, sum 0, squ 0, avg 0.0, var 0.0  
throughput write (bytes/msec): num 2, min 492, max 4590, sum 5082, squ 21310164, avg 2541.0, var 4198401.0  
sizes histogram (bytes):  
            0:     0         1024:     0         2048:     0         4096:     1  
         8192:     0        16384:     0        32768:     0        65536:     1  
       131072:     0       262144:     0       524288:     0      1048576:     0  
      2097152:     0      4194304:     0      8388608:     0    > 8388608:     0  
d2c histogram (usec):  
            0:     0            8:     0           16:     0           32:     0  
           64:     0          128:     0          256:     0          512:     0  
         1024:     0         2048:     0         4096:     0         8192:     0  
        16384:     2        32768:     0        65536:     0       131072:     0  
       262144:     0       524288:     0      1048576:     0      2097152:     0  
      4194304:     0      8388608:     0     16777216:     0     33554432:     0  
    >33554432:     0  
bidirectional requests: 0  

参考

digoal's wechat