phpgdbtracepoint技巧_Kernel trace tools二内核态实行时间跟踪

在实际事情中，会碰着由于内核态不调度而引发的高网络延迟或者卡顿问题。
但是，对付该类问题的定位和追踪缺少行之有效的方案或客不雅观依据，须要耗费大量韶光和精力用于问题排查，trace-noschedule 工具便是在该背景下出身的自研工具。

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

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

在实际项目实践中，我们常常会碰着延迟高导致的问题。
由于我们做事器的内核默认配成内核态不支持抢占，因此不抢占这点也是可能导致问题的缘故原由之一。
例如 A 进程陷入内核态实行韶光过长，一定影响其他希望在该核运行的进程。
此时就会导致调度延迟。
针对这种 case，我们开拓了一款工具专门跟踪陷入内核态永劫光不调度的进程。
这对付我们排查问题可以有一定的辅导方向。
同时如果是此类缘故原由导致的延迟，也可以快速定位问题缘故原由。

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

我们知道运用程序陷入内核态的办法紧张是系统调用。
我们是否可以通过系统调用供应的 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; }}

我们看到不更新韶光戳的条件比较苛刻。
紧张考虑以下几种情形：

我们再看下 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);}

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

安装 trace-noschedule 工具很大略，git clone 代码后实行如下命令即可安装。

make -j8make install5. 如何利用

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

root@n18-061-206:/proc/trace_noschedule# lsdistribution 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 distributionTrace 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_trace6. 案例展示

这里以一个实际问题带你理解工具的利用。
问题是背景是，业务创造 docker 彷佛有问题，pull 不下来镜像。
登录机器会卡顿，实行很多命令也会卡顿。

6.1 首先看下 CPU 利用情形。

有几个 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 distributionTrace 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/0xa2COMM: 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 -l65803

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