阅读 110

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

本文是由字节跳动系统技术与工程团队出品的“kernel trace tools”系列文章之一,以介绍团队自研多类延迟问题追踪工具。

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

目前,trace-runqlat 已开源,如感兴趣详见Open Source Repo

1. 问题背景

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

2. 我们想做什么

在此之前开源工具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(二):内核态执行时间跟踪

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

字节跳动系统部 STE 团队

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

欢迎关注字节跳动技术团队

关注下面的标签,发现更多相似文章
评论