本文是由字节跳动体系 STE 团队出品的 “kernel trace tools” 系列文章，以介绍团队自研多类推迟问题追寻东西。

在实践工作中，会遇到因为中止和软中止封闭时刻过长而引发的高网络推迟问题。可是，对于该类问题的定位和追寻缺乏行之有用的计划或客观依据，需求消耗大量时刻和精力用于^ n q 5 O问题排查，Interrupts-off or( a ) @ X ~ j Q softirqs-off latency tracer (简称：trace-irqoff)东西便是在该背景下诞生的自研东西。

目前，trace-irqoff 已开源，如感兴趣详见 Open So% b Z Uurce Repo: http://github.com/bytedance/trace-irqoff/tree/master
。

1. 问题背景

在工作中，咱们常常遇到事务的进程/ W |网络推迟高。基于此前分析同类问题的丰厚经历，形成上述问题的原因有许多种。咱们发现以下两种原因常常出现在咱们的视野中。

• hardirq 封闭时刻过长。
• softirq 封闭时刻过长。

hardirq 封闭时刻过长会导致调度推迟，本地 CPU 的 softirq 也会因而得不到履行。咱们知道网络收发包便是运用 softirq，因而 hardirq 封闭时刻过长必定导致问题。同样，softirq 封闭4 K d ] r w ~ $是一样的，虽不会影响 hardt ! G , A G Mirq，可是它直接影响了 softirq 的履行。

2. 咱们需求什么

每一次为了承认是否以R } /上原因导致问题，咱们常常需求浪费许多的时刻。因而有必要开发一0 u a款东西专门能够定位这种原因导致的网络推迟问题。咱们并$ Z ~ / F d i D K不是只求I X 7 P t案发现场，咱们还要抓住首恶。咱们需求知道哪个进程` j 4 C G = r _ *在代码什么方位封闭中止，这很有助于咱们高效地解决问题。

3. 是否有现成的计划

咱们的意图很简略，盯梢 hardirq/sofl 3 * ? mtirq 封闭时刻。咱们有什么办法做到呢？最简略直观的办法应该是在内核开关中止的当地加入 hook 函数，核算开关时刻戳即可得到4 M差值，差值即封闭时刻。Linux 内核提供翻开封闭中止的 API 如下：

/* hardirN J ` G r `  Aq enable/disab/ Q r ` w v K 2le api */
local_irq_disable()
local_irq_enable()
local_i6 3 # Z Y ^ : erq_save()
local_irq_restore()
/* softirq enable/disable api */
local_bh_disable()
local_bh_eU : znable()

没错，hardirq 封闭盯梢 Linux 内核中已经有现成的完成计划，咱们只需求装备以下 config 选项即可。

