bpftrace[1] 可以追踪用户态函数的函数开始(uprobe
)和函数返回(uretprobe
),由于我们在统计某个函数运行时间来进行性能剖析时,也经常用记下时间来统计函数的运行时间,所以利用这两种trace点,结合bpftrace提供的nsecs
、lhist()
等内置组件,我们可以将时间统计脚本和程序代码相分离。
本文以一个简单程序举例,希望读者能够在短时间内了解这种思想,进行灵活运用扩展。当然,复杂的统计需要更复杂的bpftrace脚本构造方法。
1. 被profile的程序
我写了一个称为sleep_prog
的进行“随机正态睡眠”的小程序,代码如下[2]。(这个程序会调用sleep_func()
函数1000次,每次的睡眠的时间是随机生成的,随机生成用10次[0, 100)的均匀分布之和模拟正态分布,所以,sleep_func()
每次睡眠的时间应该类似均值为500 us的正态分布。)
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 |
#include <stdio.h> #include <stdlib.h> #include <unistd.h> #include <time.h> void sleep_func(int sleep_time_us) { usleep(sleep_time_us); } int main() { int lower = 0, upper = 100; srand(time(0)); for (int k = 1000; k > 0; k--) { int sleep_time_us = 0; for (int i = 0; i < 10; i++) { sleep_time_us += rand() % (upper - lower) + lower; } printf("us: %d\n", sleep_time_us); sleep_func(sleep_time_us); } return 0; } |
2. 用于统计的bpftrace脚本
bptrace工具接收脚本文件作为参数,这里我将它命名为profile.d
,代码如下[2]。容易看出,我们需要追踪两个探针,分别是sleep_func()
函数的开始(uprobe
)和结束(‘uretprobe’),在“开始探针”部分,我们利用内置的nsecs
变量记下当前的时间到我们自定义的变量@t_start
中;在"结束探针"中,我们将当前时间nsecs
与@t_start
相减作为本次sleep_func函数的运行时间,以内置的lhist
直方图的形式存储到@my_host
变量中,并清零@t_start
。这样,在这个bpftrace脚本被Ctrl+c
结束后,一个sleep_func()
函数的运行时间分布直方图就会被打印出来。(注意: 脚本里的/home/zjc/test/sleep_prog
路径应该替换成你的程序的路径)
1 2 3 4 5 6 7 8 9 10 11 12 13 14 |
#!/usr/bin/bpftrace uprobe:/home/zjc/test/sleep_prog:sleep_func { @t_start=nsecs; } uretprobe:/home/zjc/test/sleep_prog:sleep_func /@t_start/ { @my_hist = lhist(nsecs - @t_start, 0, 10000000, 50000); clear(@t_start); } |
3. 测试和结果
Step 1.
在A终端,编译sleep_prog
程序:
1 2 |
gcc sleep_prog.c -o sleep_prog |
Step 2.
在B终端,用超级权限运行profile.d
脚本:
1 2 |
sudo profile.d |
Step 3.
在A终端,运行sleep_prog
程序:
1 2 |
./sleep_prog |
Step 4.
用Ctrl+c
结束掉A中断的bpftrace脚本,样例结果如下,可以看出,的确比较符合正态分布啊~
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 |
zjc@test $ sudo ./profile.d [sudo] password for zjc: Attaching 2 probes... ^C @my_hist: [250000, 300000) 1 | | [300000, 350000) 6 |@@ | [350000, 400000) 14 |@@@@@@ | [400000, 450000) 39 |@@@@@@@@@@@@@@@@ | [450000, 500000) 63 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ | [500000, 550000) 120 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@| [550000, 600000) 82 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ | [600000, 650000) 96 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ | [650000, 700000) 53 |@@@@@@@@@@@@@@@@@@@@@@ | [700000, 750000) 18 |@@@@@@@ | [750000, 800000) 7 |@@@ | [800000, 850000) 0 | | [850000, 900000) 0 | | [900000, 950000) 0 | | [950000, 1000000) 0 | | [1000000, 1050000) 0 | | [1050000, 1100000) 0 | | [1100000, 1150000) 0 | | [1150000, 1200000) 1 | | |
[1] https://github.com/zhangjaycee/real_tech/wiki/linux_017#bpftrace
[2] https://gist.github.com/zhangjaycee/d9e0b342c8984856cea944c5c4e24dc8