bcc测量函数执行时间

获取函数的执行时间对性能分析十分有益，这里给出一个示例来测量kernel 函数的执行时间。

kprobe可用来在函数执行的开始加入探测点，kretprobe可以在函数返回前加入探测点，分别在这个两个探测获取时间，其差值可以作为函数的执行时间。相对ftrace，这种方式要精确很多。下面是一个例子，测量__smp_call_single_queue的执行时间。

#!/usr/bin/python3
from bpfcc import BPF
import time

# BPF program
b = BPF(text="""
#include <uapi/linux/ptrace.h>
#include <linux/sched.h>

    struct data_t {
    u64 delta;
    u32 pid;
    u64 ts;
    u64 cpu;
    char comm[TASK_COMM_LEN];
};

BPF_PERF_OUTPUT(events);

BPF_HASH(start, u32);
BPF_HASH(arg0, u32);
int begin(struct pt_regs *ctx, int cpu) {
    struct data_t data = {};
    u64 pid_tgid = bpf_get_current_pid_tgid();
    u32 pid = pid_tgid >> 32;
    u32 tid = (u32)pid_tgid;
    u64 ts, c = 0;

    c = (u64)cpu;

    bpf_get_current_comm(&data.comm, sizeof(data.comm));
    if (data.comm[0] != 's' || data.comm[1] != 'c' || data.comm[2] != 'h')
        return 0;
    arg0.update(&tid, &c);
    ts = bpf_ktime_get_ns();
    start.update(&tid, &ts);
    return 0;
};

int end(struct pt_regs *ctx) {
    struct data_t data = {};
    u32 tid;
    u64 *tsp, ts, delta;
    u64 *cpu;

    ts = bpf_ktime_get_ns();
    tid = (u32)bpf_get_current_pid_tgid();
    data.ts = ts;
    bpf_get_current_comm(&data.comm, sizeof(data.comm));
    if (data.comm[0] != 's' || data.comm[1] != 'c' || data.comm[2] != 'h')
        return 0;

    tsp = start.lookup(&tid);
    if (tsp == 0) return 0;     // check hash value before do next，otherwise， error out on compiling
    start.delete(&tid);

    cpu = arg0.lookup(&tid);
    if (cpu == 0) return 0;
    arg0.delete(&tid);

    data.pid = bpf_get_current_pid_tgid();
    delta = ts - *tsp;
    data.delta = delta;
    data.cpu = *cpu;
    events.perf_submit(ctx, &data, sizeof(data));
    return 0;
};
""")

b.attach_kprobe(event="__smp_call_single_queue", fn_name="begin")
b.attach_kretprobe(event="__smp_call_single_queue", fn_name="end")
# header
print("%-18s %-6s %s %-18s %-18s %-10s %-10s" % ("ELAPS(ns)", "TID", "CALL", "COUNT", "DELTA(ns)", "CUR_CPU", "PEER_CPU"))

count = 0
tstamp = 0
# process event
def print_event(cpu, data0, size):
    global count
    global tstamp
    count += 1
    now = time.time_ns()
    delta = now - tstamp
    tstamp = now
    event = b["events"].event(data0)
    print("%-18d %-6d %-10s %-18d %-18d %-10d %-10d" % (event.delta,
        event.pid, event.comm, count, delta, cpu, event.cpu))

# loop with callback to print_event
b["events"].open_perf_buffer(print_event)
while 1:
    try:
        b.perf_buffer_poll()
    except KeyboardInterrupt:
        exit()

这个例子提供了bcc的多种接口的用法。包含：

• kprobe和kretprobe；
• 获取函数入参，c函数的第一个参数指定为struct pt_regs *ctx，他包含了函数入参，上下文等。第二个参数指定探测点的第一个参数。
• 使用perf buff作为输出：这里使用BPF_PERF_OUTPUT声明一个全局的buff变量，使用perf_submit来向buff加入内容，使用python的bpf库函数open_perf_buffer给输出注册回调函数，使用perf_buffer_poll输出结果；
• 使用BPF_HASH声明一个map作为全局变量使用，这样就可以在两个c函数之间传递信息，使用update接口添加key，value对，使用lookup接口获取key对应的value，记住，必须检查value是否不为0再做下一步，否则会编译报错，获取value后删除该键值对。
• 使用bpf_get_current_pid_tgid获取线程tid；
• 使用bpf_get_current_comm获取用户态命令；
• 使用bpf_ktime_get_ns获取当前的纳秒时间，记住，在入口点c函数的末尾获取时间，在返回点c函数的开始获取时间，这样测量得到的时间最准确，因为c函数在做一些操作的耗时不可忽略；
• 开头的from bpfcc import BPF在centos系统上是对的，在ubuntu上需要修改为from bcc import BPF;

本例并不完美，在过滤command时使用了tricky的方法，还需寻找更优雅的方式。