Timerlat 追踪器¶

timerlat 追踪器旨在帮助抢占式内核开发人员查找实时线程唤醒延迟的根源。与 cyclictest 类似，该追踪器设置一个周期性定时器来唤醒线程。然后，线程计算一个唤醒延迟值，即当前时间与定时器预定到期的绝对时间之间的差值。timerlat 的主要目标是以某种有助于内核开发人员的方式进行追踪。

用法¶

将 ASCII 文本“timerlat”写入追踪系统的 current_tracer 文件中（通常挂载在 /sys/kernel/tracing）。

例如

[root@f32 ~]# cd /sys/kernel/tracing/
[root@f32 tracing]# echo timerlat > current_tracer

可以通过读取 trace 文件来跟踪追踪记录

[root@f32 tracing]# cat trace
# tracer: timerlat
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            || /
#                            ||||             ACTIVATION
#         TASK-PID      CPU# ||||   TIMESTAMP    ID            CONTEXT                LATENCY
#            | |         |   ||||      |         |                  |                       |
        <idle>-0       [000] d.h1    54.029328: #1     context    irq timer_latency       932 ns
         <...>-867     [000] ....    54.029339: #1     context thread timer_latency     11700 ns
        <idle>-0       [001] dNh1    54.029346: #1     context    irq timer_latency      2833 ns
         <...>-868     [001] ....    54.029353: #1     context thread timer_latency      9820 ns
        <idle>-0       [000] d.h1    54.030328: #2     context    irq timer_latency       769 ns
         <...>-867     [000] ....    54.030330: #2     context thread timer_latency      3070 ns
        <idle>-0       [001] d.h1    54.030344: #2     context    irq timer_latency       935 ns
         <...>-868     [001] ....    54.030347: #2     context thread timer_latency      4351 ns

该追踪器为每个 CPU 创建一个具有实时优先级 SCHED_FIFO:95 的内核线程，该线程在每次激活时打印两行。第一行是在线程激活之前的 hardirq 上下文中观察到的定时器延迟。第二行是由线程观察到的定时器延迟。ACTIVATION ID 字段用于将 irq 执行与其各自的 thread 执行关联起来。

irq / thread 的拆分对于澄清意外的高值来自哪个上下文非常重要。irq 上下文可能会被与硬件相关的操作（例如 SMI、NMI、IRQ）或线程屏蔽中断所延迟。一旦定时器触发，延迟也可能受到线程引起的阻塞的影响。例如，通过 preempt_disable() 推迟调度器执行、调度器执行或屏蔽中断。线程也可能受到来自其他线程和 IRQ 的干扰而延迟。

追踪器选项¶

timerlat 追踪器构建于 osnoise 追踪器之上。因此，其配置也是在 osnoise/ 配置目录中完成的。timerlat 的配置包括

cpus：timerlat 线程将在其上执行的 CPU。

timerlat_period_us：timerlat 线程的周期。

stop_tracing_us：如果 irq 上下文中的定时器延迟高于配置的值，则停止系统追踪。写入 0 会禁用此选项。

stop_tracing_total_us：如果 thread 上下文中的定时器延迟高于配置的值，则停止系统追踪。写入 0 会禁用此选项。

print_stack：保存发生 IRQ 时的栈。该栈在 thread context 事件之后打印，或者如果在 stop_tracing_us 命中时在 IRQ 处理程序中打印。

timerlat 与 osnoise¶

timerlat 还可以利用 osnoise: traceevents。例如

  [root@f32 ~]# cd /sys/kernel/tracing/
  [root@f32 tracing]# echo timerlat > current_tracer
  [root@f32 tracing]# echo 1 > events/osnoise/enable
  [root@f32 tracing]# echo 25 > osnoise/stop_tracing_total_us
  [root@f32 tracing]# tail -10 trace
       cc1-87882   [005] d..h...   548.771078: #402268 context    irq timer_latency     13585 ns
       cc1-87882   [005] dNLh1..   548.771082: irq_noise: local_timer:236 start 548.771077442 duration 7597 ns
       cc1-87882   [005] dNLh2..   548.771099: irq_noise: qxl:21 start 548.771085017 duration 7139 ns
       cc1-87882   [005] d...3..   548.771102: thread_noise:      cc1:87882 start 548.771078243 duration 9909 ns
timerlat/5-1035    [005] .......   548.771104: #402268 context thread timer_latency     39960 ns

在这种情况下，定时器延迟的根本原因不是指向单一原因，而是多个原因。首先，定时器 IRQ 被延迟了 13 us，这可能指向一个较长的 IRQ 禁用段（参见 IRQ 栈轨迹部分）。然后，唤醒 timerlat 线程的定时器中断耗时 7597 ns，qxl:21 设备 IRQ 耗时 7139 ns。最后，cc1 线程噪声在上下文切换前耗费了 9909 ns 的时间。这些证据有助于开发人员使用其他追踪方法来找出如何调试和优化系统。

值得一提的是，osnoise: events 报告的 duration 值是净值。例如，thread_noise 不包含由 IRQ 执行引起的开销持续时间（实际上占了 12736 ns）。但是由 timerlat 追踪器（timerlat_latency）报告的值是毛值。

下图展示了 CPU 时间线，以及 timerlat 追踪器如何在顶部观察它、osnoise: events 如何在底部观察它。时间线中的每个“-”大约表示 1 us，时间向右流动 ==>

    External     timer irq                   thread
     clock        latency                    latency
     event        13585 ns                   39960 ns
       |             ^                         ^
       v             |                         |
       |-------------|                         |
       |-------------+-------------------------|
                     ^                         ^
