结合例子学习eBPF与bcc：初探

AshinZ

发布于 2023-11-01 17:09:56

2970

发布于 2023-11-01 17:09:56

文章被收录于专栏：程栩的性能优化笔记程栩的性能优化笔记

引

当你问ChatGPT：eBPF和bcc是什么？

eBPF是一种内核技术，它允许用户在不修改内核源代码的情况下，通过一种安全的、可编程的方式来扩展内核功能。BCC是一组用于eBPF的工具和库，它们使开发人员能够使用高级语言编写eBPF程序，从而更轻松地构建和部署内核跟踪和监控工具。

本文不会介绍eBPF和bcc的由来和历史，而是会基于bcc文档中的例子来介绍与学习ebpf和bcc。

eBPF和bcc后续简写为bcc。本文提到的例子均出现在bcc仓库examples下。

Hello World

让我们来看看计算机中不可避免的Hello World例子：

from bcc import BPF

BPF(text='int kprobe__sys_clone(void *ctx) { bpf_trace_printk("Hello, World!\\n"); return 0; }').trace_print()

让我们运行一下：

[root@VM-16-2-centos bcc]# ./examples/hello_world.py 
b'           <...>-3512395 [000] d... 9506128.282815: bpf_trace_printk: Hello, World!'

在这里我们需要知道以下的一些知识点：

text='...'里面的内容是真正的eBPF程序，是用C 编写的，而我们这里使用的bcc可以认为是eBPF的一个前端，通过它快速的编写eBPF程序；这段代码是注入到内核中执行的，所以调用的时候请注意用root权限；如果没有输出的话可以打开一个新的shell然后随便执行一些命令；
kprobe__sys_clone()：这里通过了一个内核探针来进行内核动态追踪，其命名规则是kprobe__，后面跟相关的内核函数名，例如这里是sys_clone；
void *ctx：这里ctx中也包含了一些参数，但是在这个例子中用不到；
bpf_trace_printk：按照referance_guide中的说明，这个函数是bcc的一个辅助函数，用于将printf的结果输出到trace_pipe，注意这里的trace_pipe是全局共享，因此并发时会有冲突，可以用BPF_PERF_OUTPUT替代；
return 0：eBPF程序必需的组成部分；
.trace_point()：bcc进程会通过这个方式读取trace_pipe的内容并打印；

这段代码的意思是追踪sys_clone这个系统调用，一旦该系统调用触发，就输出Hello, World!。这个程序被执行以后，会先将text='...'的内容注入到内核中，挂载到sys_clone这个函数开始的地方。内核每次执行sys_clone的时候，都会执行我们注入的函数，也即输出Hello, World!。

如何查看全部的`kprobe`列表？

可以首先挂载debugfs：

mkdir debugfs
mount -t debugfs none debugfs/
cd debugfs
cat kprobe/list

或者直接通过：

/sys/kernel/debug/kprobes/list

如下图所示：

kprobe

通过这种方式，我们可以得到已注册(registered)的kprobe列表，如果要查看可获得(available)的kprobe，可以通过：

cat  /sys/kernel/debug/tracing/available_filter_functions

sys_sync

学习了如何追踪sys_clone后，让我们尝试追踪一下sys_sync吧。

ChatGPT说：sys_sync是一个系统调用，它将所有已修改的文件系统缓存数据写入磁盘，以确保数据的持久性。在调用sys_sync之后，文件系统缓存数据将与磁盘上的数据同步，因此在系统崩溃或意外断电等情况下，不会丢失数据。sys_sync通常由系统管理员或应用程序在执行重要操作之前调用，例如进行备份或升级操作。但是，由于sys_sync需要将所有数据写入磁盘，因此可能会导致系统性能下降。

基于我们刚才的学习，我们可以修改代码如下所示：

#!/usr/bin/python

from bcc import BPF

BPF(text='int kprobe__sys_sync(void *ctx) { bpf_trace_printk("Sync!!!\\n"); return 0; }').trace_print()

运行一下看看：

[root@VM-16-2-centos examples]# ./sync.py

