用bpftrace进行性能剖析–统计函数运行时间

bpftrace[1] 可以追踪用户态函数的函数开始(uprobe)和函数返回(uretprobe),由于我们在统计某个函数运行时间来进行性能剖析时,也经常用记下时间来统计函数的运行时间,所以利用这两种trace点,结合bpftrace提供的nsecslhist()等内置组件,我们可以将时间统计脚本和程序代码相分离。

本文以一个简单程序举例,希望读者能够在短时间内了解这种思想,进行灵活运用扩展。当然,复杂的统计需要更复杂的bpftrace脚本构造方法。

1. 被profile的程序

我写了一个称为sleep_prog的进行“随机正态睡眠”的小程序,代码如下[2]。(这个程序会调用sleep_func()函数1000次,每次的睡眠的时间是随机生成的,随机生成用10次[0, 100)的均匀分布之和模拟正态分布,所以,sleep_func()每次睡眠的时间应该类似均值为500 us的正态分布。)

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路径应该替换成你的程序的路径)

3. 测试和结果

Step 1.

在A终端,编译sleep_prog程序:

Step 2.

在B终端,用超级权限运行profile.d脚本:

Step 3.

在A终端,运行sleep_prog程序:

Step 4.

Ctrl+c结束掉A中断的bpftrace脚本,样例结果如下,可以看出,的确比较符合正态分布啊~


[1] https://github.com/zhangjaycee/real_tech/wiki/linux_017#bpftrace

[2] https://gist.github.com/zhangjaycee/d9e0b342c8984856cea944c5c4e24dc8

发表评论

电子邮件地址不会被公开。 必填项已用*标注