CONFIG_IRu ; ( e 9 QQ$ _ 9 ! & - KSOFF_TRACER=y

好了，好像咱们什么都不用做直接运用即可。看起来是这样的，可是这儿存在& . ? 2 个问题。

CONF8 / = t LIG_IRQSOFF_I @ ; nTRACER 默许是封闭的，假如需求这么做咱们需求重新编译内核，还要重装，最终等候问题复现。这不是咱们想要的。
Linux 内核里边中止开关频频。即便计划可行，overhead 也会很高。所以再一次不是咱们想要的。

4. 咱们3 ^ & 9的办法

咱们换一个思路。咱们能够利用 hrtimer 判别两次中止之间的时刻来判别是否封闭了中止。hrtimer 是 Linux 中的高精度守时器，而且履行上下文是 hardirq。所以能够基于这种方法，尽管不行精确可是足以满意咱们的需求。例如L ! 2 o，hrtimer 守时周期是 10msz Q K c。那么两次0 G L 9 I |中止之间的时刻距离应该是 10ms8 & = M D。假如R y Z # O B R某次发现两次采样时刻距离是 50ms，能够B M n . m x F R直接阐明封闭中止约 50ms。别的依据采样定理，两次中止之间的时刻距x p s离有必要大于 2 倍采样周期（20ms）才干认为中止封闭。所以咱们的办法比较清晰了，针对每个 CPU 都会发动一个 hrtimer，而且绑定每个 CPU。在 hrA o l I + ytimer handle 里边核算中止时刻距离。这就做到了中止封闭检测了5 ) u %。
sD B w Y * ^oftirq 该怎么办呢？咱们能够如法炮制。在 Linux 内核中，普通守时器 timer 履行上下文便是 softirq。很契合咱们需求。所以咱们能够依照类似的办法周J o 6 E I 0 N G [期性采样，只不过守时器运用的是普通 timw k # L I * e M ger。

5. 记载首恶的栈

当咱[ # m i p C * )们发现两次中止时刻距离大于阈值时，咱们需求知道当时 CPU 终究在做什么，导致 hardirq/softirq 被封闭。咱们能够在中止处理函数中记载当时 CPU 的栈。这么做的前提是，中止处理函数履行时，当时进程不能发作调度，也便是首恶有必要在现场。可谓是”抓个现行”。

5.1 hardirq

针对 hardirq 封闭状况。当进程在封闭和翻开中止之间发作了守时器中止，此时虽不会响应中止，可是硬件会置位 pendie j L G { @ng。当进程翻开中止时，与此一起会响应中止。hardirq ha. / pndle 会被调用。当时的进程底子没有机会调= Z l + e E L – E度，所以这一定是现场，而且当时进程一定是首恶。

5.2 softirq

针对 softirq 封闭状况，是否满意上述前提呢？进程调用 local_bh_enable()翻开 softi1 @ .rq。精简下翻开下半部的函数如下：

void __loo d Y g +cal_bh_enable_ip(unsigned long ip, unsigned int cnt)
{
/*
* Keep preemption disabled unt 5 % ,il we are done with
* softirq processing:
*/
preempt_count_sub(cnN S d t ) Q zt - 1);
if (unl _ ^ T 8 vikely(!in_l I + t 6interrupt() && loc` 3 V = S 9 F kal_softirq_pending())) {
do_` N ]softirq();
}
preempt_count_dec();
}

咱们能够看到假如有 softirq pending 的话，do_softirq()会负责在当1 ` R时进程上下文处理 softirq。并其他抢占是封闭的状态。所以咱们不会调度出去，而且调用 loq q k d mcal_bh_enable() 会马上响应普通守时器 timer。所以这也满意以上条件。

6. so# C & X {ftirq 的特别

我先回忆下触发 softirq 的履行场景。总共会有 3 个当地。

• irq_exit()

• local_bh_enable()

• ksoftirqd 进程

当中止回来时会检查 softirq peu w @ z lnding，这是大部分履行 softirqq V c : A 7 G I 的场景，因为中止的特别性，在 timer handle 里边记载当时 CPU 的栈^ , C X 3 a是有用– e I I ; e :的。local_bh_enable()的状8 K – * l 6 D ! &况上面已经讨论，能够抓住首恶。可是第 3 种状况下，却不能。这是为什么呢？

咱们是在 timer hd ] @ m D g =andle 里边记载仓库信息，u , m z # R假如 irq_exit 时R B W u softirq 履行时刻过长，会被安排到 ksoftirqd 进程履行。那咱们记载的栈信息是什么？仅仅是 ksoftirqd 进程的栈，ksoftirq 并不是首恶。记载是没有用的。所以针对 ksoftirqd 履行的场景，咱们需求特别的处理。咱们凭借 hrtimer handle。hrtimer 除了测量两次 hardirq 距离O J $ * q F E y a外，还测量 softirq 多长时刻没有履行，在合适的时分记载栈。hrtimer 履行的时分，W f k :顺便会检测 softirqirq 多长时刻没有更新时刻戳，假如操作阈值咱们也会记载栈信息，这是因为后续假如 softirq 被推迟到 ksM 1 P *oftirqd 进程履行的话，由 softirq 的 timer 记载的栈就没有价值了。

7. 如何装置

装置 trace-irqoff 东西q M ~ V P S 7 # K很简略，git clone 代码后履行如下指令! s v即可装置。

make -j8
make install

8. 如何运用

装置 trace-irqoff 东西成功后。会创立如下

/proc/t$ F 8 *race_irqoff 目录。
root@n18-061-206:/p3 K - Sroc/trac- N a Z y Ye_irqoff# ls
distribute  enable  sampling_period  trace_latency

/proc/trace_irqoff 目录下存在 4 个文件，别离：distribute, enable, sampling_q @ M b 2period 和 traceb s U_latency。东西装置后，默许是封闭状态，咱们需求手动翻开 trace。

8.1 翻开 trace

echo 1 > /proc/trace_irqoff/enable

8.2 封闭 trace

echo 0 > /proc/4 7 - a 4 q U U gtrace_irqoff/enable

8.3 设置 tr` I # 7 R `ace 阈值

trace-irqoff 东西只会针对封闭中止或者软中止时刻超越阈值的状况下记载仓库信息。因而咱们能够经过如下指令检查当时 trace 的阈值：

root@n18-061-206:/proc/trace_irqoff# cat /proc/trace_irqoff/trace_latency
trm Q d ) z d {ace_irqoff_latency: 50ms
hard? [ _ 8 l 8irq:
softirD 7 E ]q:

默许阈值是 50ms，如第 2 行所8 w u ( N示。第 4 行输出 hardirq: 代表下面的栈是可能封闭中止超越阈值的栈。同理，第 6 行是软中止封闭时刻超越阈值的栈。假如需求修正阈值至 100ms 可经过如下指令（写入值单位是 ms）：

echo 100 > /proc/trace_irqo* p * wff/trace_latency

8.4 铲除栈信息

当然假如需求铲除 /proc/traL f 9 ; N }ce_irqoff 记载的栈信息。能够履行如下指令（不会修正阈值为 0）：

echo 0 > /proc/trace_irqoff/trace_latency

8.5 检查中止I U ] 4 8封闭次数的核算信息

假如咱们需求知道中止被封闭一定的时刻的次数，能够经过如下指令获取核算信息：

root@n18-061-206:/proc/trace_irqoff# cat distribute
hardirq-off:
msecs           : count     distributioK 7 f 3 In
20 -> 39         : 1        |**********                              |
40 -> 79         : 0        |                                        |
80 -> 159        : 4        |****************************************|
160 -> 319        : 2        |********************                    |
320 -> 639        : 1        |**********                             | @ v 7 c
softirq-off:
msecs           : count     distribution
20 -> 39         : 0        |                                        |
4%  T Q )0 -> 79         : 0        |                                        |
80 -> 159        : 0        |                                        |
160 -> 3192 2 ) G | [ U        : 1        |**************************************X 1 k w  V c**|

在这个比如中，咱们看到 hardirq 被封闭时刻 x ∈ [80, 159] ms，次数 4 次。softirq 被封闭时刻 x ∈4 – c [160, 319] ms，次数 1 次 假如没有任何信息输出，这阐明没有任何当地封闭e p D中止时刻超越 20ms。

8.6 修正采样周期

从上面一节咱们能够看到，中止封闭时刻分布图m E c v ; R O W &最小粒度是 20ms。这是因为采样周期是 10ms。依据采样定理，大于等于 2 倍采样( ~ 0周期时刻才干反映+ t ) { z真实状况。假如需求提高核算粒度，可修正采样周期时刻。例如修正采样周期为 1ms，可履行如下指令（有必要在 tracT y Z { V P ] 7er 封闭的状况4 X ! O m x R下操作有用）：

# 单位 ms3 t 5 U 1 } a _，可设置最小的采样周期是 1ms。
echo 1 > /proc/trace_irqoff/sampling_period

9. 事H C % I M k W ) Z例分析

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_latency
trace_irG c ] p +qoff_latency: 50ms
hardirq:
cpu: 17
COMMAND: bash PID: 22840 LATENCY: 107ms
trace_irU 6 A W ] /qoff_hrtimer_handler+0x39/0x99 [trace_irqoff]
__hrtimer_run_i y Fqueues+0xfa/0x270
hrtimer_interrupt+0x101/0x240
smp_apic_a Q Z c H E B ( ptime! ^ T + Y l 1 Mr_interrupt+0x5e/0x120
apic_timer_interrupt+0xf/0x20
disable_hardirq+0x5b/0x7L ] ! ^0
proc_reg_write+0x36/0x60
__v} - h $fs_write+0x33/0x19} L ` = / t p0
vfs_write+0xb0/0x190
ksys_write+0x52/0xc0
do_syscall_64+0x4f/0xe0
enp U Ytry_SYSCALL_64_after_hwframe+0x44/0xa9
softirq:

咱们能够看到 hardirq 一栏记载 cpu17 履行 bash 指令s 4 4 w , r，封闭中止 107ms（误差 10ms 之内）。其栈信息对应 disable_hardirq() 函l s h T F [ i S数中。第 20 行 softirq 一栏没有信息，} L Z b U a阐明没有记载 softirq 被封闭的栈。

9.2 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_latency% w  n
trace_irq? Z g 3 | C ^ Q _off_latency: 50ms
hardirq:
softirq:
cpu: 17
CG 6 P N 6 o n n SOMMAND: bash PID: 22840 LATENCY: 51+ms
trace_irqoff_hrtimer_handler+0x97/0x99 [trace_irqoff]
__hrtimer_run_qS b x V j sueues+0xfa/0x270
hrtimw , : |er_interrupt+0x101/0x240
smp_apic_= V x { B otimer_in( F $ 4 @terrupt+0x5e/0x120
apic_timer_interrupt+0xf/0x20
delay_tsc+0x3c/0x50
disable_softirq+0x4b/0x80
proc_reg_B [ ) f e A z $write+0x36/0x60
__vfs_write+0x33/0x190
vfs_write+0xb0/0xh $ $ s p l 8190
ksys_write+0x52/0xc0
do_syscall_64+0x4f/0xe0
entry_SYSCALL_64_after_hwframe+0x44s 6 ? C + | ) 3/0xa9
COMv . ` j eMAND: bash PID: 22840 LATENCY: 106ms
trace_irqoff_timer_handler+0x3a/0x60 [I & r 0 x 1 # J otrace_irqoff]
call_timer_fn+5 4 Q 1 q 6 _0x29/0x120
run_timer_softirq+0x16c/0x400
__do_softirq+0x108/0x2b8
do_softirq_own_stack+0x2a/0x40
do_softirq.part.21+0x56/0x60
__local_bh_enable_ip2 l Y 3 1 t ( 9+0x60/0x70
dis# 8 l _ * s f O {able_softirq+0x62/0x80
proc_reg_write+0x36/0x60
__vfs_write+0x33/0x190
vfs_write+0xb0/0x190
k; , 3 | .sys_wri% ) e s ? # H W qte+0x52/0xc0
do_syscall_64+0x4f/0xH - 3 v ` c J !e0
entry_SYSCALL_64_after_hwframe+0x44`  t/0xa9

针对F T B 0 C N softirq 封闭状况，有 2 个栈与之对应。咱d 6 | W [们留意到第 9 行的函数名称和第 24 行的函数名称是不一样的。第 9 行的栈是硬件中止 handler 捕捉到软中止封闭，第 24 行| * h 0 # R 5是软中止 handler 捕捉到软中止被封闭。正常状况下，咱们以 24 行开始的栈为分析目标即可。当 24 行的栈是无效的时分，能够看第 9 行的栈。这儿留意：第 9B J x ` P 行的 lantency 提示信息 51+ms 是阈值信息。并非实践 latency（所以我在后面增加一个’+w s 0 _ I l R s‘字符，表明 latency 大于 5k ) b 81ms）。实践的 latency 是第 24 行显示的 106ms。下面就看下为什么 2 个栈是有必要的。? n V | k ]

9.3 ksoftirqd 推迟

咱们看一个从前处理的一个实践问题：

root@n115-081-045:_ Q U A - h/proc/trace_irqof 3 g  ~ 1 , 1 Wff# cat trace_latency
trace_irqoff_latency: 300ms
hardirq:
so( g . 0 N v G 9fZ t s T - Vtirq:
cpu: 4
COMMAND: lxcfs PID: 4058797 LATENCY:j 0 ^ m 303+ms
trace_irqoff_record+0x12b/0x1b0 [trace_irqoff]
trace_irqoff_hrtimer_ha^ J b C #ndler+0x97/0x99 [trace_irqoff]
__hR - g ortimer_run_queues+0xdc/0x220
ho e W M g = nrtimer_interrupt+0xa6/0x1f0
smp_apic_timer_interrupt+0x62/0x120
apic_timer_interrupt+0x7d/0x90
memcg_sum_events.isra.26+0x3f/0x60
memcg_st1 4 @ O v o : A xat_show+0x323/0x460
seq_read+0x11f/0x3f0
__vfs_read+R C A = ~ Z /0x33/0x160
vfs_read+0x91/0x1O R R 1 X j30
SyS_read+0x52/0xc0
do_syscall_64+0x68/0x100
entry_SYSCAU h A K n ~ @ $LL_64_after_hwfrar  d 5 z me+0x3d/0xa2
COMMAND: ksoftirqd/4 PID: 34 LATENCY: 409ms
trace_irqoff_record+0x12b/0x1b0 [trace_iG Y D d 6 Z * T +rqoff]
trace_irqoff_timer_handler+0x3a/0x60 [trace_irqofg ! K J H N W bf]
call_timer_fn+0x2e/$ y 4 ^0x130
run_timer_softirq+0x1d4/0x420
__do_softirq+0x108/&  t0x2a9
run_ksoftirqd+0x1e/0x40
smpboot_thr^ 4 A p  4 G Dead_fnT ) 8 h W q  T+0xfe/0x150
kthread+0xfc/0x130
ret_from_fork+0x1f/0x30

咱们看到下面的进程 kso1 F @ Y p h t b fftirqd/4 的栈，推迟K n / b % 9 ( U时刻是 409ms。ksoftirqd 进程是 kernel 中处理 softirq 的进程。因而这段栈对咱们是没有意义的，因为首恶已经错过了。所以此时，咱们能够借鉴上面的栈信息，咱们看到当 softirq 被推迟 303ms 的时分，当时 CPU 正在履行的进程是 lxcfs。而且栈是 memory cgroup 相关。因而，咱们根本能够判别 lxcfs 进程履行时刻过长，因为 kernC c f h f I Q n *el 态不支持抢占，因而导致 ksoftirqd 进程没有机会得到运行。

10. 总结

依据字节内部实践来看，trace-irqoff 装置便捷且运用灵敏度高，能将问题定位耗时缩短至分钟等级，运用收益可观，而且已经经过该东西定位许多问题，提高了工作效率。

更多分享

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

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

深化理解 Linux 内核–jemalloc 引起的 TL_ 4 |B shootdown 及优化

字节跳动体系 STE 团队

字节跳动体系 STE 团队一向致力于操作体系内核与虚拟化、体系根底软件与根底库的构D h a E 5 o k建和性能优化、超大规模数据中心的稳定性和可靠性建造、新硬件与软件的协同设计等A } w 2 w体系根底技能领域的研制与工程化落地，具备全面的根底软件工程才能，为字节上层事务保驾护航。u w Z E : V 4 X ,一起，团队积极关注社区技能意向，拥抱开源和标准。欢迎更多有志之士加入，如有意向可发送简历至：sysrecruitment( x ! T K & G $@bytedance.com

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