Kernel trace tools(二):内核态执行时间跟踪

栏目: IT技术 · 发布时间: 3年前

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

在实际工作中,会遇到由于内核态不调度而引发的高网络延迟或者卡顿问题。但是,对于该类问题的定位和追踪缺乏行之有效的方案或客观依据,需要耗费大量时间和精力用于问题排查,trace-noschedule 工具便是在该背景下诞生的自研工具。

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

https://github.com/bytedance/trace-noschedule

1. 问题背景

在实际项目实践中,我们经常会遇到延迟高导致的问题。由于我们服务器的内核默认配成内核态不支持抢占,因此不抢占这点也是可能导致问题的原因之一。例如 A 进程陷入内核态执行时间过长,必然影响其他希望在该核运行的进程。此时就会导致调度延迟。针对这种 case,我们开发了一款 工具 专门跟踪陷入内核态长时间不调度的进程。这对于我们排查问题可以有一定的指导方向。同时如果是此类原因导致的延迟,也可以快速定位问题原因。

2. 我们想做什么

当一个进程陷入内核态时,我们应该记录其时间戳。当离开内核时,再一次记录时间戳。然后求差值即可得到进程在内核态运行的时间。思路比较清晰。

3. 如何实现

我们知道应用程序陷入内核态的方式主要是系统调用。我们是否可以通过系统调用提供的 tracepoint 完成呢?当系统调用开始,记录时间戳,系统调用退出,再次记录时间戳。求差值,就是本次系统调用花费的时间。这种方法是否可靠?很明显不可靠。因为进程在内核态很可能由于资源不满足导致主动 schedule。这种情况下,根本不是一直占用 CPU 不调度的情况。因此,这种方法不可行。

既然系统调用这条路走不通,我们就换一种方式。我们知道一个线程执行的生命周期,起于 schedule,止于 schedule。所以我们可以知道一个线程从开始执行到主动或被动放弃 CPU 之间的时间差。这部分时间是总时间,即 user+kernel 的时间。我们是否有办法获取总时间呢?很幸运我们有 schedule 的 tracepoint 可以获取。

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

我们只需要 enable sched_switch 即可获取每个线程执行的总时间。是不是激动的心,颤抖的手,是不是马上想用 bcc 行动了?但是有个新的问题摆在我们面前,如何过滤掉 user 态执行的时间?因为用户态支持抢占,内核态不支持抢占。所以统计内核态的时间才是有意义的。

过滤用户态执行时间可以间接的通过定时器实现。我们知道周期性定时中断,可以获取被打断的上下文是用户态或者内核态。所以开始时间戳 last 需要不断的更新。第一次是从 schedule 开始,后面每次更新是在定时器中断中,如果发现当前中断是打断的用户态,那么更新 last 时间戳,否则不更新。此刻认为用户线程在内核态执行。我们看下示例代码。

static enum hrtimer_restart trace_nosched_hrtimer_handler(struct hrtimer *hrtimer)
{
        /*
         * Skip the idle task and make sure we are not only the
         * running task on the CPU. If we are interrupted from
         * user mode, it indicate that we are not executing in
         * the kernel space, so we should also skip it.
         */
        if (!is_idle_task(current) && regs && !user_mode(regs) &&
            !single_task_running()) {
                /* The kernel mode */
                /*
                 * If the execution time exceeds the threshold, record
                 * the call trace.
                 */
        } else {
                /* The user mode */
                stack_trace->last_timestamp = now;
        }
}

我们看到不更新时间戳的条件比较苛刻。主要考虑以下几种情况:

  • 如果中断时从用户态发生,则更新 last_timestamp 时间戳。

  • 如果当前 CPU 运行队列只有一个 task,更新 last_timestamp 时间戳。因为这种情况下,占有 CPU 不放没有任何问题。

  • 如果当前进程是 idle 进程,同样更新 last_timestamp 时间戳。因为 idle 进程本身就可能在内核态长时间运行,没有任何问题。

我们再看下 tracepoint 的 hook 函数实现。

static void probe_sched_switch(void *priv, bool preempt,
                               struct task_struct *prev,
                               struct task_struct *next)
{
        u64 now = local_clock();
        u64 last = cpu_stack_trace->last_timestamp;
        cpu_stack_trace->last_timestamp = now;
        /*
         * Skip the idle task and make sure we are not only the
         * running task on the CPU.
         */
        if (!is_idle_task(prev) && !single_task_running())
                hist_update(cpu_stack_trace, now - last);
}

记录时间差值,差不多可以认为是内核态执行的时间。当操作设定阈值,我们更新柱状图统计计数。

4. 如何安装

安装 trace-noschedule 工具很简单,git clone 代码后执行如下命令即可安装。

make -j8
make install

5. 如何使用

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

root@n18-061-206:/proc/trace_noschedule# ls
distribution  enable  stack_trace  threshold

/proc/trace_noschedule 目录下存在 4 个文件,分别:distribution, enable, stack_trace 和 threshold。工具安装后,默认是关闭状态。

5.1 打开 tracer

执行以下命令打开 tracer。

echo 1 > /proc/trace_noschedule/enable

5.2 关闭 tracer

执行如下命令关闭 tracer。

echo 0 > /proc/trace_noschedule/enable

Note : debug 问题后请记得关闭 tracer。因为模块内部实现基于 sched tracepoint,overhead 不能忽略。

5.3 设置阈值

trace_noschedule 只会针对内核态执行时间超过阈值不调度的进程记录 stack trace。为了更高效的运作,我们有必要设定一个合理阈值。例如设置 60ms 的阈值(单位:ns):

echo 60000000 > /proc/trace_noschedule/threshold

5.4 查看内核态长时间未调度进程执行的时间分布。

