在Linux中有很多用于调试内核和用户空间程序的工具。 它们中的大多数会影响性能，并且不能轻松地在生产环境中运行。 几年前，
开发了 eBPF，它提供了以低开销跟踪内核和用户空间的功能，而无需重新编译程序或加载内核模块。
现在有很多使用eBPF的工具，在本文中，我们将说明如何使用
PythonBCC库编写自己的分析工具。 本文基于生产环境中的实际问题。 我们将引导您解决问题，并说明在某些情况下如何使用现有的密件抄送工具。
Ceph很慢
新平台已添加到ceph集群。 将某些数据迁移到平台后，写入请求的等待时间比其他服务器上的等待时间长。
该平台具有一个新的缓存虚拟设备-bcache（我们之前未在此集群中使用过）和一个新内核-4.15，该内核在该集群中的其他任何地方均未使用。 问题的根源可能在任何地方，因此让我们更深入地研究一下。
调查主机
让我们看看ceph-osd进程内部发生了什么。 我们使用跟踪工具
perf和
Flamescope来构建火焰图：
从火焰图可以看出，
fdatasync（）花了很多时间在
generic_make_request（）函数中提交bio。 因此，我们问题的根源不在ceph守护程序之外。 可能是内核，bcache或磁盘问题。 iostat输出显示bcache设备的高延迟。
另一个可疑的发现是systemd-udevd守护程序正在消耗CPU；它是CPU。 在多个CPU上大约占20％。 这是奇怪的行为，所以我们必须找出正在发生的事情。 由于systemd-udevd可与uevents一起使用，因此我们必须使用
udevadm Monitor来确定系统中是否有任何uevents。 检查后，我们发现系统中的每个块设备都将生成许多“更改”事件。
这是不寻常的，因此我们将找出导致所有这些事件发送的原因。
使用BCC工具包
众所周知，内核（和ceph守护程序）花费大量时间来执行
generic_make_requst（）函数。 让我们使用
BCC工具包中的 funclatency来衡量其延迟，以确保我们走在正确的道路上。 我们将以1秒的间隔（-i）跟踪ceph守护程序的PID（-p参数），并以毫秒（-m）显示延迟。
此功能通常运行非常快。 它所做的只是将生物结构提交到设备驱动程序的队列中。
Bcache是一个复杂的设备； 实际上，它由3个设备组成：一个后备设备，在我们的例子中是慢速硬盘； 缓存设备，即NVMe驱动器的分区； 以及应用程序使用的bcache虚拟设备。 我们知道提交速度很慢，但是使用哪种设备？ 我们稍后会讨论这一点。
到目前为止，我们知道uevent会在ceph守护进程中导致问题，我们必须找到触发uevent的软件，要找到导致uevent生成的原因并不容易。 我们假设它是仅定期运行的软件。 要查看系统上正在执行什么，我们使用BCC工具箱中的
execsnoop 。 我们可以运行它并将
stdout重定向到文件。
例如：
/usr/share/bcc/tools/execsnoop | tee ./execdump
我们不会在此处提供完整的execsnoop输出，但是我们发现其中一个有趣的字符串是：
sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:/]' '{print $2}' | sed 's/^ \([0-9]*\) C.*/\1/'
第三列是流程的PPID。 我们检查了5802是什么，并发现它是我们的监视守护程序线程之一。 进一步查看监视系统配置，我们发现一个错误的参数。 每30秒钟检索一次HBA温度，这种情况经常发生。 将检查间隔更改为更合适的值后，我们看到我们的ceph延迟与其他平台匹配。
但是我们仍然不知道为什么bcache延迟如此之高。 我们建立了具有相同配置的测试平台，并尝试在bcache设备上重现fio问题，同时使用udevadm trigger命令触发udev。
编写基于BCC的工具
我们在这里要做的是编写一个简单的工具，该工具可以跟踪最慢的generic_make_request（）调用，并打印该函数所需要的磁盘的名称。
该计划很简单：
- 在generic_make_request（）上注册kprobe ：
- 在generic_make_request（）返回语句上注册kretprobe ：
- 检索当前时间戳
- 查找以前保存的时间戳并将其与当前时间戳进行比较
- 如果结果高于阈值，请查找先前保存的磁盘名称，并将其与其他信息一起打印到终端上
Kprobes和
kretprobes使用断点在运行时更改函数的代码。 您可以找到
文档以及关于此的很好的
文章 。 如果查看不同
BCC工具的代码，就会发现它们都具有相同的结构。 我们将跳过参数解析，而将重点放在BPF程序本身上。
我们程序的文本将在python中定义如下：
bpf_text = “””
BPF程序使用
哈希图在不同功能之间共享数据。 我们将使用PID作为键，并使用自定义结构作为值。
struct data_t { u64 pid; u64 ts; char comm[TASK_COMM_LEN]; u64 lat; char disk[DISK_NAME_LEN]; }; BPF_HASH(p, u64, struct data_t); BPF_PERF_OUTPUT(events);
在这里，我们使用
u64键类型和
struct data_t值类型注册一个名为
p的哈希映射。 可从我们的BPF程序上下文访问此地图。
BPF_PERF_OUTPUT宏注册另一个称为
事件的映射，该映射用于
将数据推送到用户空间。
在测量函数调用与其返回之间或一个函数调用与另一个函数调用之间的等待时间时，必须确保保存并稍后访问的数据与同一上下文相关。 换句话说，您必须知道同一功能的任何其他并行执行。 可以跟踪一个进程的函数调用与另一个进程的同一函数的返回之间的延迟，但这对我们没有帮助。
生物延迟工具就是一个很好的例子，其中将指向
结构请求的指针用作哈希映射键。
接下来，我们必须编写将通过kprobe机制在函数调用上执行的代码：
void start(struct pt_regs *ctx, struct bio *bio) { u64 pid = bpf_get_current_pid_tgid(); struct data_t data = {}; u64 ts = bpf_ktime_get_ns(); data.pid = pid; data.ts = ts; bpf_probe_read_str(&data.disk, sizeof(data.disk), (void*)bio->bi_disk->disk_name); p.update(&pid, &data); }
在这里，我们有第一个
generic_make_request（）参数作为函数的第二个参数。 然后，我们以纳秒为单位获取PID和当前时间戳，并将其写入新分配的
struct data_t data中 。 我们从bio结构中获取磁盘名称，并将其传递给
generic_make_request（） ，并将其保存到我们的
数据中 。 最后一步是将条目添加到我们之前描述的哈希图中。
该函数将在
generic_make_request（）返回时执行：
void stop(struct pt_regs *ctx) { u64 pid = bpf_get_current_pid_tgid(); u64 ts = bpf_ktime_get_ns(); struct data_t* data = p.lookup(&pid); if (data != 0 && data->ts > 0) { bpf_get_current_comm(&data->comm, sizeof(data->comm)); data->lat = (ts - data->ts)/1000; if (data->lat > MIN_US) { FACTOR data->pid >>= 32; events.perf_submit(ctx, data, sizeof(struct data_t)); } p.delete(&pid); } }
我们从先前的输出中获得PID和时间戳，并在哈希图中查找其中
key == current PID的值。 如果找到它，我们将得到正在运行的进程的名称，并将其添加到
数据结构中。 我们在这里使用
data-> pid所做的事情为我们提供了线程组ID。 先前调用的
bpf_get_current_pid_tgid（）函数以相同的64位值返回进程的线程GID和PID。
我们对每个线程的ID都不感兴趣，但是我们想知道主线程的PID。 在检查了延迟是否超过阈值之后，我们通过
事件映射将
数据结构提交给用户空间，然后最后删除哈希映射条目。
在我们的python脚本中，我们必须根据想要的阈值和想要在结果中看到的时间单位来替换
MIN_US和
FACTOR ：
bpf_text = bpf_text.replace('MIN_US',str(min_usec)) if args.milliseconds: bpf_text = bpf_text.replace('FACTOR','data->lat /= 1000;') label = "msec" else: bpf_text = bpf_text.replace('FACTOR','') label = "usec"
然后，我们必须使用
BPF（）宏准备BPF程序并注册探针：
b = BPF(text=bpf_text) b.attach_kprobe(event="generic_make_request",fn_name="start") b.attach_kretprobe(event="generic_make_request",fn_name="stop")
我们还需要在脚本中定义与
struct data_t相同的结构，以从BPF程序中读取数据：
TASK_COMM_LEN = 16
最后一步是打印所需的数据：
def print_event(cpu, data, size): global start event = ct.cast(data, ct.POINTER(Data)).contents if start == 0: start = event.ts time_s = (float(event.ts - start)) / 1000000000 print("%-18.9f %-16s %-6d %-1s %s %s" % (time_s, event.comm, event.pid, event.lat, label, event.disk)) b["events"].open_perf_buffer(print_event)
完整脚本可在
GitHub上获得 。 让我们运行脚本并在fio写入bcache设备时触发udev事件：
成功！ 现在，我们看到bcache的高延迟实际上是其后备设备的
generic_make_request（）延迟。
挖掘内核
提交请求时会拖累什么？ 我们看到在请求计费开始之前就出现了延迟高峰。 可以通过在问题期间运行iostat或
biolatency BCC脚本 （基于记帐请求启动）来轻松检查此问题，因此这两种工具都不会显示磁盘问题。
如果我们看一下
generic_make_request（） ，就会发现在开始记帐之前有两个函数正在运行。 第一个是
generic_make_request_checks（） ，它很轻巧，并根据设备设置等检查生物。 第二个是
blk_queue_enter（） ，它具有一个
wait_event_interruptible（）调用：
ret = wait_event_interruptible(q->mq_freeze_wq, (atomic_read(&q->mq_freeze_depth) == 0 && (preempt || !blk_queue_preempt_only(q))) || blk_queue_dying(q));
在这里，内核等待直到队列被冻结为止。 让我们测量一下blk_queue_enter（）的延迟：
~
看来我们接近了。 用于冻结/解冻队列的函数是
blk_mq_freeze_queue和
blk_mq_unfreeze_queue 。 它们用于更改队列设置，这可能会影响当前正在运行的io请求。 调用
blk_mq_freeze_queue（）时 ，
q-> mq_freeze_depth在
blk_freeze_queue_start（）中递增。 之后，内核在
blk_mq_freeze_queue_wait（）中等待队列为空。
此等待时间等于磁盘延迟，因为内核必须等待所有io操作完成。 当队列为空时，可以进行更改。 最后一步是调用
blk_mq_unfreeze_queue（） ，这会减少
Frozen_depth计数器。
现在我们知道足以解决此问题。 udevadm trigger命令更改块设备的设置。 这些设置在udev规则中进行了描述。 我们可以通过sysfs或查看内核源代码来更改冻结队列的设置。 另外，我们可以从BCC工具箱中
调用trace来为每个
blk_freeze_queue调用打印内核和用户堆栈：
~
Udev规则不会经常更改，因此即使将已经存在的值分配给某些参数也会导致应用程序的提交延迟高峰。 当然，当设备的配置没有任何变化（没有连接或分离设备）时生成udev事件不是一个好习惯。 尽管如此，如果没有理由，我们可以防止内核冻结队列。
三个 小的 提交解决了该问题。
结论
eBPF是高度灵活且功能强大的工具。 在本文中，我们仅研究了一种情况，并演示了其功能。 如果您对开发基于BCC的工具感兴趣，则应查看
官方教程 ，其中描述了其基本概念。
还有其他有趣的基于eBPF的工具可用于性能分析和调试。 其中之一是
bpftrace ，它使您可以使用类似于awk的语言编写功能强大的oneliners和小程序。 另一个是
ebpf_exporter ，它具有强大的可视化和警报功能，可以为您的prometheus服务器收集低级别的高分辨率指标。