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

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

本文以一个简单程序举例，希望读者能够在短时间内了解这种思想，进行灵活运用扩展。当然，复杂的统计需要更复杂的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

JciX ~

Jc's Blog