如何使 bpftrace:runqlat.bt 按 workqueue name 统计延迟
问题
当我们想利用 ebpf 统计 task/kworker 的调度延迟，通常有两个前端选择，一是 bcc，另一个是 bpftrace。而如果要自定义，通常选择先上手 bpftrace，因为简单。
bpftrace/tools 下的工具 runqlat.bt 就可以统计调度延迟，只不过输出是直方图，我们希望能够像 perf sched 那样输出 task/kworker 的调度延迟时间。
浏览 runqlat.bt
先浏览下代码，参考 v0.11.4:
1 #!/usr/bin/env bpftrace
2 /*
3 * runqlat.bt CPU scheduler run queue latency as a histogram.
4 * For Linux, uses bpftrace, eBPF.
5 *
6 * This is a bpftrace version of the bcc tool of the same name.
7 *
8 * Copyright 2018 Netflix, Inc.
9 * Licensed under the Apache License, Version 2.0 (the "License")
10 *
11 * 17-Sep-2018 Brendan Gregg Created this.
12 */
13
14 #include <linux/sched.h>
15
16 BEGIN
17 {
18 printf("Tracing CPU scheduler... Hit Ctrl-C to end.\n");
19 }
20
21 tracepoint:sched:sched_wakeup,
22 tracepoint:sched:sched_wakeup_new
23 {
24 @qtime[args->pid] = nsecs;
25 }
26
27 tracepoint:sched:sched_switch
28 {
29 if (args->prev_state == TASK_RUNNING) {
30 @qtime[args->prev_pid] = nsecs;
31 }
32
33 $ns = @qtime[args->next_pid];
34 if ($ns) {
35 @usecs = hist((nsecs - $ns) / 1000);
36 }
37 delete(@qtime[args->next_pid]);
38 }
39
40 END
41 {
42 clear(@qtime);
43 }行数不多，看上去也很简单，对于首次接触 bpftrace 的这段代码主要盲点: args/@/$/nsecs/hist/delete/clear/BEGIN/END。
先运行下看看：
root@localhost:/bpftrace# bpftrace tools/runqlat.bt
Attaching 5 probes...
Tracing CPU scheduler... Hit Ctrl-C to end.
^C
@usecs:
[2, 4) 236 |@@@@@@@@@ |
[4, 8) 1109 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ |
[8, 16) 1246 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[16, 32) 772 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ |
[32, 64) 233 |@@@@@@@@@ |
[64, 128) 318 |@@@@@@@@@@@@@ |
[128, 256) 147 |@@@@@@ |
[256, 512) 42 |@ |
[512, 1K) 52 |@@ |
[1K, 2K) 22 | |
[2K, 4K) 7 | |这些输出是怎么产生的？带着这些疑问来认识 bpftrace。
了解 bpftrace 语言
基本语法就是：probe[,probe,...] /filter/ { action }
probe 可以有多种，比如这里的 traceponit，action 可以有多个，filter 是过滤条件，可写可不写，看情况。
- @, $
代表变量类型，@ 表示全局 (map variables)，而 $ 表示 scratch variables(栈变量？)
@[] 表示关联数组，它是 map variable 的变体，格式 @array_name[key_name, key_name2, ...] = value, 类似 hash or Python Dict：
>>> Dict = {1: 'Geeks', 2: 'For', 3: 'Geeks'}
>>> Dict
{1: 'Geeks', 2: 'For', 3: 'Geeks'}
>>> Dict[1]
'Geeks'
>>> Dict[2]
'For'- args
docs/tutorial_one_liners.md:
argsis a pointer to a struct containing all the tracepoint arguments. This
struct is automatically generated by bpftrace based tracepoint information.
args 是一个指针，指向该 tracepoint 的所有参数。这个结构是由 bpftrace 根据 tracepoint 信息自动生成。
可以用如下命令找出这个结构：
root@localhost:/# bpftrace -vl 'tracepoint:sched:sched_wakeup'
tracepoint:sched:sched_wakeup
char comm[16];
pid_t pid;
int prio;
int success;
int target_cpu;
long state;再看下 wakeup tracepoint code:
static void ttwu_do_wakeup(struct rq *rq, struct task_struct *p, int wake_flags,
struct rq_flags *rf)
{
check_preempt_curr(rq, p, wake_flags);
p->state = TASK_RUNNING;
trace_sched_wakeup(p);DEFINE_EVENT(sched_wakeup_template, sched_wakeup,
TP_PROTO(struct task_struct *p),
TP_ARGS(p));DECLARE_EVENT_CLASS(sched_wakeup_template,
TP_PROTO(struct task_struct *p),
TP_ARGS(__perf_task(p)),
TP_STRUCT__entry(
__array( char, comm, TASK_COMM_LEN )
__field( pid_t, pid )
__field( int, prio )
__field( int, success )
__field( int, target_cpu )
),到这里就清晰了，这个 args 就指向 TP_STRUCT__entry。
- nsecs
内置变量，里面用的是 {bpf_}ktime_get_ns()。
- BEGIN, END
These are special built-in events provided by the bpftrace runtime. BEGIN is triggered before all other probes are attached. END is triggered after all other probes are detached.
内置probe，管开头和结束。
- delete/clear/hist
都是内置 map functions，map 是一种特殊的 data type，除了用作 variable 外，还可以用来存储直方图（调用hist） 等。
delete 是从 map 里删除一个 key，所以要指定 key，比如上面的 delete(@qtime[args->next_pid])，
而 clear 是清除 map 里所有 keys/values, 所以语法是 clear(map m), 比如上面的 clear(@qtime)。
bpftrace 退出时所有的 maps 都会打印出来, 不想打就在 END block 里加上 clear。
ok, 在了解下这些基本语言规则后，我们来修改这个 bt 文件。
修改 runqlat.bt
调度延迟的时间就是从 wakeup 开始一直到 start running 这个时间点。
wakeup 时记录 wakeup time 到 @qtimes[task_id] 里，而在 switch 时，用 nsecs 减去这个 wakeup 的时间(前提要存在)就是这个 task 的调度延迟。
来看下 kernel trace_sched_switch():
TRACE_EVENT(sched_switch,
TP_PROTO(bool preempt,
struct task_struct *prev,
struct task_struct *next),
TP_ARGS(preempt, prev, next),
TP_STRUCT__entry(
__array( char, prev_comm, TASK_COMM_LEN )
__field( pid_t, prev_pid )
__field( int, prev_prio )
__field( long, prev_state )
__array( char, next_comm, TASK_COMM_LEN )
__field( pid_t, next_pid )
__field( int, next_prio )
),
TP_fast_assign(
memcpy(__entry->next_comm, next->comm, TASK_COMM_LEN);
__entry->prev_pid = prev->pid;
__entry->prev_prio = prev->prio;
__entry->prev_state = __trace_sched_switch_state(preempt, prev);
memcpy(__entry->prev_comm, prev->comm, TASK_COMM_LEN);
__entry->next_pid = next->pid;
__entry->next_prio = next->prio;我们关心的是 prev_comm 和 next_comm，next 是即将 running 的 task，所以 switch block 可以改成：
$ns = @qtime[args->next_pid];
if ($ns) {
- @usecs = hist((nsecs - $ns) / 1000);
+ @uesc[args->next_comm] = ((nsecs - $ns) / 1000);
}这样就输出所有 tasks 的调度延迟了，效果如下：
Attaching 5 probes...
Tracing CPU scheduler... Hit Ctrl-C to end.
@usecs[ksoftirqd/6]: 14
@usecs[swapper/2]: 14
@usecs[swapper/1]: 17
@usecs[swapper/0]: 17
@usecs[kworker/7:1]: 32
@usecs[swapper/6]: 42
@usecs[kworker/6:1]: 50
@usecs[kworker/3:2]: 57因为要 Ctrl-c 才终止，把 bpftrace tools/runqlat.bt 输出重定向到文本，grep kworker 搜索这个文本即可完成 kworker 统计。
那代码要支持过滤 kworker 怎么写了？高版本有字符串包含，这个版本只有 strncmp，修改如下:
tracepoint:sched:sched_wakeup_new
{
- @qtime[args->pid] = nsecs;
+ if (!strncmp(args->comm, "kworker", 7)) {
+ @qtime[args->pid] = nsecs;
+ }
}
tracepoint:sched:sched_switch
{
if (args->prev_state == TASK_RUNNING) {
- @qtime[args->prev_pid] = nsecs;
+ if (!strncmp(args->prev_comm, "kworker", 7)) {
+ @qtime[args->prev_pid] = nsecs;
+ }
}这样一次性统计所有 kworker 的调度延迟，我们跑下看看：
Attaching 5 probes...
Tracing CPU scheduler... Hit Ctrl-C to end.
^C
@usecs[kworker/3:2]: 40
@usecs[kworker/u17:2]: 44
@usecs[kworker/7:1]: 64
@usecs[kworker/u16:14]: 81
@usecs[kworker/6:1]: 92
@usecs[kworker/u16:5]: 120
@usecs[kworker/u16:7]: 121
@usecs[kworker/u16:1]: 124怎么没有 workqueue name? 方括号里的显示来自 args->next_comm，也就是入参 next 的 comm，来看 kernel 部分(大概还有一半-)。
btw: 看了下最新的 Linux 6.3rc 也不支持。
本站采用CC BY-NC-SA 4.0进行许可 | 转载请注明原文链接 - 如何使 bpftrace:runqlat.bt 按 workqueue name 统计延迟