似乎短时间内没有输出，这可能是因为系统并没有什么写入操作，我们新起一个终端，手动触发一下：

[root@VM-16-2-centos examples]# sync

可以看到现在就有输出了：

sync

hello_fields.py

前面我们介绍了很简短的bcc程序例子，那么比较长的程序我们该如何编写呢？我们来学习/tracing/hello_fields.py：

#!/usr/bin/python
#
# This is a Hello World example that formats output as fields.

from bcc import BPF
from bcc.utils import printb

# define BPF program
prog = """
int hello(void *ctx) {
    bpf_trace_printk("Hello, World!\\n");
    return 0;
}
"""

# load BPF program
b = BPF(text=prog)
b.attach_kprobe(event=b.get_syscall_fnname("clone"), fn_name="hello")

# header
print("%-18s %-16s %-6s %s" % ("TIME(s)", "COMM", "PID", "MESSAGE"))

# format output
while 1:
    try:
        (task, pid, cpu, flags, ts, msg) = b.trace_fields()
    except ValueError:
        continue
    except KeyboardInterrupt:
        exit()
    printb(b"%-18.9f %-16s %-6d %s" % (ts, task, pid, msg))

从注释上我们可以看出，其整体是对Hello World例子的格式更换，我们需要了解如下几点：

prog =：我们通过先声明源码的方式声明了eBPF的代码，然后再将其载入到我们的bcc前端中，这样的话，我们就可以更好的编写代码了。
hello()：这是我们声明的一个C函数，这个函数后续会被挂载到对应的函数调用上，其传入的参数ctx必须要放在函数第一位；
b.attach_probe(event=b.get_syscall_fnname("clone"), fn_name="hello")：这段话的意思是将我们前面声明的hello函数挂载到sys_clone这个内核探针上，我们可以多次调用进行多次挂载，比如同时将hello挂载到sys_sync上，这样就不需要重复编写了；
trace_fields()：是一个bcc的辅助函数，可以读取trace_pipe的内容并进行划分，可以在调试的时候使用，正式使用还是建议通过BPF_PERF_OUTPUT机制；

阅读代码我们发现，这个程序并没有对Hello World做太大的变更，只是对程序的写法做了更好的调整，从而能够让我们更好的开发。由于clone触发过于频繁，在这里我们调整为对sync的追踪，并且添加两个追踪函数：

# define BPF program
prog = """
int hello(void *ctx) {
    bpf_trace_printk("Hello, World!\\n");
    return 0;
}

int sync(void *ctx) {
    bpf_trace_printk("Hello, Sync!\\n");
    return 0;
}
"""

# load BPF program
b = BPF(text=prog)
b.attach_kprobe(event=b.get_syscall_fnname("sync"), fn_name="hello")
b.attach_kprobe(event=b.get_syscall_fnname("sync"), fn_name="sync")

运行看看：

hello_sync

可以看到两个挂载函数都执行了，比起前面的例子可读性更强。

sync_timing.py

正如ChatGPT告诉我们的，sys_sync需要将所有数据写入磁盘，因此可能会导致系统性能下降。sys_sync执行会花多少时间呢？如果有人短时间内多次运行sys_sync，我们就需要给出警示，该如何实现呢？

实现这个需求，我们自然而然的会想到：得记录一下sys_sync每次执行出现的时间，然后进行计算和提示。也即：「eBPF中如何保存数据呢？」

我们学习一下/tracing/sync_timing.py，如果 1 秒之内多次使用了 sync ，它会告诉我们到底 do_sync 花了多少时间。也即如果使用了 sync;sync;sync ，后面两次 sync 会被打印出来：

#!/usr/bin/python
#
# sync_timing.py    Trace time between syncs.
#                   For Linux, uses BCC, eBPF. Embedded C.
#
# Written as a basic example of tracing time between events.
#
# Copyright 2016 Netflix, Inc.
# Licensed under the Apache License, Version 2.0 (the "License")

from __future__ import print_function
from bcc import BPF
from bcc.utils import printb

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

