php5ereg技巧_Kernel trace tools一中断和软中断关闭时间过长问题追踪

在实际事情中，会碰着由于中断和软中断关闭韶光过长而引发的高网络延迟问题。
但是，对付该类问题的定位和追踪缺少行之有效的方案或客不雅观依据，须要耗费大量韶光和精力用于问题排查，Interrupts-off or softirqs-off latency tracer (简称：trace-irqoff)工具便是在该背景下出身的自研工具。

目前，trace-irqoff 已开源，如感兴趣详见 Open Source Repo：GitHub - bytedance/trace-irqoff: Interrupts-off or softirqs-off latency tracer

在事情中，我们常常碰着业务的进程网络延迟高。
基于此前剖析同类问题的丰富履历，造成上述问题的缘故原由有很多种。
我们创造以下两种缘故原由常常涌如今我们的视野中。

hardirq 关闭韶光过长会导致调度延迟，本地 CPU 的 softirq 也会因此得不到实行。
我们知道网络收发包便是利用 softirq，因此 hardirq 关闭韶光过长一定导致问题。
同样，softirq 关闭是一样的，虽不会影响 hardirq，但是它直接影响了 softirq 的实行。

每一次为了确认是否以上缘故原由导致问题，我们常常须要摧残浪费蹂躏很多的韶光。
因此有必要开拓一款工具专门可以定位这种缘故原由导致的网络延迟问题。
我们并不是只求案创造场，我们还要捉住首恶。
我们须要知道哪个进程在代码什么位置关闭中断，这很有助于我们高效地办理问题。

我们的目的很大略，跟踪 hardirq/softirq 关闭韶光。
我们有什么办法做到呢？最大略直不雅观的方法该当是在内核开关中断的地方加入 hook 函数，统计开关韶光戳即可得到差值，差值即关闭韶光。
Linux 内核供应打开关闭中断的 API 如下：

/ hardirq enable/disable api /local_irq_disable()local_irq_enable()local_irq_save()local_irq_restore()/ softirq enable/disable api /local_bh_disable()local_bh_enable()

没错，hardirq 关闭跟踪 Linux 内核中已经有现成的实现方案，我们只须要配置以下 config 选项即可。

CONFIG_IRQSOFF_TRACER=y

好了，彷佛我们什么都不用做直策应用即可。
看起来是这样的，但是这里存在 2 个问题。

CONFIG_IRQSOFF_TRACER 默认是关闭的，如果须要这么做我们须要重新编译内核，还要重装，末了等待问题复现。
这不是我们想要的。
Linux 内核里面中断开关频繁。
纵然方案可行，overhead 也会很高。
以是再一次不是我们想要的。

我们换一个思路。
我们可以利用 hrtimer 判断两次中断之间的韶光来判断是否关闭了中断。
hrtimer 是 Linux 中的高精度定时器，并且实行高下文是 hardirq。
以是可以基于这种办法，虽然不足精确但是足以知足我们的需求。
例如，hrtimer 定时周期是 10ms。
那么两次中断之间的韶光间隔该当是 10ms。
如果某次创造两次采样韶光间隔是 50ms，可以间接解释关闭中断约 50ms。
其余根据采样定理，两次中断之间的韶光间隔必须大于 2 倍采样周期（20ms）才能认为中断关闭。
以是我们的方法比较明确了，针对每个 CPU 都会启动一个 hrtimer，并且绑定每个 CPU。
在 hrtimer handle 里面打算中断韶光间隔。
这就做到了中断关闭检测了。
softirq 该怎么办呢？我们可以如法炮制。
在 Linux 内核中，普通定时器 timer 实行高下文便是 softirq。
很符合我们需求。
以是我们可以按照类似的方法周期性采样，只不过定时器利用的是普通 timer。

