标签：__ 坑记 TASK sched trace 失常 state 任务 prev

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。

到此，这个不痛但痒的奇怪问题终于搞清楚了，它的来龙去脉也终于搞清楚了，天空又蓝了，云朵又白了，风儿也甜了。

标签：__,坑记,TASK,sched,trace,失常,state,任务,prev
From： https://www.cnblogs.com/liuhailong0112/p/17799599.html

一次任务状态"失常"的踩坑记

0 背景

一 ebpf代码自检

二利用trace event佐证

2.1 令人震惊的结论

2.2 唠叨唠叨论证过程

2.3 大胆怀疑，小心验证

2.4 刨根问底，连根拔起

相关文章

赞助商

阅读排行

一次任务状态"失常"的踩坑记

0 背景

一 ebpf代码自检

二 利用trace event佐证

2.1 令人震惊的结论

2.2 唠叨唠叨论证过程

2.3 大胆怀疑，小心验证

2.4 刨根问底，连根拔起

相关文章

赞助商

阅读排行

二利用trace event佐证