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 堆疊跟蹤¶

使用者空間介面¶