rtla-timerlat-top.rst

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