bcc-tools工具之funcslower

笔者在使用funcslower这个函数时，发现其功能相比funclatency对时间更加具体化，对于想知道某个函数执行时间分布情况时，

采用funclatency是个不错的选择，但是对于急切想知道系统中某个函数被执行的时间时,使用funcslower再方便不过了。

funcslower字面意思，函数中的慢者，简而言之，用于更正系统中，那些进行调用执行时间超过了某个设定值。

这个功能可能会是你在多种系统分析工具都无效后，作为最后的诊断手段，用于系统性能问题分析了。

老样子，从help说起。

usage: funcslower [-hf] [-p PID] [-U | -K] [-m MIN_MS] [-u MIN_US] [-a ARGUMENTS] [-T]
                     [-t] [-v]
                     function [function ...]

Trace slow kernel or user function calls.

positional arguments:
  function              function(s) to trace

optional arguments:
  -h, --help            show this help message and exit
  -p PID, --pid PID     trace this PID only
  -m MIN_MS, --min-ms MIN_MS       # 执行时间低于xx毫秒，作为阈值
                        minimum duration to trace (ms)  
  -u MIN_US, --min-us MIN_US
                        minimum duration to trace (us)  #执行时间长于xx us，作为阈值
  -U, --user-stack
                        show stacks from user space     #显示用户态栈调用信息
  -K, --kernel-stack
                        show stacks from kernel space   #显示内核态栈调用信息
  -f                    print output in folded stack format. # 个人认为是用于生成火焰图时可以考虑
  -a ARGUMENTS, --arguments ARGUMENTS
                        print this many entry arguments, as hex  #打印输入参数，安装十进制的方式
  -T, --time            show HH:MM:SS timestamp                  # 显示时间戳
  -t, --timestamp       show timestamp in seconds at us resolution # 显示时间戳，采用秒的形式
  -v, --verbose         print the BPF program for debugging purposes # 显示该函数调用信息

./funcslower c:open -u 1

统计系统中执行open函数时延操作1us的进程

# ./funcslower c:open -u 1
Tracing function calls slower than 1 us... Ctrl+C to quit.  #comm吧表示执行的指令
COMM           PID    LAT(us)             RVAL FUNC
less           27074    33.77                3 c:open 
less           27074     9.96 ffffffffffffffff c:open 
less           27074     5.92 ffffffffffffffff c:open 
less           27074    15.88 ffffffffffffffff c:open 
less           27074     8.89                3 c:open 
less           27074    15.89                3 c:open 
sh             27075    20.97                4 c:open 
bash           27075    20.14                4 c:open 

需要注意的是： 上面出现fffffff等内容的是open函数操作返回值RVAL失败，返回-1;

./funcslower -m 10 vfs_read

只显示vfs_read函数调用执行时间超过10ms的进程

Tracing function calls slower than 10 ms... Ctrl+C to quit.
COMM           PID    LAT(ms)             RVAL FUNC
bash           11527    78.97                1 vfs_read 
bash           11527   101.26                1 vfs_read 
bash           11527  1053.60                1 vfs_read 
bash           11527    44.21                1 vfs_read 

./funcslower __kmalloc -a 2 -u 1

显示执行__kmalloc时间操作1us的进程，并且打印出每一个进程传入该函数的前两个参数值。

Tracing function calls slower than 1 us... Ctrl+C to quit.
COMM           PID    LAT(us)             RVAL FUNC ARGS
kworker/0:2    27077     7.46 ffff90054f9f8e40 __kmalloc 0x98 0x1400000
kworker/0:2    27077     6.84 ffff90054f9f8e40 __kmalloc 0x98 0x1400000
bash           11527     6.87 ffff90054f9f8e40 __kmalloc 0x90 0x1408240
bash           11527     1.15 ffff90054f9f8e40 __kmalloc 0x90 0x1408240
bash           11527     1.15 ffff90055a1b8c00 __kmalloc 0x2c 0x1400240
bash           11527     1.18 ffff90054b87d240 __kmalloc 0x1c 0x1400040

./funcslower -U -m 30 '/usr/sbin/nginx:database_write'

用于跟踪某一类特例程序里面的某个函数执行时间超过30ms的进程，并打印其用户态栈信息。

Tracing function calls slower than 30 ms... Ctrl+C to quit.
COMM           PID    LAT(ms)             RVAL FUNC
nginx          1617     30.15                9 /usr/sbin/nginx:database_write
    DataBaseProvider::setData(std::string const&, record_s&)
    UserDataProvider::saveRecordData(RecordData const&)
    RequestProcessor::writeResponse(int)
    RequestProcessor::processRequest()
    RequestRouter::processRequest(RequestWrapper*, ResponseWrapper*)
    ngx_http_core_content_phase
    ngx_http_core_run_phases
    ngx_http_process_request
    ngx_process_events_and_timers
    ngx_spawn_process
    ngx_master_process_cycle
    main
    __libc_start_main
    [unknown]