funclatency从字面意思就可以知道其作用是获取函数的执行时延(这里的时延可不是函数被延时了多长时间,而是函数执行了多长时间)
先funclatency --help查看下其支持的功能有哪些?
usage: funclatency [-h] [-p PID] [-i INTERVAL] [-d DURATION] [-T] [-u] [-m] [-F] [-r] [-v] pattern Time functions and print latency as a histogram 矩形图 positional arguments: pattern search expression for functions optional arguments: -h, --help show this help message and exit -p PID, --pid PID trace this PID only 指定跟踪某个进程ID各函数花费时间 -i INTERVAL, --interval INTERVAL 指定执行间隔时间,以秒为单位 summary interval, in seconds -d DURATION, --duration DURATION 指定该程序运行多次时间 total duration of trace, in seconds -T, --timestamp include timestamp on output 输出时间戳,即当前调用funlatency的具体时间 -u, --microseconds microsecond histogram 矩形图统计采用us的形式 -m, --milliseconds millisecond histogram 矩形图统计采用毫秒的形式 -F, --function show a separate histogram per function 每一个函数单独采用矩形图显示 -r, --regexp use regular expressions. Default is "*" wildcards 匹配规则,监测某一类函数 only. -v, --verbose print the BPF program (for debugging purposes) 打印调试信息
目前在用funclatency追踪函数执行时长时,有一个好处是可以直观的显示函数在某一段时间内运行情况,缺点是你无法知道函数在某个时间段内具体运行了多长时间。
下面简要的介绍下各参数的具体使用方法:
./funclatency do_sys_open
跟踪do_sys_open执行时长
nsecs : count distribution
0 -> 1 : 0 | |
2 -> 3 : 0 | |
4 -> 7 : 0 | |
8 -> 15 : 0 | |
16 -> 31 : 0 | |
32 -> 63 : 0 | |
64 -> 127 : 0 | |
128 -> 255 : 0 | |
256 -> 511 : 0 | |
512 -> 1023 : 0 | |
1024 -> 2047 : 0 | |
2048 -> 4095 : 0 | |
4096 -> 8191 : 1 |****************************************|
8192 -> 16383 : 0 | |
16384 -> 32767 : 1 |****************************************|
32768 -> 65535 : 1 |****************************************|
从上面可以清楚的看出,do_sys_open主要运行时间在4096 -> 8191 、16384 -> 32767、32768 -> 65535三个时间间隔内,显示时间为ns
./funclatency c:read
查看用户态动态库函数read执行时间分布情况
./funclatency -u vfs_read
矩形图时间间隔采用us显示
usecs : count distribution 0 -> 1 : 0 | | 2 -> 3 : 2 |************* | 4 -> 7 : 2 |************* | 8 -> 15 : 6 |****************************************|
./funclatency -m do_nanosleep
矩形图采用毫秒显示
./funclatency -i 2 -d 10 c:open
用户态跟踪open函数,以每隔2秒,一共跟踪10s的方式
./funclatency -mTi 5 vfs_read
每隔5s输出一次跟踪结果,并且每次都打印时间戳,矩形图显示单位为ms
06:30:49 msecs : count distribution 0 -> 1 : 64 |****************************************| 06:30:54 msecs : count distribution 0 -> 1 : 617 |****************************************| 2 -> 3 : 1 | | 4 -> 7 : 0 | | 8 -> 15 : 0 | | 16 -> 31 : 2 | |
./funclatency -p 181 vfs_read
只跟踪id为181的进程调用vfs_read的运行时间情况
./funclatency 'vfs_fstat*'
追踪vfs_fstat*类函数总共运行时间分布情况
Tracing 33 functions for "timer*"... Hit Ctrl-C to end. ^C nsecs : count distribution 0 -> 1 : 0 | | 2 -> 3 : 0 | | 4 -> 7 : 0 | | 8 -> 15 : 0 | | 16 -> 31 : 0 | | 32 -> 63 : 0 | | 64 -> 127 : 0 | | 128 -> 255 : 0 | | 256 -> 511 : 0 | | 512 -> 1023 : 28 |* | 1024 -> 2047 : 153 |****** | 2048 -> 4095 : 196 |******* | 4096 -> 8191 : 987 |****************************************|
./funclatency 'c:*printf'
追踪用户态动态函数*printf总共运行时间
./funclatency -F 'timer*'
显示 vfs_r*这类函数的每一个函数运行时间的矩形图
Tracing 33 functions for "timer*"... Hit Ctrl-C to end. Function = timer_clear_idle nsecs : count distribution 0 -> 1 : 0 | | 2 -> 3 : 0 | | 4 -> 7 : 0 | | 8 -> 15 : 0 | | 16 -> 31 : 0 | | 32 -> 63 : 0 | | 64 -> 127 : 0 | | 128 -> 255 : 0 | | 256 -> 511 : 0 | | 512 -> 1023 : 3 | | 1024 -> 2047 : 25 |***** | 2048 -> 4095 : 64 |************** | 4096 -> 8191 : 181 |****************************************|
后面的还有其他timer类的函数没有打印出来