当我们创造两次中断韶光间隔大于阈值时，我们须要知道当前 CPU 究竟在做什么，导致 hardirq/softirq 被关闭。
我们可以在中断处理函数中记录当前 CPU 的栈。
这么做的条件是，中断处理函数实行时，当提高程不能发生调度，也便是首恶必须在现场。
可谓是"抓个现行"。

针对 hardirq 关闭情形。
当进程在关闭和打开中断之间发生了定时器中断，此时虽不会相应中断，但是硬件会置位 pending。
当进程打开中断时，与此同时会相应中断。
hardirq handle 会被调用。
当前的进程根本没有机会调度，以是这一定是现场，而且当提高程一定是首恶。

针对 softirq 关闭情形，是否知足上述条件呢？进程调用 local_bh_enable()打开 softirq。
精简下打开下半部的函数如下：

void __local_bh_enable_ip(unsigned long ip, unsigned int cnt){ / Keep preemption disabled until we are done with softirq processing: / preempt_count_sub(cnt - 1); if (unlikely(!in_interrupt() && local_softirq_pending())) { do_softirq(); } preempt_count_dec();}

我们可以看到如果有 softirq pending 的话，do_softirq()会卖力在当提高程高下文处理 softirq。
并其他抢占是关闭的状态。
以是我们不会调度出去，并且调用 local_bh_enable() 会急速相应普通定时器 timer。
以是这也知足以上条件。

我先回顾下触发 softirq 的实行场景。
一共会有 3 个地方。

当中断返回时会检讨 softirq pending，这是大部分实行 softirq 的场景，由于中断的分外性，在 timer handle 里面记录当前 CPU 的栈是有效的。
local_bh_enable()的情形上面已经谈论，可以捉住首恶。
但是第 3 种情形下，却不能。
这是为什么呢？

我们是在 timer handle 里面记录堆栈信息，如果 irq_exit 时 softirq 实行韶光过长，会被安排到 ksoftirqd 进程实行。
那我们记录的栈信息是什么？仅仅是 ksoftirqd 进程的栈，ksoftirq 并不是首恶。
记录是没有用的。
以是针对 ksoftirqd 实行的场景，我们须要分外的处理。
我们借助 hrtimer handle。
hrtimer 除了丈量两次 hardirq 间隔外，还丈量 softirq 多永劫光没有实行，在得当的时候记录栈。
hrtimer 实行的时候，顺便会检测 softirqirq 多永劫光没有更新韶光戳，如果操作阈值我们也会记录栈信息，这是由于后续如果 softirq 被推迟到 ksoftirqd 进程实行的话，由 softirq 的 timer 记录的栈就没有代价了。

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

make -j8make install8. 如何利用

安装 trace-irqoff 工具成功后。
会创建如下

/proc/trace_irqoff 目录。
root@n18-061-206:/proc/trace_irqoff# lsdistribute enable sampling_period trace_latency

/proc/trace_irqoff 目录下存在 4 个文件，分别：distribute, enable, sampling_period 和 trace_latency。
工具安装后，默认是关闭状态，我们须要手动打开 trace。

echo 1 > /proc/trace_irqoff/enable8.2 关闭 trace

echo 0 > /proc/trace_irqoff/enable8.3 设置 trace 阈值

trace-irqoff 工具只会针对关闭中断或者软中断韶光超过阈值的情形下记录堆栈信息。
因此我们可以通过如下命令查看当前 trace 的阈值：

root@n18-061-206:/proc/trace_irqoff# cat /proc/trace_irqoff/trace_latencytrace_irqoff_latency: 50mshardirq:softirq:

默认阈值是 50ms，如第 2 行所示。
第 4 行输出 hardirq: 代表下面的栈是可能关闭中断超过阈值的栈。
同理，第 6 行是软中断关闭韶光超过阈值的栈。
如果须要修正阈值至 100ms 可通过如下命令（写入值单位是 ms）：

echo 100 > /proc/trace_irqoff/trace_latency8.4 打消栈信息

