Timerlat 追踪器¶

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

用法¶

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

例如

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

可以通过读取跟踪文件来跟踪

[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 上下文事件之后打印，或者如果命中 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 值是 net 值。例如，thread_noise 不包括 IRQ 执行造成的开销持续时间（实际上占用了 12736 纳秒）。但是 timerlat 追踪器报告的值（timerlat_latency）是 gross 值。

下面的图示说明了 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 堆栈跟踪¶

如果线程噪声是计时器延迟的主要因素，则 osnoise/print_stack 选项很有帮助，因为 preempt 或 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 延迟并唤醒在读取中等待的线程。该线程将被调度，并通过跟踪器报告线程延迟，就像内核线程一样。

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

用户空间接口¶