问题 当我们想利用 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'
docs/tutorial_one_liners.md:
args is a pointer to a struct containing all the tracepoint arguments. This
args 是一个指针，指向该 tracepoint 的所有参数。这个结构是由 bpftrace 根据 tracepoint 信息自动生成。
可以用如下命令找出这个结构：
root@localhost:/ 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。
内置变量，里面用的是 {bpf_}ktime_get_ns()。
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，管开头和结束。
都是内置 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 也不支持。