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 EXAMPLE
  34 =======
  35
  36 In the example below, the *timerlat* tracer is set to capture the stack trace at
  37 the IRQ handler, printing it to the buffer if the *Thread* timer latency is
  38 higher than *30 us*. It is also set to stop the session if a *Thread* timer
  39 latency higher than *30 us* is hit. Finally, it is set to save the trace
  40 buffer if the stop condition is hit::
  41
  42   [root@alien ~]# rtla timerlat top -s 30 -t 30 -T
  43                    Timer Latency
  44     0 00:00:59   |          IRQ Timer Latency (us)        |         Thread Timer Latency (us)
  45   CPU COUNT      |      cur       min       avg       max |      cur       min       avg       max
  46     0 #58634     |        1         0         1        10 |       11         2        10        23
  47     1 #58634     |        1         0         1         9 |       12         2         9        23
  48     2 #58634     |        0         0         1        11 |       10         2         9        23
  49     3 #58634     |        1         0         1        11 |       11         2         9        24
  50     4 #58634     |        1         0         1        10 |       11         2         9        26
  51     5 #58634     |        1         0         1         8 |       10         2         9        25
  52     6 #58634     |       12         0         1        12 |       30         2        10        30 <--- CPU with spike
  53     7 #58634     |        1         0         1         9 |       11         2         9        23
  54     8 #58633     |        1         0         1         9 |       11         2         9        26
  55     9 #58633     |        1         0         1         9 |       10         2         9        26
  56    10 #58633     |        1         0         1        13 |       11         2         9        28
  57    11 #58633     |        1         0         1        13 |       12         2         9        24
  58    12 #58633     |        1         0         1         8 |       10         2         9        23
  59    13 #58633     |        1         0         1        10 |       10         2         9        22
  60    14 #58633     |        1         0         1        18 |       12         2         9        27
  61    15 #58633     |        1         0         1        10 |       11         2         9        28
  62    16 #58633     |        0         0         1        11 |        7         2         9        26
  63    17 #58633     |        1         0         1        13 |       10         2         9        24
  64    18 #58633     |        1         0         1         9 |       13         2         9        22
  65    19 #58633     |        1         0         1        10 |       11         2         9        23
  66    20 #58633     |        1         0         1        12 |       11         2         9        28
  67    21 #58633     |        1         0         1        14 |       11         2         9        24
  68    22 #58633     |        1         0         1         8 |       11         2         9        22
  69    23 #58633     |        1         0         1        10 |       11         2         9        27
  70   timerlat hit stop tracing
  71   saving trace to timerlat_trace.txt
  72   [root@alien bristot]# tail -60 timerlat_trace.txt
  73   [...]
  74       timerlat/5-79755   [005] .......   426.271226: #58634 context thread timer_latency     10823 ns
  75               sh-109404  [006] dnLh213   426.271247: #58634 context    irq timer_latency     12505 ns
  76               sh-109404  [006] dNLh313   426.271258: irq_noise: local_timer:236 start 426.271245463 duration 12553 ns
  77               sh-109404  [006] d...313   426.271263: thread_noise:       sh:109404 start 426.271245853 duration 4769 ns
  78       timerlat/6-79756   [006] .......   426.271264: #58634 context thread timer_latency     30328 ns
  79       timerlat/6-79756   [006] ....1..   426.271265: <stack trace>
  80   => timerlat_irq
  81   => __hrtimer_run_queues
  82   => hrtimer_interrupt
  83   => __sysvec_apic_timer_interrupt
  84   => sysvec_apic_timer_interrupt
  85   => asm_sysvec_apic_timer_interrupt
  86   => _raw_spin_unlock_irqrestore                        <---- spinlock that disabled interrupt.
  87   => try_to_wake_up
  88   => autoremove_wake_function
  89   => __wake_up_common
  90   => __wake_up_common_lock
  91   => ep_poll_callback
  92   => __wake_up_common
  93   => __wake_up_common_lock
  94   => fsnotify_add_event
  95   => inotify_handle_inode_event
  96   => fsnotify
  97   => __fsnotify_parent
  98   => __fput
  99   => task_work_run
 100   => exit_to_user_mode_prepare
 101   => syscall_exit_to_user_mode
 102   => do_syscall_64
 103   => entry_SYSCALL_64_after_hwframe
 104   => 0x7265000001378c
 105   => 0x10000cea7
 106   => 0x25a00000204a
 107   => 0x12e302d00000000
 108   => 0x19b51010901b6
 109   => 0x283ce00726500
 110   => 0x61ea308872
 111   => 0x00000fe3
 112             bash-109109  [007] d..h...   426.271265: #58634 context    irq timer_latency      1211 ns
 113       timerlat/6-79756   [006] .......   426.271267: timerlat_main: stop tracing hit on cpu 6
 114
 115 In the trace, it is possible the notice that the *IRQ* timer latency was
 116 already high, accounting *12505 ns*. The IRQ delay was caused by the
 117 *bash-109109* process that disabled IRQs in the wake-up path
 118 (*_try_to_wake_up()* function). The duration of the IRQ handler that woke
 119 up the timerlat thread, informed with the **osnoise:irq_noise** event, was
 120 also high and added more *12553 ns* to the Thread latency. Finally, the
 121 **osnoise:thread_noise** added by the currently running thread (including
 122 the scheduling overhead) added more *4769 ns*. Summing up these values,
 123 the *Thread* timer latency accounted for *30328 ns*.
 124
 125 The primary reason for this high value is the wake-up path that was hit
 126 twice during this case: when the *bash-109109* was waking up a thread
 127 and then when the *timerlat* thread was awakened. This information can
 128 then be used as the starting point of a more fine-grained analysis.
 129
 130 Note that **rtla timerlat** was dispatched without changing *timerlat* tracer
 131 threads' priority. That is generally not needed because these threads hava
 132 priority *FIFO:95* by default, which is a common priority used by real-time
 133 kernel developers to analyze scheduling delays.
 134
 135 SEE ALSO
 136 --------
 137 **rtla-timerlat**\(1), **rtla-timerlat-hist**\(1)
 138
 139 *timerlat* tracer documentation: <https://www.kernel.org/doc/html/latest/trace/timerlat-tracer.html>
 140
 141 AUTHOR
 142 ------
 143 Written by Daniel Bristot de Oliveira <bristot@kernel.org>
 144
 145 .. include:: common_appendix.rst