Linux内核实时机制x - 实时性之中断响应优化
在基于PREEMPT_RT的Linux实时系统，社区开发了一套测试工具集rt-test，用于测试实时系统的各种指标。
其中重点关注的指标有：
- 中断响应时间 Cyclitest
- 信号混洗时间 sigwaittest
- 死锁解除时间 ptsematest
- 消息传递时间 pmqtest
1 Cyclitest 工具
- cyclictest 是Linux上非常流行、常见的实时性测试工具，它通过使用高精度定时器来测量两个时间点的延时.
1.1 安装Cyclitest
git clone git://git.kernel.org/pub/scm/utils/rt-tests/rt-tests.git
cd rt-tests
git checkout stable/v1.0
make all
make install ~/0-code/5.15$ git clone git://git.kernel.org/pub/scm/utils/rt-tests/rt-tests.git
正克隆到 'rt-tests'...
remote: Enumerating objects: 5534, done.
remote: Counting objects: 100% (7/7), done.
remote: Compressing objects: 100% (7/7), done.
remote: Total 5534 (delta 1), reused 0 (delta 0), pack-reused 5527
接收对象中: 100% (5534/5534), 1.08 MiB | 654.00 KiB/s, 完成.
处理 delta 中: 100% (3569/3569), 完成.0-code/5.15/rt-tests# ls
bld hackbench MAINTAINERS pip_stress ptsematest rt.sh signaltest svsematest
COPYING histogram Makefile pi_stress README.markdown scripts sigwaittest
cyclictest hwlatdetect output-kong-nort pmqtest rt-migrate-test sendme src
- 实测图
2 非实时内核中断响应测试
0-code/5.15/rt-tests# ./cyclictest -p 90 -m -c 0 -i 1000 -l 1000 -h 100 -t 4
# /dev/cpu_dma_latency set to 0us
policy: fifo: loadavg: 1.04 4.48 6.57 2/1628 385205T: 0 (385170) P:90 I:1000 C: 1000 Min: 3 Act: 3 Avg: 7 Max: 252
T: 1 (385171) P:90 I:1000 C: 999 Min: 3 Act: 5 Avg: 3 Max: 18
T: 2 (385172) P:90 I:1000 C: 999 Min: 3 Act: 4 Avg: 3 Max: 20
T: 3 (385173) P:90 I:1000 C: 999 Min: 3 Act: 4 Avg: 6 Max: 363
3 实时内核中断响应测试
0-code/5.15/rt-tests# trace-cmd start -e all;./cyclictest -p 90 -m -n -c 0 -t 4 -D5m -b 50 --tracemark
# /dev/cpu_dma_latency set to 0us
INFO: debugfs mountpoint: /sys/kernel/debug/tracing/
policy: fifo: loadavg: 6.17 15.98 18.12 2/1152 1691773T: 0 (1691490) P:90 I:1000 C: 31633 Min: 7 Act: 14 Avg: 15 Max: 36
T: 1 (1691491) P:90 I:1500 C: 21049 Min: 10 Act: 15 Avg: 15 Max: 28
T: 2 (1691492) P:90 I:2000 C: 15757 Min: 7 Act: 14 Avg: 15 Max: 40
T: 3 (1691493) P:90 I:2500 C: 12582 Min: 7 Act: 25 Avg: 15 Max: 40
# Thread Ids: 1691490 1691491 1691492 1691493
# Break thread: 1691493
# Break value: 56Ftrace抓取日志
0-code/5.15/rt-tests# trace-cmd extract
CPU 0: 1077425 events lost
CPU 1: 1512931 events lost
CPU 2: 764575 events lost
CPU 3: 600860 events lost
CPU 4: 992340 events lost
CPU 5: 1030188 events lost
CPU 6: 1340854 events lost
CPU 7: 781496 events lost
CPU0 data recorded at offset=0x75a0001449984 bytes in size
CPU1 data recorded at offset=0x8bc0001449984 bytes in size
CPU2 data recorded at offset=0xa1e0001449984 bytes in size
CPU3 data recorded at offset=0xb800001449984 bytes in size
CPU4 data recorded at offset=0xce20001449984 bytes in size
CPU5 data recorded at offset=0xe440001449984 bytes in size
CPU6 data recorded at offset=0xfa60001449984 bytes in size
CPU7 data recorded at offset=0x11080001449984 bytes in size0-code/5.15/rt-tests# trace-cmd report -l > log.txt
嵌入式板卡-小系统测试结果
~/rt-tests# ./cyclictest -p98 -m -n -D3m -t5
# /dev/cpu_dma_latency set to 0us
policy: fifo: loadavg: 2.20 1.73 0.87 1/156 420T: 0 ( 414) P:98 I:1000 C: 179997 Min: 4 Act: 5 Avg: 5 Max: 9
T: 1 ( 415) P:98 I:1500 C: 119982 Min: 5 Act: 6 Avg: 5 Max: 10
T: 2 ( 416) P:98 I:2000 C: 89975 Min: 5 Act: 6 Avg: 5 Max: 8
T: 3 ( 417) P:98 I:2500 C: 71970 Min: 5 Act: 6 Avg: 5 Max: 7
T: 4 ( 418) P:98 I:3000 C: 59967 Min: 5 Act: 6 Avg: 5 Max: 8实时内核优化参数
cat /proc/osinfo
OS Type: Desktop
Kernel Version: 5.4.18-87.76
Source Version: NA
Build Time: # SMP PREEMPT_RT Thu Oct 24 05:30:26 UTC 2024
Architecture: aarch64
Online CPUs: 4
MemTotal: 8062440 KB
PageSize: 4 KB
Uptime: 220.16 Sec
Cmdline: BOOT_IMAGE=/vmlinuz-5.4.18-87.76-rt root=UUID=62db6dc4-b0d2-4beb-9e9b-c2e19006d930 ro quiet splash loglevel=0 console=tty0 resume=UUID=9fb16b7c-2e59-41d3-8de5-146708b4a8ca audit=0 security=none efi=runtime selinux=0 numa_balancing=disable nohlt tsc=reliable rcu_nocb_poll skew_tick=1 isolcpus=2-3 intel_pstate=disable nosoftlockup nohz=on nohz_full=2-3 rcu_nocbs=2-3cyclictest 的延迟时间计算分析
在 cyclictest 中，延迟时间指的是从预定的唤醒时间到实际开始执行任务之间的时间差。
关键事件分析
调度切换 (sched_switch)
- 第一个关键事件是 cyclictest:3789 线程被调度出去：
cyclicte-3789 3d..20 1691.977868: sched_switch: cyclictest:3789 [120] S ==> swapper/3:0 [120]
这个事件表明 cyclictest 线程（PID 3789）被调度出去，进入空闲状态（swapper/3 是内核的空闲线程）。
定时器到期和唤醒 (hrtimer_expire_entry, sched_waking, sched_wakeup)- 接下来，我们看到一系列与定时器相关的事件：
<idle>-0 3d.h10 1691.978278: hrtimer_expire_entry: hrtimer=0xffffffa0e6cefde0
now=1691884829406 function=hrtimer_wakeup/0x0
<idle>-0 3d.h30 1691.978278: sched_waking: comm=cyclictest pid=3791 prio=4 target_cpu=003
<idle>-0 3dNh40 1691.978279: sched_wakeup: cyclictest:3791 [4] success=1 CPU:003
这些事件表明一个高分辨率定时器（hrtimer）到期，并且触发了对 cyclictest 线程（PID 3791）的唤醒操作。
- 调度切换回 cyclictest，最后，cyclictest 线程被调度回来继续执行：
<idle>-0 3d..20 1691.978288: sched_switch: swapper/3:0 [120] R ==> cyclictest:3791 [4]
延迟时间计算
预定唤醒时间：这是由 cyclictest 设置的下一个定时器到期时间，对应于 hrtimer_expire_entry 事件的时间戳 1691.978278。
实际开始执行时间：这是 cyclictest 线程重新获得 CPU 时间并开始执行的时间点，对应于 sched_switch 事件的时间戳 1691.978288。
因此，延迟时间可以通过以下公式计算：深色版本
延迟时间 = 实际开始执行时间 - 预定唤醒时间= 1691.978288 - 1691.978278= 0.000010 秒 (或 10 微秒)
总结
在你提供的日志中，cyclictest 的延迟时间为 10 微秒。这个时间段是从定时器到期（预定唤醒时间）到 cyclictest 线程重新获得 CPU 并开始执行（实际开始执行时间）之间的时间差。通过这种方式，你可以使用 ftrace 数据来分析和理解 cyclictest 报告的延迟原因。
