0 背景
业务场景中需要统计任务处于"D"状态offcpu的时长，为此和队友一起尝试使用ebpf在trace_sched_switch()这个trace点挂上自己的ebpf处理函数。这个ebpf处理函数使用SEC("tp/sched/sched_switch")来声明，然后在处理函数中判断"prev_state"是否带有"TASK_UNINTERRUPTIBLE"标志，如果有则记录下即将切换出去的任务的prev_pid；后面这个任务再切换回来的时候，再取出来。
刚开始一切work well，直到发现kworker这种类型的任务经常无法被统计到--我们同时在trace_sched_stat_blocked()这个tracepoint添加了ebpf探针函数，奇怪的是trace_sched_stat_blocked()可以检测到的kwoker经历了"blocked"状态，但是使用trace_sched_switch()就无法捕获到。
这究竟是怎么回事呢？
一 ebpf代码自检
重新梳理了一下trace_sched_switch()的处理函数，发现是判断"D"状态的方式有点问题：
if (prev_state == TASK_UNINTERRUPTBLE) { /* got it */ }
因为我们从内核源码观察到kworker在进入睡眠时会将状态设置为“TASK_IDLE”，这是种复合状态，即：
#define TASK_IDLE (TASK_UNINTERRUPTIBLE | TASK_NOLOAD)
如果使用前面的 "=="来进行判断，势必会失败。于是我们赶紧将其修改为与操作"&"来进行判断，即：
if (prev_state & TASK_UNINTERRUPTBLE) {
/* got it */
}
改完之后我们感觉已经胜券在握，代码重新运行时，已经开始准备开香槟庆祝，but....状况仍然没有一丁点改善。
"What hanppend?"我和队友都陷入了沉思。
二 利用trace event佐证
2.1 令人震惊的结论
为了确保我们的判定条件没有问题，队友在判断条件前面讲prev_state的值给"打印"出来，另我们惊讶的是，这个状态居然是0x80，也就是TASK_DEAD：
#define TASK_DEAD 0x0080
这又再一次刷新了我的认知。因为在我有限的Linux调度知识范围内，我理解任务的状态要变为TASK_DEAD只有两个地方：1) 新任务创建失败；2) 任务退出的最后一丁点阶段。这两种状态都是不可逆的，一旦进入这种状态就宣布任务死翘翘了，没有机会再参与调度了。然而我们愣是看到prev_state==TASK_DEAD的kworker任务一次又一次的被唤醒、调度、再唤醒、调度......
2.2 唠叨唠叨论证过程
我冷静的喝了一杯5个核桃强压心中的惊慌。
"人类会说谎，但是机器不会，一定是有哪里我没有搞清楚的地方"，在绝望的时候这个坚定的声音总是这样震耳溃聋。
这次我不再依赖ebpf程序，我直接在机器上使用trace event来检查，简化后的脚本如下：
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable echo 1 > /sys/kernel/debug/tracing/events/sched/sched_stat_blocked/enable echo 1 > /sys/kernel/debug/tracing/tracing_on sleep $TIMEOUT echo 0 > /sys/kernel/debug/tracing/tracing_on echo 0 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable echo 0 > /sys/kernel/debug/tracing/events/sched/sched_stat_blocked/enable cat /sys/kernel/debug/tracing/trace > $HOME/trace.log echo "" > /sys/kernel/debug/tracing/trace
从采集的日志trace.log中我复现了ebpf中遇到的问题，且看下面3行：
【1】<...>-111117 [003] d... 4674198.005896: sched_switch: prev_comm=kworker/3:2 prev_pid=111117 prev_prio=120 prev_state=I ==> next_comm=swapper/3 next_pid=0 next_prio=120 【2】<idle>-0 [003] d.s. 4674198.213880: sched_stat_blocked: comm=kworker/3:2 pid=111117 delay=207983755 [ns] 【3】<idle>-0 [003] d... 4674198.213885: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/3:2 next_pid=111117 next_prio=120
这3行专门截取了一个kworker任务111117经过了 调度切换离开CPU、就绪进入队列、调度切换调入CPU的3个阶段。
- 阶段【1】
kworker 111117调度切换离开CPU，离开时trace信息中的”prev_state=I“，从内核代码可知，prev_state=I也就意味着prev_state的值为TASK_DEAD，这个结论和前面ebpf的代码结论一致。
而这段内核代码截取自TRACE_EVENT(sched_switch,....)如下所示：
TP_printk("prev_comm=%s prev_pid=%d prev_prio=%d prev_state=%s%s ==> next_comm=%s next_pid=%d next_prio=%d", __entry->prev_comm, __entry->prev_pid, __entry->prev_prio, (__entry->prev_state & (TASK_REPORT_MAX - 1)) ? __print_flags(__entry->prev_state & (TASK_REPORT_MAX - 1), "|", { TASK_INTERRUPTIBLE, "S" }, { TASK_UNINTERRUPTIBLE, "D" }, { __TASK_STOPPED, "T" }, { __TASK_TRACED, "t" }, { EXIT_DEAD, "X" }, { EXIT_ZOMBIE, "Z" }, { TASK_PARKED, "P" }, { TASK_DEAD, "I" }) : /* 如果输出位I，则反推出prev_state值为TASK_DEAD */ "R",
- 阶段【2】
kworker 111117唤醒后进入到就绪队列并经过了trace_sched_stat_block()这个trace点；而要经过这个trace点，从内核源码来看一个必要条件就是观察到之前这个kworker睡眠时的任务状态有TASK_UNINTERRUPTIBLE标志。这段内核代码如下所示：
/* dequeue */ update_stats_dequeue() { if (tsk->state & TASK_UNINTERRUPTIBLE) /* 需要切换出去的任务必须要有TASK_UNINTERRUPTIBLE标记才会设置block_start */ __schedstat_set(se->statistics.block_start, rq_clock(rq_of(cfs_rq))); } /* enqueue */ update_stats_enqueue_sleeper() { block_start = schedstat_val(se->statistics.block_start); …… if (block_start) { /* block_start只有在dequeue时tsk->state有TASK_UNINTERRUPTIBLE标记才会设置 */ …… trace_sched_stat_blocked(tsk, delta); } }
- 【阶段3】
kworker 111117从就绪队列得到CPU调度、执行。
用trace event的实验结论和排查1中使用ebpf的结论一致，那就是kworker偶尔会出现：1) 在 trace_sched_switch中prev_state这个参数为TASK_DEAD(理论上这个prev_state来自于task->state)；2) 在切换出去、dequeue时task->state会被检查到有TASK_UNINTERRUPTIBLE标记；3) kworker切换出去后仍然有机会切换回来重新调度。
为了解开上面的疑惑又重新整理了一下内核代码，确认了一下任务切换出去的流程：
- 1) deactivate_task()任务dequeue出队，这里会检查task->state是否有TASK_UNINTERRUPTIBLE标记，如果有会走到trace_sched_stat_block()这个trace点；
- 2) 任务切换 context_switch()，在执行切换前有trace_sched_switch()这个trace点，我们前面就是拿这个trace点的数据。
而这两个步骤之间并没有明确的task->state状态改变的情况。
因此我甚至开始怀疑trace_sched_switch中的prev_state参数和task->state值并不相同了。
2.3 大胆怀疑，小心验证
为了验证我的怀疑点，我又凑到内核代码中寻找trace_sched_switch的代码，不看不知道，一看吓一跳：
/* * Tracepoint for task switches, performed by the scheduler: */ TRACE_EVENT(sched_switch, 。。。。。。 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是在这里计算得到的，并非直接取自task->state __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; /* XXX SCHED_DEADLINE */ ), TP_printk("prev_comm=%s prev_pid=%d prev_prio=%d prev_state=%s%s ==> next_comm=%s next_pid=%d next_prio=%d", __entry->prev_comm, __entry->prev_pid, __entry->prev_prio, //根据prev_state的值打印不同的字符标记 (__entry->prev_state & (TASK_REPORT_MAX - 1)) ? __print_flags(__entry->prev_state & (TASK_REPORT_MAX - 1), "|", { TASK_INTERRUPTIBLE, "S" }, { TASK_UNINTERRUPTIBLE, "D" }, { __TASK_STOPPED, "T" }, { __TASK_TRACED, "t" }, { EXIT_DEAD, "X" }, { EXIT_ZOMBIE, "Z" }, { TASK_PARKED, "P" }, { TASK_DEAD, "I" }) : 。。。。。。 );
这个代码得到两个信息：
- 1) prev_state不是直接来自于task->state的，
- 2) prev_state确实有对TASK_DEAD的判断，说明我们前面就正好触发到这种场景。
对于prev_state状态的计算，简单展开出来是这样的：
static inline long __trace_sched_switch_state(bool preempt, struct task_struct *p) { unsigned int state; ...... state = task_state_index(p); /* 这个函数计算 */ ...... /* 计算的state如果不为0 需要做(1<<(state-1))运算 */ return state ? (1 << (state - 1)) : state; } /* kworker线程切换出去时task->state会设置为TASK_IDLE */ #define TASK_IDLE (TASK_UNINTERRUPTIBLE | TASK_NOLOAD) /* 这里TASK_REPORT的值为0x7F */ #define TASK_REPORT (TASK_RUNNING | TASK_INTERRUPTIBLE | \ TASK_UNINTERRUPTIBLE | __TASK_STOPPED | \ __TASK_TRACED | EXIT_DEAD | EXIT_ZOMBIE | \ TASK_PARKED) /* TASK_REPORT_IDLE = TASK_REPORT + 1 ，即0x7F + 1 = 0x80 */ #define TASK_REPORT_IDLE (TASK_REPORT + 1) #define TASK_REPORT_MAX (TASK_REPORT_IDLE << 1) static inline unsigned int task_state_index(struct task_struct *tsk) { unsigned int tsk_state = READ_ONCE(tsk->state); unsigned int state = (tsk_state | tsk->exit_state) & TASK_REPORT; BUILD_BUG_ON_NOT_POWER_OF_2(TASK_REPORT_MAX); /* 这里是一个关键地方，kworker线程在无work、调度出去的时候会设置为这个状态，然后schedule()调度出去 */ if (tsk_state == TASK_IDLE) state = TASK_REPORT_IDLE; /* 由上面宏定义可知，这为0x80 */ /* 返回最高位为1的位置，例如state=0x80则返回8 */ return fls(state); }
这段代码有两个信息需要说明：
- 1) kworker的睡眠
kworker线程在没有work做时，会将task->state设置TASK_IDLE状态，这是一个复合状态，包含了TASK_UNINTERRUPTIBLE状态；
- 2) prev_state的计算
在trace_sched_siwtch中计算prev_state时，如果task->state状态为TASK_IDLE，则会经过3次转换，最终转换为0x80。这3次转换时这样的：(1) state = TASK_REPORT_IDLE，即0x80; (2) fls(state)转换为8； (3) (1<<(state-1))再次转换为0x80。
而0x80在task状态中正好对应着TASK_DEAD，what a fuck!!
也就是说如果task->state为TASK_IDLE的话，则trace_sched_switch()中prev_state的是TASK_DEAD，而trace buffer中输出的字符串就是"I" !!!
这样一来，前面的诡异逻辑就说的通了。
- 首先，不论通过ebpf还是trace event接口我们看到的prev_state值是0x80，是因为trace_sched_switch()中将TASK_IDLE值转换为了TASK_DEAD；
- 其次，任务出队时，dequeue直接检查的是task->state，针对kworker线程而言，其值为TASK_IDLE，这是一个复合状态，里面包含了TASK_UNINTERRUPTIBLE，所以trace_sched_stat_blocked()能够trace到kworker
- 最后，虽然prev_state值等于TASK_DEAD，但这只是一种内核代码借用TASK_DEAD标志的"巧合"，在trace_switch_context上下文中不能单纯用prev_state值来进行任务状态判断。
2.4 刨根问底，连根拔起
为什么内核会这样呢？这其实和两个补丁有关：
sched/debug: Add explicit TASK_IDLE printing
sched/debug: Add explicit TASK_PARKED printing
在Linux系统中每个任务(idle除外)都有一个/proc/$pid/status接口，这个接口里面有一个字段叫做”State“，表示任务的状态，如运行状态"R"：
# cat /proc/self/status Name: cat Umask: 0022 State: R (running) Tgid: 18364 Ngid: 0 Pid: 18364 PPid: 18350 。。。。。。
而这里展示的"State"信息是通过内核中的一个叫做task_state_array的数组来提供的：
/* * The task state array is a strange "bitmap" of * reasons to sleep. Thus "running" is zero, and * you can test for combinations of others with * simple bit tests. */ static const char * const task_state_array[] = { /* states in TASK_REPORT: */ "R (running)", /* 0x00 */ "S (sleeping)", /* 0x01 */ "D (disk sleep)", /* 0x02 */ "T (stopped)", /* 0x04 */ "t (tracing stop)", /* 0x08 */ "X (dead)", /* 0x10 */ "Z (zombie)", /* 0x20 */ "P (parked)", /* 0x40 */ /* states beyond TASK_REPORT: */ "I (idle)", /* 0x80 */ };
从注释上可以看到这个数组是一个"strange bitmap"，数组的第0个元素表示"R (running)"，即就绪状态；更重要的是这个数组分为了两个部分
- 第一部分：
”in TASK_REPORT“，其对应数组index范围[0, 7]对应的取值分别为 (1<<index-1)，即在宏TASK_REPORT(0x7f)以内，代表着这些TASK_RUNNING , TASK_INTERRUPTIBLE, TASK_UNINTERRUPTIBLE , __TASK_STOPPED, __TASK_TRACED , EXIT_DEAD , EXIT_ZOMBIE , TASK_PARKED 标志。
- 第二部分：
"beyond TASK_REPORT"，其值为0x80，代表的是TASK_IDLE(但是从值来看其实也等于TASK_DEAD，但是在这个上下文环境不代表TASK_DEAD)。
这里的"I (idle)"是最特殊的，因为虽然它代表的是TASK_IDLE状态，但是它的值和这里的数组的index是没有对应起来的。TASK_IDLE值是0x402，但是通过(1<<index-1)计算的值是0x80；
而不论是在/proc/pid/status的"State"的计算中，还是在trace_sched_siwtch的"prev_state"计算中都是按照(1<<index-1)的方式来计算的。因此内核实际上对TASK_IDLE状态在task_state_array中做了一个映射，刚好映射到TASK_DEAD值上，这才造成了之前的误会。
那为什么不直接把TASK_IDLE的值作为数组中的index呢？
- 首先，task_state_array是一个bitmap数组，因此只能够表示一个元素只能够代表一个bit位，而TASK_IDLE是一个组合标志，占用了两个bit位，导致task_state_array这个bitmap无法表示；
- 其次，如果直接取TASK_IDLE的high bit，也就是0x400，会造成这个数组中间的"空洞"，这个空洞一会浪费空间，第二还会导致通用的index计算公式失效。
这一点也可以从前面的两个补丁看出来，最开始TASK_IDLE对应值是0x40，在bitmap引入TASK_PARKED后，又才变为0x80。
到此，这个不痛但痒的奇怪问题终于搞清楚了，它的来龙去脉也终于搞清楚了，天空又蓝了，云朵又白了，风儿也甜了。
