Kernel trace tools（三）：内核 runqueue 延迟跟踪
摘要：trace-runqlat 只会针对延迟超过阈值的情况，记录 runqueue 前面的线程执行的时间情况。作用是记录被跟踪的进程在加入 runqueue 后，前面的每个线程执行的时间及线程 command 等信息。
本文是由字节跳动系统部 STE 团队出品的“kernel trace tools”系列文章之一，以介绍团队自研多类延迟问题追踪工具。
在实际工作中，会遇到由于 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 状态呢？有以下可能。
-
进程被唤醒，会被加入 runqueue
-
进程被抢占，会被重新加入 runqueue
-
进程 yield，主动让出 CPU 使用权，但是依然挂在 runqueue 上 先考虑第一个问题，如何知道进程被唤醒呢？很幸运，我们有另一个 tracepoint 可以知道进程被唤醒。
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 私有云。因此可以通过如下命令安装：
make make install
Note : 由于工具使用 sched tracepoint，对性能有一定影响。调试完成记得执行 rmmod trace_runqlat 卸载模块。
5. 如何使用
安装 trace-runqlat 工具成功后。会创建如下 /proc/trace_runqlat 目录。
root@n18-061-206:/proc/trace_runqlat# ls distribution 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（二）：内核态执行时间跟踪
字节跳动系统部 STE 团队
字节跳动 STE 团队一直致力于操作系统内核与虚拟化、系统基础软件与基础库的构建和性能优化、超大规模数据中心的稳定性和可靠性建设、新硬件与软件的协同设计等基础技术领域的研发与工程化落地，具备全面的基础软件工程能力，为字节上层业务保驾护航。同时，团队积极关注社区技术动向，拥抱开源和标准。欢迎更多有志之士加入，如有意向可发送简历至 [email protected] 。
欢迎关注「字节跳动技术团队」
点击阅读原文，快来加入我们吧！
