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

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

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

1. 被profile的程序

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

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

#!/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程序:

gcc sleep_prog.c -o sleep_prog

Step 2.

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

sudo profile.d

Step 3.

在A终端,运行sleep_prog程序:

./sleep_prog

Step 4.

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

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

Leave a Reply

Your email address will not be published. Required fields are marked *