root@n18-061-206:/proc/trace_noschedule# cat distribution
Trace noschedule thread:
         msecs           : count     distribution
        20 -> 39         : 1        |**********                              |
        40 -> 79         : 0        |                                        |
        80 -> 159        : 4        |****************************************|
       160 -> 319        : 2        |********************                    |

在内核态有 4 次执行时间在[80, 159]ms 范围内没有调度。

5.5 是谁占用 CPU 不调度

stack_trace 记录占用 CPU 时间超过阈值不调度进程的栈。

root@n18-061-206:/proc/trace_noschedule# cat stack_trace
 cpu: 0
     COMM: sh PID: 1270013 DURATION: 100ms
     delay_tsc+0x21/0x50
     nosched_test_write+0x53/0x90 [trace_noschedule]
     proc_reg_write+0x36/0x60
     __vfs_write+0x33/0x190
     vfs_write+0xb0/0x190
     ksys_write+0x52/0xc0
     do_syscall_64+0x4f/0xe0
     entry_SYSCALL_64_after_hwframe+0x44/0xa9

这是个内核态测试的 case,在内核态执行 mdelay(100)占用 CPU 100ms 不调度。此时记录的栈如上面所示。"DURATION"记录的就是执行持续时间。

5.6 清除 stack trace

如果我们需要清除 stack trace 记录的信息(stack trace buffer 是有大小限制的,必要的时候需要 clear)。

echo 0 > /proc/trace_noschedule/stack_trace

6. 案例展示

这里以一个实际问题带你了解工具的使用。问题是背景是,业务发现 docker 好像有问题,pull 不下来镜像。登录机器会卡顿,执行很多命令也会卡顿。

6.1 首先看下 CPU 使用情况。

Kernel trace tools(二):内核态执行时间跟踪

有几个 CPU 100%,而且还是 sys 态使用。系统究竟在干吗?

6.2 使用 perf 工具

使用 perf top 看下 CPU 情况,发现 60%左右的时间在 spinlock 上。但是没看出内核哪个路径的 spinlock。使用 trace-noschedule 工具看看是否有发现。

6.3 trace-noschedule 跟踪

root@n131-103-013:/proc/trace_noschedule# cat distribution
Trace noschedule thread:
         msecs           : count     distribution
        20 -> 39         : 760      |****************************************|
        40 -> 79         : 488      |*************************               |
        80 -> 159        : 73       |***                                     |

内核态长时间未调度,而且时间很长。看下工具记录的栈信息,截取如下:

COMM: runc PID: 499045 DURATION: 75ms
     native_queued_spin_lock_slowpath+0x112/0x190
     _raw_spin_lock+0x1d/0x20
     prepend_path+0x266/0x2d0
     __d_path+0x4b/0x80
     seq_path_root+0x53/0xb0
     show_mountinfo+0xb8/0x290
     seq_read+0x321/0x3f0
     __vfs_read+0x33/0x160
     vfs_read+0x91/0x130
     SyS_read+0x52/0xc0
     do_syscall_64+0x68/0x100
     entry_SYSCALL_64_after_hwframe+0x3d/0xa2
COMM: falcon-agent PID: 3002056 DURATION: 114ms
     native_queued_spin_lock_slowpath+0x10f/0x190
     _raw_spin_lock+0x1d/0x20
     prepend_path+0x266/0x2d0
     __d_path+0x4b/0x80
     seq_path_root+0x53/0xb0
     show_vfsmnt+0x7a/0x170
     seq_read+0x321/0x3f0
     __vfs_read+0x33/0x160
     vfs_read+0x91/0x130
     SyS_read+0x52/0xc0
     do_syscall_64+0x68/0x100
     entry_SYSCALL_64_after_hwframe+0x3d/0xa2

说明内核态确实一直在 spin。主要集中在以上两个路径文件的读取。分别是 /proc/$pid/mounts/proc/$pid/mountinfo 文件。

6.4 查看 mountinfo 信息

可能是 mount 太多,导致遍历时间很久。而且长时间持锁。

root@n131-103-013:/var/log/atop# mount -v | wc -l
65803

确实很多,65803 多个。大量的/dev/shm 挂载。以下信息只是其中一部分展示。既然知道了问题原因就可以对症下药了,下一步就是排查为什么/dev/shm 挂载很多。这让我们很快定位问题原因。

7. 总结

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

更多分享

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

字节跳动混沌工程实践总结

gdb 提示 coredump 文件 truncated 问题排查

字节跳动系统部 STE 团队

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

Kernel trace tools(二):内核态执行时间跟踪

欢迎关注字节跳动技术

  点击阅读原文,快来加入我们吧!


以上就是本文的全部内容,希望对大家的学习有所帮助,也希望大家多多支持 码农网

查看所有标签

猜你喜欢:

本站部分资源来源于网络,本站转载出于传递更多信息之目的,版权归原作者或者来源机构所有,如转载稿涉及版权问题,请联系我们

CSS精粹

CSS精粹

Rachel Andrew / 曹明伦 / 人民邮电出版社 / 2007-10 / 39.00元

本书采用问答的形式,为CSS使用过程中一些有价值的经典问题提供了精彩的实践解决方案。本书内容包括文本样式、CSS图像、导航、表格数据、注册表和用户界面、浏览器和设置支持、CSS定位和布局以及未来相关技术。 本书的目标读者是每一个需要使作CSS的Web设计人员和开发人员。本书通过经典的问题和精彩的解答将理论融于实践,使每一个带着问题阅读本书的读者都能找到自己满意的答案。一起来看看 《CSS精粹》 这本书的介绍吧!

HTML 压缩/解压工具
HTML 压缩/解压工具

在线压缩/解压 HTML 代码

URL 编码/解码
URL 编码/解码

URL 编码/解码

SHA 加密
SHA 加密

SHA 加密工具