bcc-tools工具之funclatency

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类的函数没有打印出来
原文地址:https://www.cnblogs.com/haoxing990/p/12122372.html