BPF_HASH(last); // 声明全局哈希 {0: xxx}

int do_trace(struct pt_regs *ctx) {
    u64 ts, *tsp, delta, key = 0; // 由于只有一个键值对，所以key=0

    // attempt to read stored timestamp
    tsp = last.lookup(&key); // 寻找 key = 0的哈希值
    if (tsp != NULL) { // 能够找到 也即tsp是0对应的值，也即上次执行sync的时间
        delta = bpf_ktime_get_ns() - *tsp; // 计算两次执行的差值
        if (delta < 1000000000) { // 差值过小，短时间内执行多次sync
            // output if time is less than 1 second
            bpf_trace_printk("%d\\n", delta / 1000000); // 通过bpf_trace_printk提示
        }
        last.delete(&key); // 删除键值对，这是一个内核bug，已在4.8.10修复
    }

    // update stored timestamp
    ts = bpf_ktime_get_ns(); // 获取当前时间，重新存储到0位置
    last.update(&key, &ts);
    return 0;
}
""")

b.attach_kprobe(event=b.get_syscall_fnname("sync"), fn_name="do_trace") # 挂载do_trace到sync
print("Tracing for quick sync's... Ctrl-C to end")

# format output
start = 0
while 1:
    try:
        (task, pid, cpu, flags, ts, ms) = b.trace_fields()
        if start == 0:
            start = ts
        ts = ts - start
        printb(b"At time %.2f s: multiple syncs detected, last %s ms ago" % (ts, ms))
    except KeyboardInterrupt:
        exit()

在这个程序中，我们需要了解到：

bpf_ktime_get_ns()：返回表示当前时间的u64类别的纳秒数；
BPF_HASH(last)：创建一个叫做last的BPF哈希，key和value都是默认的u64类型。我们可以想象这是一个很大的哈希表，可以存储我们可能用到的数据，从而在多个不同的函数中使用；该函数可以在reference_guide查看更多信息；
key = 0：只有一个键值对，所以key为零；
last.lookup(&key)：通过key去全局哈希表里面找对应的值，找到的话返回值，否则返回空；
last.delete(&key)：从哈希中删除键值对，这是一个内核bug，已经在4.8.10中修复；
last.update(&key, &ts)：传入两个参数，覆盖更新原有的键值对；

运行看看：

sync_timing.py

sync_count.py

我们通过sync_timing检测到了多次短时间内调用sync的情况，那么分别调用了多少次呢？让我们来实现一个sync_count.py。

需求是：统计sync调用的次数以及短时间内调用sync的次数。前者很容易理解，后者我们可以认为是被检测到sync运行过快的次数。

我们该如何实现呢？显然这里我们需要做一些数据的保存工作，那么BPF_HASH一定是需要用到的，看起来只要保存对应的数据就可以了，让我们试试吧。

我们可以复用BPF_HASH(last)，在其中的key=1和key=2的位置分别保存两个数据：

    u64 *all_count, *detected_count; // 指针
    u64 all_count_key = 1;
    u64 detected_count_key = 2;
    u64 all_count_data = 0, detected_count_data = 0; // 值类型

接着，修改do_trace函数，首先获取到原来的值：

// get sync all count
all_count = last.lookup(&all_count_key);
if (all_count != NULL) {
    all_count_data = *all_count;
}
// get sync detected count
detected_count = last.lookup(&detected_count_key);
if (detected_count != NULL) {
    detected_count_data = *detected_count;
} else {
    detected_count_data = 0;
}

由于all_count每次都会更新，我们直接更新：

// update sync all count
all_count_data += 1;
last.delete(&all_count_key);
last.update(&all_count_key, &all_count_data);

接着我们在检测到短时间内多次执行的逻辑中添加更新detected_count的逻辑：

if (delta < 1000000000) {
    // output if time is less than 1 second
    bpf_trace_printk("%d\\n", delta / 1000000);

    // update detected_count_data
    detected_count_data += 1;
    last.delete(&detected_count_key);
    last.update(&detected_count_key, &detected_count_data);
}
last.delete(&key);

由于我们使用bpf_trace_printk作为输出函数，为了避免输出不一致的情况，我们添加一个变量来存储delta_time，如果检测到了短时间内多次执行则delta_time就是间隔时间，否则是零，然后统一输出：

u64 delta_time = 0;
if (tsp != NULL) {
    delta = bpf_ktime_get_ns() - *tsp;
    if (delta < 1000000000) {
        // output if time is less than 1 second
        delta_time = delta / 1000000;

        // update detected_count_data
        detected_count_data += 1;
        last.delete(&detected_count_key);
        last.update(&detected_count_key, &detected_count_data);
    }
    last.delete(&key);
}
bpf_trace_printk("%d,%d,%d\\n", delta_time, all_count_data , detected_count_data);

bpf_trace_printk的输出本质上是个字符串，所以我们需要自行解析：

        (task, pid, cpu, flags, ts, all_data) = b.trace_fields()
        delta_time, all_count, detected_count = all_data.split(b',')
        if start == 0:
            start = ts
        ts = ts - start
        if delta_time is not b'0':
            printb(b"At time %.2f s: multiple syncs detected, last %s ms ago, all_count:%s, detected_count: %s" % (ts, delta_time, all_count, detected_count))
        else:
            printb(b"At time %.2f s: all_count:%s, detected_count: %s" % (ts, all_count, detected_count))

通过判断delta_time是否为0来区分两种情况并输出。让我们运行一下试试：

sync_count

看起来确实实现了我们的需求。

sync_count

#!/usr/bin/python

from __future__ import print_function
from bcc import BPF
from bcc.utils import printb

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

BPF_HASH(last);

int do_trace(struct pt_regs *ctx) {
    u64 ts, *tsp, delta, key = 0;
    u64 *all_count, *detected_count;
    u64 all_count_key = 1;
    u64 detected_count_key = 2;
    u64 all_count_data = 0, detected_count_data = 0;

    // get sync all count
    all_count = last.lookup(&all_count_key);
    if (all_count != NULL) {
        all_count_data = *all_count;
    }

    // get sync detected count
    detected_count = last.lookup(&detected_count_key);
    if (detected_count != NULL) {
        detected_count_data = *detected_count;
    } else {
        detected_count_data = 0;
    }

    // update sync all count
    all_count_data += 1;
    last.delete(&all_count_key);
    last.update(&all_count_key, &all_count_data);


    // attempt to read stored timestamp
    tsp = last.lookup(&key);
    u64 delta_time = 0;
    if (tsp != NULL) {
        delta = bpf_ktime_get_ns() - *tsp;
        if (delta < 1000000000) {
            // output if time is less than 1 second
            delta_time = delta / 1000000;

            // update detected_count_data
            detected_count_data += 1;
            last.delete(&detected_count_key);
            last.update(&detected_count_key, &detected_count_data);
        }
        last.delete(&key);
    }

    // update stored timestamp
    ts = bpf_ktime_get_ns();
    last.update(&key, &ts);
    bpf_trace_printk("%d,%d,%d\\n", delta_time, all_count_data , detected_count_data);
    return 0;
}
""")

b.attach_kprobe(event=b.get_syscall_fnname("sync"), fn_name="do_trace")
print("Tracing for quick sync's... Ctrl-C to end")

# format output
start = 0
while 1:
    try:
        (task, pid, cpu, flags, ts, all_data) = b.trace_fields()
        delta_time, all_count, detected_count = all_data.split(b',')
        if start == 0:
            start = ts
        ts = ts - start
        if delta_time is not b'0':
            printb(b"At time %.2f s: multiple syncs detected, last %s ms ago, all_count:%s, detected_count: %s" % (ts, delta_time, all_count, detected_count))
        else:
            printb(b"At time %.2f s: all_count:%s, detected_count: %s" % (ts, all_count, detected_count))
    except KeyboardInterrupt:
        exit()

本文参与腾讯云自媒体分享计划，分享自微信公众号。

原始发表：2023-08-20，如有侵权请联系 cloudcommunity@tencent.com 删除

count