从高Ceph延迟到使用eBPF / BCC的内核补丁

图片

Linux有大量的内核调试工具和应用程序。 它们中的大多数会对应用程序性能产生不利影响,因此不能在生产中使用。

几年前, 开发了另一种工具 -eBPF。 这样就可以以较低的开销跟踪内核和用户应用程序,而无需重建程序并将第三方模块加载到内核中。

现在有许多使用eBPF的应用程序实用程序,在本文中,我们将研究如何基于PythonBCC库编写我们自己的分析实用程序。 本文基于真实事件。 我们将从问题的出现到纠正问题,以说明如何在特定情况下使用现有实用程序。

Ceph很慢


新主机已添加到Ceph集群。 将一些数据迁移到其中之后,我们注意到处理写入请求的速度比其他服务器上的速度要低得多。


与其他平台不同,此主机上使用了bcache和新的linux 4.15内核。 首次在此使用此配置的主机。 到那时,很明显,理论上任何事情都可能成为问题的根源。

调查主机


首先,让我们看看ceph-osd进程内部发生了什么。 为此,我们使用perfflamescope (有关更多信息,请参见 ):


图片告诉我们fdatasync()函数花了很多时间将请求发送给generic_make_request()函数。 这意味着最有可能导致问题的原因是osd守护程序本身之外的某个地方。 它可以是内核,也可以是磁盘。 iostat输出在使用bcache磁盘处理请求时显示高延迟。

检查主机时,我们发现systemd-udevd守护程序消耗大量CPU时间-在多个内核上大约占20%。 这是一种奇怪的行为,因此您需要找出其原因。 由于Systemd-udevd可与uevents配合使用,因此我们决定通过udevadm Monitor对其进行查看。 事实证明,为系统中的每个块设备生成了大量更改事件。 这是非常不寻常的,因此您将需要查看产生所有这些事件的原因。

使用BCC工具包


正如我们已经发现的那样,内核(以及系统调用中的ceph守护程序)在generic_make_request()中花费了大量时间。 让我们尝试测量此功能的速度。 密件抄送已经具有很好的实用性。 我们将通过守护进程的PID跟踪守护进程,其信息输出之间的间隔为1秒,并以毫秒为单位输出结果。


通常此功能是快速的。 她所做的只是将请求发送到设备驱动程序队列。

Bcache是一个复杂的设备,实际上包含三个磁盘:

  • 备份设备(缓存的磁盘),在这种情况下,它是慢速硬盘;
  • 缓存设备(缓存磁盘),这里是NVMe设备的一部分;
  • 应用程序可使用的bcache虚拟设备。

我们知道请求传输很慢,但是对于这些设备中的哪个设备呢? 我们稍后会处理。

现在我们知道,事件可能会引起问题。 要找到真正导致其生成的原因并不是那么简单。 假设这是一种定期运行的软件。 让我们看看使用同一套BCC实用程序中execsnoop脚本在系统上启动了哪种软件。 运行它,并将输出定向到文件。

例如,像这样:

/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(父PID)。 PID 5802的过程被证明是我们监控系统的线程之一。 检查监视系统的配置时,发现错误的参数。 每30秒测量一次HBA适配器的温度,这比所需的温度要高得多。 将验证间隔更改为更长的间隔后,我们发现在此主机上处理请求的延迟不再与其他主机脱颖而出。

但是,尚不清楚为什么bcache设备这么慢。 我们准备了具有相同配置的测试平台,并尝试通过在bcache上运行fio来重现该问题,并定期启动udevadm触发器以生成uevent。

编写基于BCC的工具


让我们尝试编写一个简单的实用程序,以跟踪和显示对generic_make_request()的最慢调用。 我们也对调用此函数的驱动器名称感兴趣。

该计划很简单:

  • kprobe注册到generic_make_request()
    • 我们保存可以通过function参数访问的磁盘名称;
    • 保存时间戳。

  • 注册kretprobe以从generic_make_request()返回:
    • 获取当前时间戳;
    • 我们搜索保存的时间戳并将其与当前时间戳进行比较;
    • 如果结果大于指定的结果,那么我们将找到保存的磁盘名称并将其显示在终端上。

Kprobeskretprobes使用断点机制动态更改功能代码。 您可以阅读有关此主题的文档和一篇不错的文章。 如果查看BCC中各种实用程序的代码,您会发现它们具有相同的结构。 因此,在本文中,我们将省略脚本参数的分析,然后转到BPF程序本身。

python脚本中的eBPF文本如下所示:

 bpf_text = “”” # Here will be the bpf program code “”” 

为了在函数之间交换数据,eBPF程序使用哈希表 。 我们也会。 作为关键字,我们将使用流程的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); 

在这里,我们注册了一个名为p的哈希表,该哈希表的键类型为u64,而值的类型为struct data_t 。 该表将在我们的BPF程序的上下文中可用。 BPF_PERF_OUTPUT宏注册另一个表,称为事件 ,用于将数据传输到用户空间。

在测量函数调用与函数调用之间的延迟或对不同函数的调用之间的延迟时,应牢记所接收的数据必须属于同一上下文。 换句话说,您需要记住可能并行启动的功能。 我们有机会测量在一个进程的上下文中调用一个函数与在另一个进程的上下文中从该函数返回之间的延迟,但这很可能是无用的。 一个很好的例子是biolatency实用程序 ,其中将指向结构请求的指针(反映单个磁盘请求 )设置为哈希表中的键。

接下来,我们需要编写在调用被调查函数时将运行的代码:

 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和时间戳,但不会为新的数据结构分配内存。 相反,我们在哈希表中查找键==当前PID的现有结构。 如果找到该结构,那么我们将找出正在运行的进程的名称并将其添加到其中。

