Corrector: TinyCorrect v0.2-rc2 - [tables]
Author: 王杰迅 wangjiexun@foxmail.com
Date: 2024/09/05
Revisor: falcon falcon@tinylab.org
Project: RISC-V Linux 内核剖析
Sponsor: PLCT Lab, ISCAS
rtla timerlat 介绍（二）：延迟测试原理
前言
上一篇文章中介绍了 rtla timerlat 的基本功能、编译过程和使用方法，本篇将介绍 rtla timerlat 测试延迟的原理和延迟分析结果中各数值的具体含义。
cyclictest 原理
前文说过，传统的 Linux 调度延迟测试工具 cyclictest 只能测试出整体延迟，无法提供更详细的延迟分析，因为其通过黑盒方法来测量延迟。如图所示，cyclictest 创建一个或多个高优先级的循环任务，每当循环开始时，它会设置一个定时器，然后进入睡眠状态等待定时器。当定时器触发时，线程被唤醒并读取当前时间。当前时间与预定唤醒时间的差值就是一份调度延迟样本。
通过收集这些周期时间数据，cyclictest 可以统计出最小、最大以及平均延迟时间，帮助分析系统的响应时间和稳定性。
rtla timerlat 原理
不同于仅仅运行在用户态的 cyclictest，rtla timerlat 由内核态和用户态的两个部分组成。运行在内核态的为 timerlat tracer，负责进行延迟数据的测试和收集。运行在用户态的为 rtla 应用程序，负责数据的统计与展示。
启用 timerlat tracer 时，会创建一个统计延迟的测试线程，其主要工作与 cyclictest 基本一致：循环地设置定时器、进入睡眠状态等待唤醒、唤醒后计算延迟。然而由于其运行在内核态而非用户态，因此可以获得更详细的延迟数据，如进入中断处理程序的延迟（如下图的 IRQ Latency）、唤醒测试线程的最终延迟（Thread Latency）。
timerlat tracer
开启 timerlat tracer 的命令如下：
# mount -t tracefs none /sys/kernel/tracing
# echo timerlat > /sys/kernel/tracing/current_tracer
# echo 1 > /sys/kernel/tracing/tracing_on
开启 timerlat tracer 后，内核会执行 /kernel/trace/trace_osnoise.c 中的 timerlat_main 函数，其主要工作为设置定时器定期唤醒自己、自己进入休眠、在被唤醒后计算调度延迟。在设置定时器时使用了高分辨率时钟，以提高精度：
// /kernel/trace/trace_osnoise.c:1891
hrtimer_init(&tlat->timer, CLOCK_MONOTONIC, HRTIMER_MODE_ABS_PINNED_HARD);
tlat->timer.function = timerlat_irq;
tlat->kthread = current;
...
wait_next_period(tlat);
启动定时器并进入休眠的代码位于 wait_next_period 函数中，next_abs_period 变量记录了定时器到时的时间：
// /kernel/trace/trace_osnoise.c:1830
static int wait_next_period(struct timerlat_variables *tlat)
{
ktime_t next_abs_period, now;
u64 rel_period = osnoise_data.timerlat_period * 1000;
now = hrtimer_cb_get_time(&tlat->timer);
next_abs_period = ns_to_ktime(tlat->abs_period + rel_period);
...
set_current_state(TASK_INTERRUPTIBLE);
hrtimer_start(&tlat->timer, next_abs_period, HRTIMER_MODE_ABS_PINNED_HARD);
schedule();
return 1;
}
每次被唤醒后，会计算当前时间与预定唤醒时间的差值，作为一个延迟样本，即 diff 变量的值。
// /kernel/trace/trace_osnoise.c:1906
now = ktime_to_ns(hrtimer_cb_get_time(&tlat->timer));
diff = now - tlat->abs_period;
s.seqnum = tlat->count;
s.timer_latency = diff;
s.context = THREAD_CONTEXT;
trace_timerlat_sample(&s);
在这里计算出的 diff 值也就是使用 rtla timerlat 测试时显示的 Thread Latency。
定时器到期后，执行的函数为 timerlat_irq，该函数运行在中断处理程序中，主要工作为：计算此时的延迟，并唤醒上面介绍的 timerlat_main 线程。在这里计算延迟的代码和上面计算 Thread Latency 的代码基本一致，只是需要将 s.context = THREAD_CONTEXT; 改为 s.context = IRQ_CONTEXT;，标志当前上下文为中断上下文，而非线程上下文。
此处测试得到的延迟也就是使用 rtla timerlat 测试时显示的 IRQ latency。
代码运行的流程图的如下所示：
rtla 应用程序
内核收集测试数据后，rtla 应用程序是如何获取的呢？其实是通过 libtraceevent 库实现的，当内核收集测试数据时，会触发特定的 trace event，进而调用 rtla 中注册好的回调函数，进行测试数据的进一步处理。
rtla 应用程序初始化时会给各种 trace event 注册对应的处理函数：
// /tools/tracing/rtla/src/timerlat_aa.c:937
static int timerlat_aa_register_events(struct osnoise_tool *tool, int dump_tasks)
{
int retval;
tep_register_event_handler(tool->trace.tep, -1, "ftrace", "timerlat",
timerlat_aa_handler, tool);
...
如上述代码则注册了针对 ftrace timerlat 这个 trace event 的回调函数 timerlat_aa_handler。当 ftrace timerlat 事件发生时，也就是在 timerlat tracer 中测试了一次 Thread Latency 或 IRQ Latency 时，timerlat_aa_handler 函数则会被调用：
// /tools/tracing/rtla/src/timerlat_aa.c:241
static int timerlat_aa_handler(struct trace_seq *s, struct tep_record *record,
struct tep_event *event, void *context)
{
...
tep_get_field_val(s, event, "context", record, &thread, 1);
if (!thread)
return timerlat_aa_irq_latency(taa_data, s, record, event);
else
return timerlat_aa_thread_latency(taa_data, s, record, event);
}
上述代码中的 tep_get_field_val 函数是获取内核测试数据的关键函数，在这里获取的变量为 "context"，即我们在测试数据时记录的上下文信息（线程上下文或中断上下文），随后根据该信息进行进一步的处理。更多 tep_get_field_val 的使用如下所示：
// /tools/tracing/rtla/src/timerlat_aa.c:216
static int timerlat_aa_thread_latency(struct timerlat_aa_data *taa_data,
struct trace_seq *s, struct tep_record *record,
struct tep_event *event)
{
...
tep_get_field_val(s, event, "timer_latency", record, &taa_data->tlat_thread_latency, 1);
tep_get_field_val(s, event, "seqnum", record, &taa_data->tlat_thread_seqnum, 1);
上述代码获取的变量 "timer_latency" 和 "seqnum" 与我们测试数据时记录的变量名一一对应。这样 rtla 应用程序就获得了从内核态收集到的延迟数据，可以进一步进行数据统计和结果展示。
延迟分析
一个典型的 rtla timerlat 延迟测试分析结果如下所示：
# rtla timerlat top -T 500 -s 500 -t -k -P f:95
0 00:00:01 | IRQ Timer Latency (us) | Thread Timer Latency (us)
CPU COUNT | cur min avg max | cur min avg max
| 0 #1015 | 236 37 42 236 | 594 213 227 594 |
|----------------|-----------------------------------|-----------------------------------|
| ALL #1015 e0 | 37 42 236 | 213 227 594 |
rtla timerlat hit stop tracing
## CPU 0 hit stop tracing, analyzing it ##
IRQ handler delay: 157.68 us (26.52 %)
IRQ latency: 236.24 us
Timerlat IRQ duration: 242.08 us (40.72 %)
Blocking thread: 101.84 us (17.13 %)
rtla:145 101.84 us
Blocking thread stack trace
-> stack_trace_save
-> timerlat_save_stack.constprop.0
-> timerlat_irq
-> trace_event_buffer_commit
-> __hrtimer_run_queues.constprop.0
-> hrtimer_interrupt
-> riscv_timer_interrupt
-> handle_percpu_devid_irq
-> ring_buffer_map
-> handle_irq_desc
-> riscv_intc_irq
-> handle_riscv_irq
------------------------------------------------------------------------
Thread latency: 594.48 us (100%)
该结果提供了多个延迟数据，如 IRQ handler delay、IRQ latency、Timerlat IRQ、Blocking thread、Thread latency。其中 IRQ latency 和 Thread latency 的具体含义已经在上文介绍过，想要弄清楚其他延迟的具体含义，只需要找到其对应的 trace event。
IRQ handler delay
该延迟由 struct timerlat_aa_data 结构体中的 timer_irq_start_delay 变量存储，修改该变量的函数为 timerlat_aa_irq_handler，于是顺藤摸瓜发现其对应的 trace event 为 irq_handler_exit，其代码位置如下所示：
// linux/kernel/irq/chip.c:924
void handle_percpu_devid_irq(struct irq_desc *desc)
{
...
trace_irq_handler_entry(irq, action);
res = action->handler(irq, raw_cpu_ptr(action->percpu_dev_id));
trace_irq_handler_exit(irq, action, res);
由上可知，IRQ handler delay 测试的是刚刚进入中断处理程序的延迟，而此时还没有进入定时器中断处理程序。因此，IRQ latency 在数值上应包含 IRQ handler delay。
下面两个数值将直接给出结论，感兴趣的同学可以根据上述思路逐步分析。
Timerlat IRQ duration
该数值为：上面代码中 trace_irq_handler_entry 和 trace_irq_handler_exit 之间的耗时，也就是整个中断处理程序的总耗时。
Blocking thread
在中断处理程序结束后，如果没有直接调度 timerlat_main 函数，而是仍在运行其他线程，则该线程称为阻塞线程（Blocking thread）。延迟分析中的 Blocking thread 数值指的则是阻塞线程从“被调度进来”到“被调度出去”的间隔时间，这是通过 sched_switch 这个 trace event 获取的。该数值的下面一行列出了阻塞线程的线程名与线程号。
各延迟具体含义如下图所示：
其中 IRQ Latency 和 Thread Latency 也就是测试结果中的 IRQ Timer Latency 与 Thread Timer Latency.
各延迟对应的 trace point 位置如下表所示：
| 延迟 | 文件 | 函数及行号 |
|---|---|---|
| IRQ Handler delay | kernel/irq/chip.c | handle_percpu_devid_irq:941 |
| IRQ Latency | kernel/trace/trace_osnoise.c | timerlat_irq:1801 |
| Timerlat IRQ duration | kernel/irq/chip.c | handle_percpu_devid_irq:941-944 |
| Blocking thread latency | /kernel/sched/core.c | __schedule:6526 |
| Thread Latency | kernel/trace/trace_osnoise.c | timerlat_main:1921 |
总结
本文通过与 cyclictest 进行比较介绍了 rtla timerlat 测试延迟的原理，通过简要的分析总结了 rtla 的输出结果中各数值的具体含义。更深刻地理解测试工具有助于更准确地分析系统延迟问题并进行优化。
参考资料
Linux scheduling latency debug and analysis libtraceevent(3) — Linux manual page timerlat tracer 源代码 rtla 源代码
首发地址：https://tinylab.org/linux-rtla-2
技术服务：https://tinylab.org/ruma.tech
