Kernel trace tools（三）：内核 runqueue 延迟跟踪

在实际工作中，会遇到由于 runqueue 太长导致调度延迟问题，我们想知道是哪些进程导致了延迟。但是，对于该类问题的定位和追踪缺乏行之有效的方案或客观依据，需要耗费大量时间和精力用于问题排查，trace-runqlat 工具便是在该背景下诞生的自研工具。

目前，trace-runqlat 已开源，如感兴趣详见：

Open Source Repo (https://github.com/bytedance/trace-runqlat)

1. 问题背景

Trace_irqoff (
https://github.com/bytedance/trace-irqoff/tree/master) 工具（之前已经开源）可以帮助我们排查由于中断被关闭导致的延迟抖动问题。但是这只是第一阶段可能遇到的问题。当我们将一个线程加入 runqueue 后，如果系统的负载很高，在 runqueue 中排在你前面的进程可能会由于执行很长时间（或许你会好奇怎么可能执行很长时间，难道不会抢占吗？还真可能出现这种情况。因为我们的 kernel 是不开抢占的。当然除此之外，负载很高 runqueue 长度很长，也会出问题）最终导致调度延迟很大。针对这种问题排查，我们开发一款新的排查工具Run queue latency tracer 简称：trace-runqlat。 作用是记录被跟踪的进程在加入 runqueue 后，前面的每个线程执行的时间及线程 command 等信息。

2. 我们想做什么

在此之前开源工具 trace-noschedule (
https://github.com/bytedance/trace-noschedule) 中，我们已经可以借助这个工具排查内核态不抢占导致的延迟问题。而 trace-runqlat 更多的是关注 runqueue 上每个进程是谁，并且 runqueue 有多长。首先，是否有现成的工具已经实现功能了呢？据我所知，bcc 存在 2 款工具 runqlen 和 runqlat。runqlen 显示的是每个 CPU 的就绪队列的长度分布柱状图。runqlat 可以针对某个特定 pid 绘制调度延迟柱状图。他们似乎很符合我们的需求。虽然我们知道了某个进程调度延迟很高。但是我们不知道是受到哪些进程的影响。你可能会有疑问，知道是谁有意义吗？当然有意义。对于混合部署来说，我们肯定希望优先保证在线业务，如果发现影响调度延迟的进程是离线业务进程，这对于我们进一步混部有一定指导意义。例如，我们是否应该考虑绑核？或者调整优先级？

3. 如何实现

我们先定义一下调度延迟。调度延迟是指从进程被加入 runqueue 到开始执行的时间差。进程挂在 runqueue 中，我们称进程处于 runnable 状态，开始执行时为 running 状态。所以调度延迟是进程从 runnable 态切换 running 状态的时间。 为了计算调度延迟，我们需要知道 2 个时间点，进程进入 runnable 状态时间点以及切换到 running 状态时间戳。进程开始执行的时间戳很容易获取。我们可以利用 tracepoint。这个 tracepoint 插在 schedule 里面。

static void __sched notrace __schedule(bool preempt){    /* ... */    trace_sched_switch(preempt, prev, next);    /* ... */}

schedule 的时候判断 next 进程是否是我们跟踪的进程，如果是的话，这个时间戳就是截止时间。那么开始时间怎么获取呢？一个进程在什么情况下会变成 runnable 状态呢？有以下可能。

static void ttwu_do_wakeup(struct rq *rq, struct task_struct *p, int wake_flags,                           struct rq_flags *rf){        /* ... */        trace_sched_wakeup(p);        /* ... */}

借助 sched_wakeup tracepoint 我们可以知道是否是我们跟踪的进程被唤醒了，此时就是第一个时间戳，加入 runqueue 时间。

这是第一种情况。另外两种情况，可以总结成一种情况处理。因为这两种情况下，进程是都是从 running 下切换 runnable 态。我们借助 sched_switch tracepoint 可以检测。现在我们得到了一个进程加入 runqueue 时间和进程开始运行时间，两个时间差值就是调度延迟时间。此时就可以记录数据，绘制柱状图，这相当于实现了 bcc 中 runqlat 工具的功能。但是，这不是我们的重点。当进程加入某个 CPU 的 runqueue 后，我们就需要对这个 CPU 的进程进行记录，记录每个进程的 comm，pid 以及执行时间。直到跟踪的进程开始执行。这些信息可以给我一定的指导作用。原理已经介绍完了，比较简单，具体的代码实现细节，可以前往源码查看。如果你发现 bug，记得 fix patch。我们很欢迎。

4. 如何安装

trace_runqlat 工具已经放到 bytedance 私有云。因此可以通过如下命令安装：

makemake install

Note: 由于工具使用 sched tracepoint，对性能有一定影响。调试完成记得执行rmmod trace_runqlat卸载模块。

5. 如何使用

安装 trace-runqlat 工具成功后。会创建如下 /proc/trace_runqlat 目录。

root@n18-061-206:/proc/trace_runqlat# lsdistribution  pid  runqlat  threshold

/proc/trace_runqlat 目录下存在 4 个文件，分别：distribution, pid, runqlat 和 threshold。工具安装后，默认是打开状态，但是并没有 trace 任何线程，我们需要手动设置需要 trace 的线程 pid。

5.1 跟踪特定 pid 线程

echo $pid > /proc/trace_runqlat/pid

5.2 关闭跟踪

echo -1 > /proc/trace_runqlat/pid

5.3 设置阈值

trace-runqlat 只会针对延迟超过阈值的情况，记录 runqueue 前面的线程执行的时间情况。为了更高效的运作，我们有必要设定一个合理阈值。例如设置 60ms 的阈值：

echo 60000000 > /proc/trace_runqlat/threshold # 单位ns

如果需要查看当前设定的阈值，可执行如下命令：

cat /proc/trace_runqlat/threshold

5.4 查看线程 runqueue latency 分布

我们以直方图的形式展示被跟踪进程 runqueue latency 的分布情况。

cat /proc/trace_runqlat/distribution

你看到的信息展示如同下面这样：

         msecs           : count     distribution         1 -> 1          : 0        |                                        |         2 -> 3          : 0        |                                        |         4 -> 7          : 0        |                                        |         8 -> 15         : 0        |                                        |        16 -> 31         : 0        |                                        |        32 -> 63         : 68       |****************************************|

我们可以看到 latency 集中在[32, 63]毫秒，次数 68 次。

5.5 是谁在 runqueue 的前面

针对 latency 超过阈值的情况，我们会记录 runqueue 前面的线程执行情况。注意，必须关闭 trace 的情况下才能查看
/proc/trace_runqlat/runqlat 信息。

6. 案例分析

为了展示 trace-runqlat 工具的功能，我们构建一个场景，模拟高负载的情况。我在一个 CPU 上起 10 个进程，分别是 loop0-loop9。每个进程都在用户态无限循环执行，消耗 CPU 资源。我们跟踪 loop0 进程。查看 loop0 调度延迟的原因。

cat /proc/trace_runqlat/runqlat  latency(us): 35999 runqlen: 10      COMM: loop7            PID: 3789453  RUNTIME(us):   4000      COMM: loop2            PID: 3789448  RUNTIME(us):   4001      COMM: loop4            PID: 3789450  RUNTIME(us):   3998      COMM: loop1            PID: 3789447  RUNTIME(us):   3999      COMM: loop3            PID: 3789449  RUNTIME(us):   4000      COMM: loop8            PID: 3789454  RUNTIME(us):   3999      COMM: loop9            PID: 3789455  RUNTIME(us):   4001      COMM: kworker/0:2      PID: 3621088  RUNTIME(us):      3      COMM: loop5            PID: 3789451  RUNTIME(us):   3994      COMM: loop6            PID: 3789452  RUNTIME(us):   3999

我们可以看到 runqueue latency 是 35999us。runqueue 前面有 10 个进程。每个进程的执行时间加在一起差不多就是总的 latency。loop1-loop9 都在这里了。还多了个 kworker，不过转瞬即逝。我们看到每个 loop 执行时间基本是 4ms。这其实是 CFS 调度器给进程分配的最大时间片。

7. 总结

根据字节内部实践来看，trace-runqlat 安装便捷且使用灵活度高，能将问题定位耗时缩短至分钟级别，使用收益可观，并且已经通过该工具定位问题，提高了工作效率。

更多分享

Kernel trace tools（一）：中断和软中断关闭时间过长问题追踪

Kernel trace tools（二）：内核态执行时间跟踪

字节跳动在 Go 络库上的实践

字节跳动系统部 STE 团队

字节跳动系统部 STE 团队一直致力于操作系统内核与虚拟化、系统基础软件与基础库的构建和性能优化、超大规模数据中心的稳定性和可靠性建设、新硬件与软件的协同设计等基础技术领域的研发与工程化落地，具备全面的基础软件工程能力，为字节上层业务保驾护航。同时，团队积极关注 区技术动向，拥抱开源和标准。欢迎更多有志之士加入，如有意向可发送简历至 sysrecruitment@bytedance.com。

字节跳动技术团队