当然如果须要打消 /proc/trace_irqoff 记录的栈信息。
可以实行如下命令（不会修正阈值为 0）：

echo 0 > /proc/trace_irqoff/trace_latency8.5 查看中断关闭次数的统计信息

如果我们须要知道中断被关闭一定的韶光的次数，可以通过如下命令获取统计信息：

root@n18-061-206:/proc/trace_irqoff# cat distributehardirq-off: msecs : count distribution 20 -> 39 : 1 | | 40 -> 79 : 0 | | 80 -> 159 : 4 || 160 -> 319 : 2 | | 320 -> 639 : 1 | |softirq-off: msecs : count distribution 20 -> 39 : 0 | | 40 -> 79 : 0 | | 80 -> 159 : 0 | | 160 -> 319 : 1 ||

在这个例子中，我们看到 hardirq 被关闭韶光 x ∈ [80, 159] ms，次数 4 次。
softirq 被关闭韶光 x ∈ [160, 319] ms，次数 1 次 如果没有任何信息输出，这解释没有任何地方关闭中断韶光超过 20ms。

从上面一节我们可以看到，中断关闭韶光分布图最小粒度是 20ms。
这是由于采样周期是 10ms。
根据采样定理，大于即是 2 倍采样周期韶光才能反响真实情形。
如果须要提高统计粒度，可修正采样周期韶光。
例如修正采样周期为 1ms，可实行如下命令（必须在 tracer 关闭的情形下操作有效）：

# 单位 ms，可设置最小的采样周期是 1ms。
echo 1 > /proc/trace_irqoff/sampling_period9. 案例剖析9.1 hardirq 关闭

我们利用如下示意测试程序，关闭中断 100ms。
查看 trace_irqoff 文件内容。

static void disable_hardirq(unsigned long latency){ local_irq_disable(); mdelay(latency); local_irq_enanle();}

通过模块测试以上代码，然后查看栈信息。

root@n18-061-206:/proc/trace_irqoff# cat trace_latencytrace_irqoff_latency: 50ms hardirq: cpu: 17 COMMAND: bash PID: 22840 LATENCY: 107ms trace_irqoff_hrtimer_handler+0x39/0x99 [trace_irqoff] __hrtimer_run_queues+0xfa/0x270 hrtimer_interrupt+0x101/0x240 smp_apic_timer_interrupt+0x5e/0x120 apic_timer_interrupt+0xf/0x20 disable_hardirq+0x5b/0x70 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/0xa9softirq:

我们可以看到 hardirq 一栏记录 cpu17 实行 bash 命令，关闭中断 107ms（偏差 10ms 之内）。
其栈信息对应 disable_hardirq() 函数中。
第 20 行 softirq 一栏没有信息，解释没有记录 softirq 被关闭的栈。

我们利用如下示意测试程序，关闭 softirq 100ms。
查看 trace_irqoff 文件内容。

static void disable_softirq(unsigned long latency){ local_bh_disable(); mdelay(latency); local_bh_enanle();}

通过模块测试以上代码，然后查看栈信息。

root@n18-061-206:/proc/trace_irqoff# cat trace_latencytrace_irqoff_latency: 50mshardirq:softirq:cpu: 17COMMAND: bash PID: 22840 LATENCY: 51+mstrace_irqoff_hrtimer_handler+0x97/0x99 [trace_irqoff]__hrtimer_run_queues+0xfa/0x270hrtimer_interrupt+0x101/0x240smp_apic_timer_interrupt+0x5e/0x120apic_timer_interrupt+0xf/0x20delay_tsc+0x3c/0x50disable_softirq+0x4b/0x80proc_reg_write+0x36/0x60__vfs_write+0x33/0x190vfs_write+0xb0/0x190ksys_write+0x52/0xc0do_syscall_64+0x4f/0xe0entry_SYSCALL_64_after_hwframe+0x44/0xa9COMMAND: bash PID: 22840 LATENCY: 106mstrace_irqoff_timer_handler+0x3a/0x60 [trace_irqoff]call_timer_fn+0x29/0x120run_timer_softirq+0x16c/0x400__do_softirq+0x108/0x2b8do_softirq_own_stack+0x2a/0x40do_softirq.part.21+0x56/0x60__local_bh_enable_ip+0x60/0x70disable_softirq+0x62/0x80proc_reg_write+0x36/0x60__vfs_write+0x33/0x190vfs_write+0xb0/0x190ksys_write+0x52/0xc0do_syscall_64+0x4f/0xe0entry_SYSCALL_64_after_hwframe+0x44/0xa9

