Documentation/tools/rtla/rtla-timerlat-top.rst

   1 ====================
   2 rtla-timerlat-top
   3 ====================
   4 -------------------------------------------
   5 Measures the operating system timer latency
   6 -------------------------------------------
   7
   8 :Manual section: 1
   9
  10 SYNOPSIS
  11 ========
  12 **rtla timerlat top** [*OPTIONS*] ...
  13
  14 DESCRIPTION
  15 ===========
  16
  17 .. include:: common_timerlat_description.rst
  18
  19 The **rtla timerlat top** displays a summary of the periodic output
  20 from the *timerlat* tracer. It also provides information for each
  21 operating system noise via the **osnoise:** tracepoints that can be
  22 seem with the option **-T**.
  23
  24 OPTIONS
  25 =======
  26
  27 .. include:: common_timerlat_options.rst
  28
  29 .. include:: common_top_options.rst
  30
  31 .. include:: common_options.rst
  32
  33 .. include:: common_timerlat_aa.rst
  34
  35 **--aa-only** *us*
  36
  37         Set stop tracing conditions and run without collecting and displaying statistics.
  38         Print the auto-analysis if the system hits the stop tracing condition. This option
  39         is useful to reduce rtla timerlat CPU, enabling the debug without the overhead of
  40         collecting the statistics.
  41
  42 EXAMPLE
  43 =======
  44
  45 In the example below, the timerlat tracer is dispatched in cpus *1-23* in the
  46 automatic trace mode, instructing the tracer to stop if a *40 us* latency or
  47 higher is found::
  48
  49   # timerlat -a 40 -c 1-23 -q
  50                                      Timer Latency
  51     0 00:00:12   |          IRQ Timer Latency (us)        |         Thread Timer Latency (us)
  52   CPU COUNT      |      cur       min       avg       max |      cur       min       avg       max
  53     1 #12322     |        0         0         1        15 |       10         3         9        31
  54     2 #12322     |        3         0         1        12 |       10         3         9        23
  55     3 #12322     |        1         0         1        21 |        8         2         8        34
  56     4 #12322     |        1         0         1        17 |       10         2        11        33
  57     5 #12322     |        0         0         1        12 |        8         3         8        25
  58     6 #12322     |        1         0         1        14 |       16         3        11        35
  59     7 #12322     |        0         0         1        14 |        9         2         8        29
  60     8 #12322     |        1         0         1        22 |        9         3         9        34
  61     9 #12322     |        0         0         1        14 |        8         2         8        24
  62    10 #12322     |        1         0         0        12 |        9         3         8        24
  63    11 #12322     |        0         0         0        15 |        6         2         7        29
  64    12 #12321     |        1         0         0        13 |        5         3         8        23
  65    13 #12319     |        0         0         1        14 |        9         3         9        26
  66    14 #12321     |        1         0         0        13 |        6         2         8        24
  67    15 #12321     |        1         0         1        15 |       12         3        11        27
  68    16 #12318     |        0         0         1        13 |        7         3        10        24
  69    17 #12319     |        0         0         1        13 |       11         3         9        25
  70    18 #12318     |        0         0         0        12 |        8         2         8        20
  71    19 #12319     |        0         0         1        18 |       10         2         9        28
  72    20 #12317     |        0         0         0        20 |        9         3         8        34
  73    21 #12318     |        0         0         0        13 |        8         3         8        28
  74    22 #12319     |        0         0         1        11 |        8         3        10        22
  75    23 #12320     |       28         0         1        28 |       41         3        11        41
  76   rtla timerlat hit stop tracing
  77   ## CPU 23 hit stop tracing, analyzing it ##
  78   IRQ handler delay:                                        27.49 us (65.52 %)
  79   IRQ latency:                                              28.13 us
  80   Timerlat IRQ duration:                                     9.59 us (22.85 %)
  81   Blocking thread:                                           3.79 us (9.03 %)
  82                          objtool:49256                       3.79 us
  83     Blocking thread stacktrace
  84                 -> timerlat_irq
  85                 -> __hrtimer_run_queues
  86                 -> hrtimer_interrupt
  87                 -> __sysvec_apic_timer_interrupt
  88                 -> sysvec_apic_timer_interrupt
  89                 -> asm_sysvec_apic_timer_interrupt
  90                 -> _raw_spin_unlock_irqrestore
  91                 -> cgroup_rstat_flush_locked
  92                 -> cgroup_rstat_flush_irqsafe
  93                 -> mem_cgroup_flush_stats
  94                 -> mem_cgroup_wb_stats
  95                 -> balance_dirty_pages
  96                 -> balance_dirty_pages_ratelimited_flags
  97                 -> btrfs_buffered_write
  98                 -> btrfs_do_write_iter
  99                 -> vfs_write
 100                 -> __x64_sys_pwrite64
 101                 -> do_syscall_64
 102                 -> entry_SYSCALL_64_after_hwframe
 103   ------------------------------------------------------------------------
 104     Thread latency:                                          41.96 us (100%)
 105
 106   The system has exit from idle latency!
 107     Max timerlat IRQ latency from idle: 17.48 us in cpu 4
 108   Saving trace to timerlat_trace.txt
 109
 110 In this case, the major factor was the delay suffered by the *IRQ handler*
 111 that handles **timerlat** wakeup: *65.52%*. This can be caused by the
 112 current thread masking interrupts, which can be seen in the blocking
 113 thread stacktrace: the current thread (*objtool:49256*) disabled interrupts
 114 via *raw spin lock* operations inside mem cgroup, while doing write
 115 syscall in a btrfs file system.
 116
 117 The raw trace is saved in the **timerlat_trace.txt** file for further analysis.
 118
 119 Note that **rtla timerlat** was dispatched without changing *timerlat* tracer
 120 threads' priority. That is generally not needed because these threads have
 121 priority *FIFO:95* by default, which is a common priority used by real-time
 122 kernel developers to analyze scheduling delays.
 123
 124 SEE ALSO
 125 --------
 126 **rtla-timerlat**\(1), **rtla-timerlat-hist**\(1)
 127
 128 *timerlat* tracer documentation: <https://www.kernel.org/doc/html/latest/trace/timerlat-tracer.html>
 129
 130 AUTHOR
 131 ------
 132 Written by Daniel Bristot de Oliveira <bristot@kernel.org>
 133
 134 .. include:: common_appendix.rst