在针对Real-Time Linux(实时性Linux)的性能调优中,cyclictest 常被比作系统的“体温计”。它能够清晰地告诉我们系统是否“生病了”(延迟过高),但往往无法直接指出“病灶”的确切位置。
当 cyclictest 报告出高达100ms的Max Latency时,我们该从何下手?是检查设备驱动代码,还是怀疑内核调度策略,亦或是底层固件(如ARM Trusted Firmware, ATF)在暗中作祟?
很多时候,我们面对的是一个复杂的黑盒。为了彻底厘清延迟的来源,我没有直接去修复某个具体的Bug,而是选择了一条逆向工程之路——编写内核模块来主动“制造故障”。通过复现硬中断风暴、优先级饿死、内核锁竞争、硬件SMI(系统管理中断) 这四大经典高延迟场景,并配合强大的 Ftrace 工具进行分析,我总结出了一套通用的二阶段排查法。
在深入细节之前,我们有必要先理解 cyclictest 的基本工作原理:

cyclictest 会创建指定数量和优先级的实时进程。每个进程设置一个定时器,用于周期性地唤醒自己。从定时器溢出触发硬件中断、进入中断服务程序(ISR)并调用 wake_up_process() 唤醒实时进程,到该进程真正开始在CPU上执行,这中间的时间差就是我们需要测量的调度延迟。进程恢复运行后,会获取当前精确时间,减去其睡眠开始时刻和预定的睡眠时长,即可计算出具体的延迟值。
那么,通常哪些原因会导致延迟异常增高呢?
- 硬中断干扰或中断被关闭。当
cyclictest 的定时器到期本应被唤醒时,CPU可能正在执行某个中断处理函数(这会自动关闭本地CPU中断),或者内核代码主动关闭了中断,导致唤醒动作被严重推迟。
- 调度延迟。
cyclictest 进程已经被成功唤醒(状态变为可运行 R),但当前CPU的运行队列(runqueue)中存在着优先级更高的线程,导致 cyclictest 无法立即获得CPU执行权。
- 内核抢占被关闭。当
cyclictest 应该被唤醒时,定时器中断可以正常触发,但由于内核处于不可抢占的状态(例如持有自旋锁),调度器无法立即切换到 cyclictest 进程。
- 硬件/固件层面的“黑洞”。在ARM64架构中,Linux内核运行在异常等级EL1,虚拟化层(如KVM)运行在EL2,安全世界(如TrustZone)运行在EL3。当CPU因为执行
hvc 或 smc 指令而陷入EL2或EL3时,整个Linux内核的运行将被完全挂起,且内核自身无法感知这段时间的流逝。
为了更直观地理解这些场景背后的原理,我们通过实际操作来逐一复现和分析它们。
场景一:硬中断干扰与中断关闭
首先,我们使用一个专门的内核模块来模拟硬中断长时间占用CPU的场景。
git clone https://github.com/hlleng/rt_test_noise
cd irq_noise && make
sudo insmod irq_noise.ko
sudo ./trace_irq_noise.sh
如果执行脚本提示缺少某些trace event,请确保内核配置中已启用它们。接着,我们使用 cyclictest 进行性能测试:
# 1. 将CPU调频策略设为performance,防止动态调频引入额外延迟
for i in 0 1 2 3; do echo performance > /sys/devices/system/cpu/cpu$i/cpufreq/scaling_governor; done
# 2. 运行cyclictest,设置当延迟超过3000微秒时停止测试并触发ftrace标记
sudo cyclictest -t 1 -a 0 -p 80 -D 5m -b 3000 --tracemark # 若无此命令,请安装rt-tests包
# 3. 向内核模块写入数据,模拟一次持续3000微秒的硬中断处理
echo 3000 | taskset -c 0 tee /proc/inject_irq_latency
对以上命令的详细解释:
- 第一句:将CPU频率调节器设为
performance模式,避免CPU因负载变化而升降频,从而排除频率变化对延迟测量的干扰。请根据实际CPU核心数修改循环范围。
- 第二句:启动
cyclictest测试。
-t 1 -a 0:只启动1个测试线程,并将其绑定到CPU0上,简化分析。
-p 80:设置线程调度策略为SCHED_FIFO,优先级为80(数值越高,优先级越高)。
-D 5m:测试时长为5分钟。
-b 3000 --tracemark:设置延迟阈值为3000微秒。一旦检测到延迟超过此值,立即停止ftrace采样和cyclictest测试,并在trace日志中写入特殊标记 tracing_mark_write: hit latency threshold。
- 未指定
-i参数时,默认唤醒间隔为1000微秒。
- 第三句:通过向
/proc/inject_irq_latency写入3000,指示irq_noise模块制造一次持续约3000微秒的“中断风暴”。如果一次写入未能触发cyclictest停止,可尝试多次写入,原因下文会解释。
若操作成功,cyclictest会输出类似以下日志,表明捕获到了超阈值的延迟:
sudo cyclictest -t 1 -a 0 -p 80 -D 5m -b 3000 --tracemark
# /dev/cpu_dma_latency set to 0us
INFO: debugfs mountpoint: /sys/kernel/debug/tracing/
policy: fifo: loadavg: 0.73 0.91 0.53 2/364 8160
T: 0 ( 8148) P:80 I:1000 C: 6003 Min: 30 Act: 49 Avg: 45 Max: 2838
# Thread Ids: 08148
# Break thread: 8148
# Break value: 3157
为了方便分析,我们将ftrace日志导出:
cat /sys/kernel/debug/tracing/trace > /tmp/trace_irq.txt
现在,让我们解读关键的trace日志片段:
tee-8160 [000] dNh.. 856.208920: sched_wakeup: comm=cyclictest pid=8148 prio=19 target_cpu=000
tee-8160 [000] dNh.. 856.208923: hrtimer_expire_exit: hrtimer=000000005c8f967e
tee-8160 [000] dNh.. 856.208926: irq_handler_exit: irq=23 ret=handled
tee-8160 [000] d.... 856.208954: sched_switch: prev_comm=tee prev_pid=8160 prev_prio=120 prev_state=R ==> next_comm=cyclictest next_pid=8148 next_prio=19
cyclictest-8148 [000] d.... 856.208990: sched_switch: prev_comm=cyclictest prev_pid=8148 prev_prio=19 prev_state=S ==> next_comm=tee next_pid=8160 next_prio=120
tee-8160 [000] d.h.. 856.209894: irq_handler_entry: irq=23 name=arch_timer
tee-8160 [000] d.h.. 856.209898: hrtimer_expire_entry: hrtimer=0000000086669db1 function=timer_callback [irq_noise] now=856211171021
tee-8160 [000] d.h.. 856.212940: hrtimer_expire_exit: hrtimer=0000000086669db1
tee-8160 [000] d.h.. 856.212944: hrtimer_expire_entry: hrtimer=000000005c8f967e function=hrtimer_wakeup now=856214218069
tee-8160 [000] dNh.. 856.212957: sched_wakeup: comm=cyclictest pid=8148 prio=19 target_cpu=000
tee-8160 [000] dNh.. 856.212959: hrtimer_expire_exit: hrtimer=000000005c8f967e
tee-8160 [000] dNh.. 856.212961: hrtimer_expire_entry: hrtimer=00000000c5b1b039 function=tick_sched_timer now=856214218069
tee-8160 [000] dNh.. 856.212991: hrtimer_expire_exit: hrtimer=00000000c5b1b039
tee-8160 [000] dNh.. 856.212994: hrtimer_expire_entry: hrtimer=000000009ea9d197 function=hrtimer_wakeup now=856214218069
tee-8160 [000] dNh.. 856.213008: sched_wakeup: comm=cyclictest pid=8147 prio=120 target_cpu=000
tee-8160 [000] dNh.. 856.213010: hrtimer_expire_exit: hrtimer=000000009ea9d197
tee-8160 [000] dNh.. 856.213012: irq_handler_exit: irq=23 ret=handled
tee-8160 [000] d.... 856.213036: sched_switch: prev_comm=tee prev_pid=8160 prev_prio=120 prev_state=R ==> next_comm=cyclictest next_pid=8148 next_prio=19
cyclictest-8148 [000] ..... 856.213140: tracing_mark_write: hit latency threshold (3157 > 3000)
关键事件说明:
sched_wakeup:当进程(线程)从阻塞状态被唤醒,并加入可运行队列(runqueue)时触发。
sched_switch:当调度器决定将CPU从一个进程(prev)切换到另一个进程(next)时触发,next进程开始占用CPU。
从日志最后一行可知,线程cyclictest-8148检测到了3157us的延迟,超过了3000us的阈值。
时间线分析:
- 在
856.212957时刻,发生了 sched_wakeup,将cyclictest-8148加入runqueue。
- 在
856.213036时刻,发生了 sched_switch,cyclictest-8148正式获得CPU并开始执行。
- 两者的差值约为79us,这是唤醒后正常的调度开销。
追溯上一次唤醒:
- 在
856.208920时刻,cyclictest-8148被上一次唤醒并加入runqueue。由于其唤醒周期是1ms(1000us),因此理论上的下一次唤醒点应在856.209920左右。
- 注意
856.209898时刻:就在cyclictest即将醒来前(相差约22us),irq_noise模块的回调函数被触发。此时CPU进入了硬中断上下文(标志位为d.h..),并开始执行一个忙等循环。
irq_noise占用的时长:从856.209898 (hrtimer_expire_entry) 到 856.212940 (hrtimer_expire_exit),持续时间约为3042us,这与我们写入的3000us基本吻合。
如果文字描述不够直观,我们可以用以下流程图来概括整个过程:
[ 上次休眠 sched_switch ] (Timestamp: 856.208990)
|
| (cyclictest 睡眠,预计 1ms 后唤醒)
v
.
. 时间流逝 ...
.
|
(就在理论唤醒点之前 856.209894) -> [ irq_handler_entry (硬件定时器中断触发) ]
|
(856.209898) -> [ hrtimer_expire_entry (irq_noise 回调开始) ]
|
v
+=========================================================================+
| *** 严重阻塞区域 (硬中断上下文) *** |
| |
| [ 理论唤醒点 T_expected (~856.2099xx) ] <-- 本该在此刻唤醒 |
| (由于下方的高优先级忙等,此唤醒被推迟) |
| |
| ..................................................................... |
| . . |
| . [ IRQ NOISE 霸占 CPU (死循环忙等) ] . |
| . . |
| . 持续时长: 3042 us . |
| . . |
| ..................................................................... |
| |
+=========================================================================+
|
(856.212940) -> [ hrtimer_expire_exit (irq_noise 回调结束,释放 CPU) ]
|
v
(856.212957) -> [ 实际唤醒 sched_wakeup ] (cyclictest 加入 runqueue)
|
| (调度延迟: 79us)
|
(856.213036) -> [ 实际执行 sched_switch ] (cyclictest 开始运行,检测到高延迟)
为什么不是100%触发?
这里存在一个“相位对齐”问题。我们注入的延迟是3000us,报警阈值(-b)也是3000us,而cyclictest的周期是1000us。考虑以下简单时序:
cyclictest计划在T=1000醒来,执行到T=1001,然后睡眠。
- 它在
T=1001正常执行完,进入睡眠,计划下次在T=2001醒来。
- 我们的中断风暴覆盖了
T=2001这个唤醒点。
cyclictest在T=4002(中断风暴结束后)才被唤醒。
- 计算延迟:
4002(实际) - 2001(计划) = 2001us。
- 结果:延迟只有2ms左右,低于3000us阈值,未能触发报警。
如果想确保100%触发,需要注入超过4000us(例如4500us)的延迟,这样最坏情况下的延迟也必然超过阈值。
场景二:调度延迟与优先级饿死
接下来分析调度延迟场景。这很好理解:当cyclictest的定时器到期,内核通过sched_wakeup将其加入runqueue。但由于此时runqueue上存在优先级更高的线程,调度器必须优先执行它们,cyclictest只能排队等待。
[ 上次休眠 sched_switch ] (cyclictest 释放 CPU 进入睡眠)
|
| (cyclictest 睡眠中...)
| (此时 CPU 上运行着其他任务,例如一个较低优先级的普通进程)
v
.
. 时间流逝 ...
.
|
(理论唤醒点 T_expected 到达) -> [ 定时器中断触发 ] (内核进入中断处理)
|
v
(中断上下文中) -> [ 核心事件: sched_wakeup (cyclictest) ]
|
| 说明: 此时 cyclictest 状态由 SLEEPING 变为 RUNNABLE。
| 它被挂入了 CPU 的运行队列 (Runqueue),**准备好**执行了。
|
v
+=========================================================================+
| *** 调度阻塞区域 (Scheduling Blocked Region) *** |
| |
| [ 关键冲突 ]:CPU 并未立即切换到 cyclictest。 |
| |
| ..................................................................... |
| . . |
| . [ 障碍:更高优先级的任务 (Higher Priority Task) 正在运行 ] . |
| . (例如:一个实时进程,或者内核自身的紧急线程,如 migration/0) . |
| . . |
| . ------------------------------------------------------------- . |
| . >> cyclictest 状态:就绪 (Runnable) . |
| . >> cyclictest 位置:在运行队列 (Runqueue) 中排队等待 CPU . |
| . ------------------------------------------------------------- . |
| . . |
| ..................................................................... |
| |
| (这段等待时间构成了主要的调度延迟) |
+=========================================================================+
|
| (高优先级任务终于执行完毕,或主动让出了 CPU)
v
[ 调度器介入 (Scheduler runs) ] (挑选下一个最合适的任务)
|
v
[ 核心事件: sched_switch ] (上下文切换:Prev_High_Prio ==> Next_cyclictest)
|
v
(cyclictest 终于获得 CPU 开始实际执行代码,计算并报告延迟)
我们可以使用stress-ng工具来模拟一个高优先级任务占满CPU的场景。
# stress-ng 使用默认的 SCHED_OTHER 策略 (普通进程),优先级低于实时进程
sudo taskset -c 0 stress-ng --cpu 1 --timeout 600s &
# 运行 cyclictest
sudo cyclictest -t 1 -a 0 -p 80 -D 5m -b 3000
policy: fifo: loadavg: 0.17 0.17 0.10 1/301 1695
T: 0 ( 1498) P:80 I:1000 C: 299994 Min: 11 Act: 53 Avg: 31 Max: 698
(由于测试内核未打PREEMPT_RT实时补丁,延迟数据可能表现一般)
接下来,我们让stress-ng以更高的实时优先级运行:
# stress-ng 使用 SCHED_FIFO 策略,优先级设为90,高于 cyclictest 的80
sudo taskset -c 0 stress-ng --cpu 1 --sched fifo --sched-prio 90 --timeout 600s &
sudo cyclictest -t 1 -a 0 -p 80 -D 5m -b 3000 --tracemark
此时,cyclictest 很可能几乎无法输出任何数据,因为CPU被优先级为90的stress-ng进程完全占满。只有当stress-ng进程超时退出后,cyclictest才有机会获得CPU并运行。
场景三:内核抢占被关闭
第三种场景——内核抢占被关闭。从用户态的观测结果来看,它与场景二(调度延迟)非常相似:cyclictest都无法及时获得CPU。可谓“同一种死法,不同的凶手”。
然而,从内核实现机制和问题排查视角来看,二者有本质区别。我们可以用一个“霸权等级金字塔”来理解CPU执行流的可打断性,等级越高,特权越大,越能阻断低等级的执行。
/ \
/ \
/ Level 1 \ <-- 硬中断 / 关中断 (Hard IRQ)
/ (最高特权) \ (谁都打不断,导致硬中断延迟)
/______________\
/ \
/ Level 2 \ <-- 关抢占 / 自旋锁 (Preempt Off)
/ (调度器失效) \ (中断能进,但不能切换任务)
/____________________\
/ \
/ Level 3 \ <-- 普通进程 / 实时进程
/ (可被随意抢占) \ (受制于优先级调度)
/__________________________\
如果已经克隆了rt_test_noise仓库,我们可以使用其中的模块来模拟关闭抢占的场景。
# 1. 设置CPU性能模式
for i in 0 1 2 3; do echo performance > /sys/devices/system/cpu/cpu$i/cpufreq/scaling_governor; done
# 2. 启动 cyclictest
sudo cyclictest -t 1 -a 0 -p 80 -D 5m -b 3000 --tracemark
# 3. 启动跟踪脚本并注入抢占延迟
sudo ./trace_preemptirqoff.sh
echo 3500 | taskset -c 0 tee /proc/inject_preempt_latency
检查记录到的最大延迟:
cat /sys/kernel/debug/tracing/tracing_max_latency
3507
可以看到最大延迟约为3507us,与我们注入的3500us基本一致。
分析详细的ftrace日志(完整日志较长),我们可以将其分为三个阶段:关闭抢占、中断插曲、开启抢占。
第一阶段:关闭抢占
k_preemp-1645 0...1. 1us : preempt_count_add <-preempt_count_add
k_preemp-1645 0...1. 2us : __udelay <-thread_fn
关注标志位 0...1.。这里的 1 表示 preempt depth(抢占深度)为1,即内核当前处于禁止抢占状态。只有抢占深度为0时,调度器才能进行任务切换。
第二阶段:中断插曲(关键)
在 362us 时,CPU0触发了一次硬件定时器中断:
k_preemp-1645 0d..1. 362us : irq_enter_rcu <-el1_interrupt
...
k_preemp-1645 0d.h1. 375us : arch_timer_handler_phys <-handle_percpu_devid_irq
中断处理程序发现cyclictest的定时器到期,于是尝试唤醒它:
k_preemp-1645 0d.h1. 389us : hrtimer_wakeup <-__hrtimer_run_queues
k_preemp-1645 0d.h1. 391us : try_to_wake_up <-wake_up_process
...
k_preemp-1645 0d.h4. 411us : enqueue_task_rt <-enqueue_task
关键标志位变化出现在 433us 这一行:
k_preemp-1645 0dNh4. 433us : task_woken_rt <-ttwu_do_wakeup
N (Need Resched) 标志被置位! 这个标志对应内核的 TIF_NEED_RESCHED 变量。它表明内核已经明确知道“有一个比当前正在运行的任务(k_preempt_noise内核线程)更重要的任务(cyclictest)在等待运行,需要尽快进行调度”。然而,由于抢占深度不为0(preempt depth=1),调度请求被暂时挂起。
第三阶段:开启抢占
k_preemp-1645 0.N.1. 3506us : preempt_count_sub <-preempt_count_sub
在注入的延迟即将结束时,内核代码调用 preempt_enable(),通过preempt_count_sub将抢占深度减少1。当抢占深度从1变为0的瞬间,内核检查到 TIF_NEED_RESCHED 标志被置位,于是立即触发调度,cyclictest终于得以执行。
整个过程可以用以下流程图概括:
[k_preempt_noise]
|
| <-- 1us: preempt_disable() [抢占关闭]
|
| (正在忙等...)
|
+---- 362us: [硬件中断发生!] -------------------------+
| |
| [IRQ Context] |
| hrtimer_wakeup -> cyclictest |
| 设置 Need_Resched 标志 (N) |
| (虽然想调度,但看到抢占关闭) |
| |
+---- 1002us: [中断返回] -----------------------------+
|
| (继续忙等... N标志一直亮着)
|
| <-- 3505us: preempt_enable() [抢占打开]
v
[终于发生 Context Switch -> cyclictest]
通过 Ftrace 对这类问题进行定位和分析,是深入理解内核调度行为的绝佳途径。更多关于系统级调试和性能剖析的技巧,可以在专注于 网络与系统 的技术社区中找到深入讨论。
场景四:硬件/固件“黑洞”
最后一种场景被称为“硬件黑洞”,在ARM64架构中尤为典型。当Linux内核(EL1)通过hvc指令陷入虚拟化层(EL2)或通过smc指令陷入安全世界(EL3)时,CPU的执行权便完全交给了底层固件或Hypervisor。
此时,Linux内核的运行被完全冻结——时钟中断得不到响应、调度器停止工作、甚至Ftrace也无法记录任何事件。从trace日志看,会出现一段诡异的空白,相邻两条记录的时间戳发生巨大的“跳跃”。
[ 正常 Linux 内核执行 (处于 EL1 层级) ]
(Trace Timestamp: T_point_A, 例如 100.000000)
|
| (内核运行中,一切正常,Ftrace 持续记录)
v
[ 触发点事件 ] (例如:需要调用安全服务或虚拟化功能)
|
(内核执行陷落指令) -> [ 执行 SMC (陷入 EL3) 或 HVC (陷入 EL2) 指令 ]
|
v
/---------------------------------------------------------------------\
| *** 进入硬件黑洞 (Entering the Hardware Black Hole) *** |
| [ CPU 执行权移交给固件 (ATF) 或 Hypervisor ] |
\---------------------------------------------------------------------/
|
v
+=========================================================================+
| *** 操作系统不可见区域 (OS Invisible Region) *** |
| |
| [ Linux 内核状态 (EL1) ]: |
| >> 完全冻结 (Frozen)。 |
| >> 时钟中断无法响应 (Timer Interrupts Blocked)。 |
| >> 调度器停滞。 |
| >> Ftrace 无法记录任何数据 (Trace is SILENT)。 |
| |
| ..................................................................... |
| . . |
| . [ 硬件真实状态 (Physical CPU at EL2/EL3) ] . |
| . >> CPU 正在高负荷执行固件或 Hypervisor 代码。 . |
| . >> 物理时钟仍在持续走动。 . |
| . >> (此处可能耗时极长,例如数毫秒甚至更久) . |
| . . |
| ..................................................................... |
| |
| (这段时间在 Trace 文件中表现为一段“空白”) |
+=========================================================================+
|
v
/---------------------------------------------------------------------\
| *** 离开硬件黑洞 (Exiting the Black Hole) *** |
| [ 固件/Hypervisor 执行完毕,执行 ERET 指令返回 Linux ] |
\---------------------------------------------------------------------/
|
v
[ Linux 内核恢复运行 (回到 EL1 层级) ]
(Trace Timestamp: T_point_B, 例如 100.005000)
|
v
[ 现象确认:诡异的时间跳变 (Time Skip Observed) ]
>> 紧邻的两条 Trace 记录之间出现了巨大的时间断层。
>> 延迟 = T_point_B - T_point_A = 5ms (而中间无任何记录)
如何排查硬件黑洞?
Linux内核提供了一个专门工具 hwlatdetect(包含在rt-tests包中,需启用内核配置CONFIG_HWLAT_TRACER)。它的原理简单粗暴:派一个内核线程高频率轮询CPU的时间戳计数器(TSC或类似机制),如果发现两次读取之间的时间差远超预期(例如,远超轮询间隔+可能的微小抖动),就判定CPU执行流曾被“偷走”。
# 运行检测 (持续10分钟,阈值设为10微秒)
sudo hwlatdetect --duration=10m --threshold=10
如果 hwlatdetect 报告了高延迟,而使用Ftrace的irqsoff、preemptoff等tracer却抓不到任何异常,那么基本可以实锤是硬件或固件层面的“黑洞”(如ATF、TrustZone服务调用耗时过长,或总线竞争等)。
总结与通用排查流程
通过以上四种场景的复现与分析,我们可以看到Linux实时延迟问题的根源主要集中于:硬中断/关中断、调度延迟、关抢占以及硬件黑洞。在实际调试中,Ftrace是我们最强大的武器。通过组合使用function_graph、irqsoff、preemptoff等追踪器,并仔细分析trace日志中的关键标志位,我们可以一步步逼近问题的真相。
一个通用的排查思路是分两个阶段审视延迟:
[上一次唤醒] --- (经过 1ms 周期) ---> [理论唤醒点 T_expected]
|
| <--- 盲区:阶段二 (Pre-Wakeup)
| 这里发生 “干扰”
| (硬中断/关中断/硬件黑洞)
|
v
[实际唤醒 sched_wakeup]
|
| <--- 明区:阶段一 (Post-Wakeup)
| 这里发生 “拥堵”
| (高优先级压制/关抢占)
|
v
[实际运行 sched_switch]
我们可以通过一个简单的脚本,在怀疑的CPU上开启最基础的事件追踪,为分析抓取第一手信息:
cd /sys/kernel/debug/tracing
echo 0 > tracing_on
echo nop > current_tracer
echo 1 > tracing_cpumask # 只抓取cpu0上的信息
echo 1 > events/sched/sched_switch/enable
echo 1 > events/sched/sched_wakeup/enable
echo 1 > events/irq/enable
echo 1 > events/timer/enable
echo 1 > tracing_on
实时性优化没有银弹,但掌握一套科学的方法论至关重要。从盲目猜测到利用 Ftrace 等工具进行精准定位,这不仅是技术能力的提升,更是工程思维方式的转变。希望这套从实践中总结的“抓鬼”指南,能帮助你在面对令人头疼的毫秒级延迟时,做到心中有谱,手下有术。在 云栈社区 等技术论坛中,与更多开发者交流类似的内核调试经验,往往能碰撞出新的解决思路。