为了获得线程GID,需要在此处使用二进制移位。 即 在我们正在工作的上下文中启动线程的主要进程的PID。 我们正在调用bpf_get_current_pid_tgid()函数以一个64位值返回线程的GID及其PID。

当输出到终端时,现在我们对流不感兴趣,而对主要过程感兴趣。 在将接收到的延迟与给定阈值进行比较之后,我们通过事件表将数据结构传输到用户空间,然后从p中删除记录。

在将加载此代码的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 ,否则我们将无法读取任何内容:

 TASK_COMM_LEN = 16 # linux/sched.h DISK_NAME_LEN = 32 # linux/genhd.h class Data(ct.Structure): _fields_ = [("pid", ct.c_ulonglong), ("ts", ct.c_ulonglong), ("comm", ct.c_char * TASK_COMM_LEN), ("lat", ct.c_ulonglong), ("disk",ct.c_char * DISK_NAME_LEN)] 

最后一步是将数据输出到终端:

 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) # format output start = 0 while 1: try: b.perf_buffer_poll() except KeyboardInterrupt: exit() 

该脚本本身在GItHub可用 。 让我们尝试在使用bcache编写fio并调用udevadm monitor的测试平台上运行它:


终于! 现在,我们看到看起来像制动的bcache设备实际上是对已缓存驱动器上的generic_make_request()的制动调用。

挖掘内核


在传输请求的过程中到底放慢了什么? 我们看到延迟甚至发生在请求开始计费之前,即 尚未解决针对特定请求进行进一步统计的请求(/ proc / diskstats或iostat)。 通过在重现问题时运行iostat或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()

 ~# /usr/share/bcc/tools/funclatency blk_queue_enter -i 1 -m Tracing 1 functions for "blk_queue_enter"... Hit Ctrl-C to end. msecs : count distribution 0 -> 1 : 341 |****************************************| msecs : count distribution 0 -> 1 : 316 |****************************************| msecs : count distribution 0 -> 1 : 255 |****************************************| 2 -> 3 : 0 | | 4 -> 7 : 0 | | 8 -> 15 : 1 | | 

看来我们已经接近解决方案。 用于“冻结/解冻”队列的函数是blk_mq_freeze_queueblk_mq_unfreeze_queue 。 当需要更改查询队列的设置时使用它们,这对于此队列中的查询可能具有危险。 调用blk_mq_freeze_queue()时blk_freeze_queue_start()函数将递增q-> mq_freeze_depth计数器 。 之后,内核在blk_mq_freeze_queue_wait()中等待空队列。

清除该队列的等待时间等同于磁盘延迟,因为内核会等待所有排队的操作完成。 队列为空时,将应用对设置的更改。 然后, 调用blk_mq_unfreeze_queue() ,递减计数器Frozen_depth

现在我们知道足够纠正这种情况了。 udevadm trigger命令导致应用块设备的设置。 这些设置在udev规则中进行了描述。 通过尝试通过sysfs或查看内核源代码来更改设置,我们可以准确地找出哪些设置“冻结了”队列。 我们还可以尝试使用BCC 跟踪实用程序,该实用程序针对每个blk_freeze_queue调用显示终端的内核堆栈和用户空间跟踪,例如:

 ~# /usr/share/bcc/tools/trace blk_freeze_queue -K -U PID TID COMM FUNC 3809642 3809642 systemd-udevd blk_freeze_queue blk_freeze_queue+0x1 [kernel] elevator_switch+0x29 [kernel] elv_iosched_store+0x197 [kernel] queue_attr_store+0x5c [kernel] sysfs_kf_write+0x3c [kernel] kernfs_fop_write+0x125 [kernel] __vfs_write+0x1b [kernel] vfs_write+0xb8 [kernel] sys_write+0x55 [kernel] do_syscall_64+0x73 [kernel] entry_SYSCALL_64_after_hwframe+0x3d [kernel] __write_nocancel+0x7 [libc-2.23.so] [unknown] 3809631 3809631 systemd-udevd blk_freeze_queue blk_freeze_queue+0x1 [kernel] queue_requests_store+0xb6 [kernel] queue_attr_store+0x5c [kernel] sysfs_kf_write+0x3c [kernel] kernfs_fop_write+0x125 [kernel] __vfs_write+0x1b [kernel] vfs_write+0xb8 [kernel] sys_write+0x55 [kernel] do_syscall_64+0x73 [kernel] entry_SYSCALL_64_after_hwframe+0x3d [kernel] __write_nocancel+0x7 [libc-2.23.so] [unknown] 

Udev规则很少更改,通常会在控制之下。 因此,我们看到,即使使用已经设置的值,也会导致将请求从应用程序传输到磁盘的延迟增加。 当然,在磁盘配置没有变化(例如,设备未连接/断开连接)时生成udev事件不是一个好习惯。 但是,如果没有必要,我们可以帮助内核不要做无用的工作,也不要冻结请求队列。 三个 小的 提交可以纠正这种情况。

结论


eBPF是一个非常灵活且功能强大的工具。 在本文中,我们研究了一个实际案例,并演示了可行方法的一小部分。 如果您对开发BCC实用程序感兴趣,则应查看官方教程 ,该教程很好地描述了基础知识。

还有其他有趣的基于eBPF的调试和性能分析工具。 其中之一是bpftrace ,它使您可以用类似awk的语言编写功能强大的单行和小型程序。 另一个-ebpf_exporter ,使您可以将低级别的高分辨率指标直接收集到您的Prometheus服务器中,并具有获得漂亮的可视化甚至将来发出警报的能力。

Source: https://habr.com/ru/post/zh-CN458592/


All Articles