Linux 有大量用于调试内核和应用程序的工具。 其中大多数会对应用程序性能产生负面影响，并且无法在生产中使用。
几年前有 — eBPF。 它使得以较低的开销跟踪内核和用户应用程序成为可能，并且无需重建程序并将第三方模块加载到内核中。
已经有许多应用程序实用程序使用 eBPF，在本文中我们将了解如何基于该库编写自己的分析实用程序 。 该文章取材于真实事件。 我们将逐一解决问题，以展示如何在特定情况下使用现有实用程序。
Ceph 很慢
Ceph 集群中已添加新主机。 将部分数据迁移到其中后，我们注意到它处理写入请求的速度比其他服务器低得多。
与其他平台不同的是，该主机使用了 bcache 和新的 linux 4.15 内核。 这是首次使用这种配置的主机。 在那一刻，很明显，从理论上讲，问题的根源可能是任何事情。
调查主机
让我们首先看看 ceph-osd 进程内部发生了什么。 为此，我们将使用 и （更多相关内容您可以阅读 ):
这张图告诉我们这个函数 数据同步（） 花费了大量时间向函数发送请求 generic_make_request()。 这意味着问题的原因很可能是在 osd 守护进程本身之外的某个地方。 这可以是内核或磁盘。 iostat 输出显示 bcache 磁盘处理请求时存在较高延迟。
在检查主机时，我们发现 systemd-udevd 守护进程消耗了大量的 CPU 时间 - 在多个核心上大约消耗了 20%。 这是奇怪的行为，因此您需要找出原因。 由于 Systemd-udevd 与 uevent 一起使用，我们决定通过 udevadm 监视器。 事实证明，系统中的每个块设备都产生了大量的变更事件。 这是很不寻常的，所以我们必须看看是什么产生了所有这些事件。
使用密件抄送工具包
正如我们已经发现的，内核（以及系统调用中的 ceph 守护进程）花费了大量时间 generic_make_request()。 让我们尝试测量这个函数的速度。 在 已经有一个很棒的实用程序了 - 功能性。 我们将通过 PID 来跟踪守护进程，输出之间的间隔为 1 秒，并以毫秒为单位输出结果。
此功能通常见效很快。 它所做的只是将请求传递到设备驱动程序队列。
缓存 是一个复杂的设备，实际上由三个磁盘组成：
- 支持设备（缓存磁盘），在本例中是慢速 HDD；
- 缓存设备（缓存盘），这里是NVMe设备的一个分区；
- 应用程序运行时使用的 bcache 虚拟设备。
我们知道请求传输很慢，但是对于这些设备中的哪一个呢？ 我们稍后会处理这个问题。
我们现在知道 uevent 可能会导致问题。 找出他们这一代的确切原因并不容易。 我们假设这是某种定期启动的软件。 让我们使用脚本看看系统上运行什么样的软件 执行监听 来自同一个 。 让我们运行它并将输出发送到文件。
例如，像这样：
/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()。 我们还对调用该函数的驱动器的名称感兴趣。
计划很简单：
- 登记 探针 上 generic_make_request():
- 我们将磁盘名称保存到内存中，可以通过函数参数访问；
- 我们保存时间戳。
- 登记 克雷特探针 从返回 generic_make_request():
- 我们得到当前的时间戳；
- 我们查找保存的时间戳并将其与当前时间戳进行比较；
- 如果结果大于指定的值，那么我们找到保存的磁盘名称并将其显示在终端上。
探针 и 克雷特探针 使用断点机制动态更改函数代码。 你可以阅读 и 关于这个主题的文章。 如果您查看以下各种实用程序的代码 ，那么你可以看到它们具有相同的结构。 因此，在本文中，我们将跳过解析脚本参数并继续讨论 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 和一个类型的值 结构体data_t。 该表将在我们的 BPF 计划中提供。 BPF_PERF_OUTPUT 宏注册了另一个表，称为 事件，用于 进入用户空间。
在测量调用函数和从函数返回之间或调用不同函数之间的延迟时，您需要考虑到接收到的数据必须属于同一上下文。 换句话说，您需要记住可能的并行启动功能。 我们能够测量在一个进程的上下文中调用函数与在另一进程的上下文中从该函数返回之间的延迟，但这可能是无用的。 一个很好的例子是 ，其中哈希表键设置为指向 结构请求，反映一个磁盘请求。
接下来，我们需要编写在调用所研究的函数时运行的代码：
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);
}
这里被调用函数的第一个参数将被替换为第二个参数 。 之后，我们获取正在工作的进程的 PID，以及当前时间戳（以纳秒为单位）。 我们将其全部记录在新选择的内容中 结构体data_t数据。 我们从结构中获取磁盘名称 生物，调用时传递 generic_make_request()，并将其保存在相同的结构中 data。 最后一步是将条目添加到前面提到的哈希表中。
返回时将调用以下函数 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 在哈希表中搜索已经存在的结构。 如果找到该结构，那么我们找出正在运行的进程的名称并将其添加到其中。
我们在这里使用的二进制移位需要获取线程 GID。 那些。 在我们正在工作的上下文中启动线程的主进程的 PID。 我们调用的函数 以单个 64 位值返回线程的 GID 及其 PID。
当输出到终端时，我们当前对线程不感兴趣，但我们对主进程感兴趣。 将产生的延迟与给定阈值进行比较后，我们通过我们的结构 data 通过表进入用户空间 事件，之后我们删除该条目 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 程序 并登记样品：
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")
我们还必须确定 结构体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()
该脚本本身可在 。 让我们尝试在运行 fio 的测试平台上运行它，写入 bcache，并调用 udevadm 监视器：
最后！ 现在我们看到，看起来像停止 bcache 设备的实际上是停止调用 generic_make_request() 对于缓存磁盘。
深入内核
请求传输过程中到底是什么减慢了速度？ 我们看到延迟甚至在请求记账开始之前就发生了，即对进一步输出统计数据（/proc/diskstats 或 iostat）的具体请求的统计尚未开始。 这可以通过在重现问题时运行 iostat 来轻松验证，或者 ，它基于请求记帐的开始和结束。 这些实用程序都不会显示对缓存磁盘的请求的问题。
如果我们看一下这个函数 generic_make_request()，然后我们会看到在请求开始计费之前，又调用了两个函数。 第一的 - generic_make_request_checks()，对有关磁盘设置的请求的合法性进行检查。 第二 - ，这有一个有趣的挑战 :
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_queue() 按功能划分 计数器增加 q->mq_freeze_深度。 之后，内核等待队列清空 .
清除此队列所需的时间相当于内核等待所有排队操作完成时的磁盘延迟。 一旦队列为空，就会应用设置更改。 之后它被称为 ，递减计数器 冻结深度.
现在我们已经有足够的知识来纠正这种情况了。 udevadm 触发命令会导致应用块设备的设置。 这些设置在 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 的有趣的调试和分析工具。 其中之一—— ，它允许您使用类似 awk 的语言编写功能强大的单行代码和小程序。 其他 - ，允许您将低级别、高分辨率的指标直接收集到您的普罗米修斯服务器中，并能够在以后获得漂亮的可视化效果甚至警报。
来源： habr.com