Kernel trace tools(三):中断和软中断关闭时间过长问题追踪

Kernel trace tools(三):内核 runqueue 延迟跟踪

本文是由字节跳动系统部 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 里面。

1
2
3
4
5
6
static void __sched notrace __schedule(bool preempt)
{
/* ... */
trace_sched_switch(preempt, prev, next);
/* ... */
}

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

  • 进程被唤醒,会被加入 runqueue
  • 进程被抢占,会被重新加入 runqueue
  • 进程 yield,主动让出 CPU 使用权,但是依然挂在 runqueue 上 先考虑第一个问题,如何知道进程被唤醒呢?很幸运,我们有另一个 tracepoint 可以知道进程被唤醒。
1
2
3
4
5
6
7
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 私有云。因此可以通过如下命令安装:

1
2
make
make install

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

5. 如何使用

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

1
2
3
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 线程

1
echo $pid > /proc/trace_runqlat/pid

5.2 关闭跟踪

1
echo -1 > /proc/trace_runqlat/pid

5.3 设置阈值

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

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

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

1
cat /proc/trace_runqlat/threshold

5.4 查看线程

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

1
cat /proc/trace_runqlat/distribution

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

1
2
3
4
5
6
7
 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 调度延迟的原因。

1
2
3
4
5
6
7
8
9
10
11
12
13
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** 。


imgimg

-------------本文结束 感谢阅读-------------