========================================================================
                  [tmr irq]  [dev irq]
[another thread...^       v..^       v.......][timerlat/ thread]  <-- CPU timeline
=========================================================================
                  |-------|  |-------|
                          |--^       v-------|
                          |          |       |
                          |          |       + thread_noise: 9909 ns
                          |          +-> irq_noise: 6139 ns
                          +-> irq_noise: 7597 ns

IRQ 栈轨迹¶

osnoise/print_stack 选项对于由于抢占或禁用 IRQ 导致线程噪声成为定时器延迟的主要因素的情况非常有用。例如

      [root@f32 tracing]# echo 500 > osnoise/stop_tracing_total_us
      [root@f32 tracing]# echo 500 > osnoise/print_stack
      [root@f32 tracing]# echo timerlat > current_tracer
      [root@f32 tracing]# tail -21 per_cpu/cpu7/trace
        insmod-1026    [007] dN.h1..   200.201948: irq_noise: local_timer:236 start 200.201939376 duration 7872 ns
        insmod-1026    [007] d..h1..   200.202587: #29800 context    irq timer_latency      1616 ns
        insmod-1026    [007] dN.h2..   200.202598: irq_noise: local_timer:236 start 200.202586162 duration 11855 ns
        insmod-1026    [007] dN.h3..   200.202947: irq_noise: local_timer:236 start 200.202939174 duration 7318 ns
        insmod-1026    [007] d...3..   200.203444: thread_noise:   insmod:1026 start 200.202586933 duration 838681 ns
    timerlat/7-1001    [007] .......   200.203445: #29800 context thread timer_latency    859978 ns
    timerlat/7-1001    [007] ....1..   200.203446: <stack trace>
=> timerlat_irq
=> __hrtimer_run_queues
=> hrtimer_interrupt
=> __sysvec_apic_timer_interrupt
=> asm_call_irq_on_stack
=> sysvec_apic_timer_interrupt
=> asm_sysvec_apic_timer_interrupt
=> delay_tsc
=> dummy_load_1ms_pd_init
=> do_one_initcall
=> do_init_module
=> __do_sys_finit_module
=> do_syscall_64
=> entry_SYSCALL_64_after_hwframe

在这种情况下，可以看到该线程对定时器延迟贡献最大，并且在 timerlat IRQ 处理程序期间保存的栈轨迹指向一个名为 dummy_load_1ms_pd_init 的函数，该函数具有以下代码（故意为之）

static int __init dummy_load_1ms_pd_init(void)
{
        preempt_disable();
        mdelay(1);
        preempt_enable();
        return 0;

}

用户空间接口¶

Timerlat 允许用户空间线程使用 timerlat 基础设施来测量调度延迟。该接口可以通过 $tracing_dir/osnoise/per_cpu/cpu$ID/timerlat_fd 内部的每个 CPU 文件描述符进行访问。

在以下条件下可以访问此接口

timerlat 追踪器已启用

osnoise 工作负载选项设置为 NO_OSNOISE_WORKLOAD

用户空间线程亲和于单个处理器

线程打开与其单个处理器关联的文件

一次只能有一个线程访问该文件

如果未满足这些条件中的任何一个，open() 系统调用将失败。打开文件描述符后，用户空间可以从中读取。

read() 系统调用将运行一段 timerlat 代码，该代码会在将来启动定时器并像常规内核线程一样等待它。

当定时器 IRQ 触发时，timerlat IRQ 将执行、报告 IRQ 延迟并唤醒在 read 中等待的线程。该线程将被调度并通过追踪器报告线程延迟 - 就像内核线程一样。

与内核中 timerlat 的区别在于，timerlat 不是重新启动定时器，而是返回到 read() 系统调用。此时，用户可以运行任何代码。

如果应用程序重新读取 timerlat 文件描述符，追踪器将报告从用户空间返回的延迟，即总延迟。如果这是工作的结束，它可以被解释为请求的响应时间。

在报告总延迟后，timerlat 将重新开始循环、启动定时器，并进入休眠状态以等待下一次激活。

如果在任何时候打破了其中一个条件（例如，线程在用户空间中发生迁移，或者 timerlat 追踪器被禁用），则将向用户空间线程发送 SIG_KILL 信号。

以下是 timerlat 的用户空间代码的基本示例

int main(void)
{
       char buffer[1024];
       int timerlat_fd;
       int retval;
       long cpu = 0;   /* place in CPU 0 */
       cpu_set_t set;

       CPU_ZERO(&set);
       CPU_SET(cpu, &set);

       if (sched_setaffinity(gettid(), sizeof(set), &set) == -1)
               return 1;

       snprintf(buffer, sizeof(buffer),
               "/sys/kernel/tracing/osnoise/per_cpu/cpu%ld/timerlat_fd",
               cpu);

       timerlat_fd = open(buffer, O_RDONLY);
       if (timerlat_fd < 0) {
               printf("error opening %s: %s\n", buffer, strerror(errno));
               exit(1);
       }

       for (;;) {
               retval = read(timerlat_fd, buffer, 1024);
               if (retval < 0)
                       break;
       }

       close(timerlat_fd);
       exit(0);
}

Linux 内核

目录

本页

Timerlat 追踪器¶

用法¶

追踪器选项¶

timerlat 与 osnoise¶

IRQ 栈轨迹¶

用户空间接口¶