针对 softirq 关闭情形，有 2 个栈与之对应。
我们把稳到第 9 行的函数名称和第 24 行的函数名称是不一样的。
第 9 行的栈是硬件中断 handler 捕捉到软中断关闭，第 24 行是软中断 handler 捕捉到软中断被关闭。
正常情形下，我们以 24 行开始的栈为剖析目标即可。
当 24 行的栈是无效的时候，可以看第 9 行的栈。
这里把稳：第 9 行的 lantency 提示信息 51+ms 是阈值信息。
并非实际 latency（以是我在后面添加一个'+'字符，表示 latency 大于 51ms）。
实际的 latency 是第 24 行显示的 106ms。
下面就看下为什么 2 个栈是有必要的。

我们看一个曾经处理的一个实际问题：

root@n115-081-045:/proc/trace_irqoff# cat trace_latencytrace_irqoff_latency: 300mshardirq:softirq:cpu: 4COMMAND: lxcfs PID: 4058797 LATENCY: 303+mstrace_irqoff_record+0x12b/0x1b0 [trace_irqoff]trace_irqoff_hrtimer_handler+0x97/0x99 [trace_irqoff]__hrtimer_run_queues+0xdc/0x220hrtimer_interrupt+0xa6/0x1f0smp_apic_timer_interrupt+0x62/0x120apic_timer_interrupt+0x7d/0x90memcg_sum_events.isra.26+0x3f/0x60memcg_stat_show+0x323/0x460seq_read+0x11f/0x3f0__vfs_read+0x33/0x160vfs_read+0x91/0x130SyS_read+0x52/0xc0do_syscall_64+0x68/0x100entry_SYSCALL_64_after_hwframe+0x3d/0xa2COMMAND: ksoftirqd/4 PID: 34 LATENCY: 409mstrace_irqoff_record+0x12b/0x1b0 [trace_irqoff]trace_irqoff_timer_handler+0x3a/0x60 [trace_irqoff]call_timer_fn+0x2e/0x130run_timer_softirq+0x1d4/0x420__do_softirq+0x108/0x2a9run_ksoftirqd+0x1e/0x40smpboot_thread_fn+0xfe/0x150kthread+0xfc/0x130ret_from_fork+0x1f/0x30

我们看到下面的进程 ksoftirqd/4 的栈，延迟韶光是 409ms。
ksoftirqd 进程是 kernel 中处理 softirq 的进程。
因此这段栈对我们是没故意义的，由于首恶已经错过了。
以是此时，我们可以借鉴上面的栈信息，我们看到当 softirq 被延迟 303ms 的时候，当前 CPU 正在实行的进程是 lxcfs。
并且栈是 memory cgroup 干系。
因此，我们基本可以判断 lxcfs 进程实行韶光过长，由于 kernel 态不支持抢占，因此导致 ksoftirqd 进程没有机会得到运行。

根据字节内部实践来看，trace-irqoff 安装便捷且利用灵巧度高，能将问题定位耗时缩短至分钟级别，利用收益可不雅观，并且已经通过该工具定位很多问题，提高了事情效率。

字节跳动在 RocksDB 存储引擎上的改进实践

字节跳动自研万亿级图数据库 & 图打算实践

深入理解 Linux 内核--jemalloc 引起的 TLB shootdown 及优化

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

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