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 内核线程，该线程在每次激活时打印两行。第一个是在线程激活之前在 *hardirq* 上下文中观察到的*定时器延迟*。第二个是线程观察到的*定时器延迟*。 ACTIVATION ID 字段用于将 *irq* 执行与其各自的 *thread* 执行相关联。

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

跟踪器选项¶

timerlat 跟踪器构建在 osnoise 跟踪器的基础上。因此，其配置也在 osnoise/ config 目录中完成。 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 微秒，这可能指向长时间的 IRQ 禁用段（请参阅 IRQ 堆栈跟踪部分）。然后，唤醒 timerlat 线程的定时器中断花费了 7597 纳秒，qxl:21 设备 IRQ 花费了 7139 纳秒。最后，cc1 线程噪声在上下文切换之前花费了 9909 纳秒的时间。这些证据对于开发人员使用其他跟踪方法来找出如何调试和优化系统很有用。

值得一提的是 osnoise: 事件报告的 *duration* 值是*净*值。例如，thread_noise 不包括 IRQ 执行导致的开销持续时间（实际上占 12736 纳秒）。但是 timerlat 跟踪器（timerlat_latency）报告的值是*总*值。

下面的图示说明了一个 CPU 时间线以及 timerlat 跟踪器如何在顶部观察它，而 osnoise: 事件在底部观察它。时间线中的每个“-”表示大约 1 微秒，时间移动 ==>

    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 堆栈跟踪¶

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

      [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

在这种情况下，可以发现线程对 *timer latency* 的贡献最大，并且在 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 延迟，并唤醒在读取中等待的线程。该线程将被调度并通过跟踪器报告线程延迟 - 就像内核线程一样。

与内核 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 堆栈跟踪¶

用户空间接口¶