1====================
2rtla-timerlat-top
3====================
4-------------------------------------------
5Measures the operating system timer latency
6-------------------------------------------
7
8:Manual section: 1
9
10SYNOPSIS
11========
12**rtla timerlat top** [*OPTIONS*] ...
13
14DESCRIPTION
15===========
16
17.. include:: common_timerlat_description.rst
18
19The **rtla timerlat top** displays a summary of the periodic output
20from the *timerlat* tracer. It also provides information for each
21operating system noise via the **osnoise:** tracepoints that can be
22seem with the option **-T**.
23
24OPTIONS
25=======
26
27.. include:: common_timerlat_options.rst
28
29.. include:: common_top_options.rst
30
31.. include:: common_options.rst
32
33EXAMPLE
34=======
35
36In the example below, the *timerlat* tracer is set to capture the stack trace at
37the IRQ handler, printing it to the buffer if the *Thread* timer latency is
38higher than *30 us*. It is also set to stop the session if a *Thread* timer
39latency higher than *30 us* is hit. Finally, it is set to save the trace
40buffer 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
115In the trace, it is possible the notice that the *IRQ* timer latency was
116already 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
119up the timerlat thread, informed with the **osnoise:irq_noise** event, was
120also high and added more *12553 ns* to the Thread latency. Finally, the
121**osnoise:thread_noise** added by the currently running thread (including
122the scheduling overhead) added more *4769 ns*. Summing up these values,
123the *Thread* timer latency accounted for *30328 ns*.
124
125The primary reason for this high value is the wake-up path that was hit
126twice during this case: when the *bash-109109* was waking up a thread
127and then when the *timerlat* thread was awakened. This information can
128then be used as the starting point of a more fine-grained analysis.
129
130Note that **rtla timerlat** was dispatched without changing *timerlat* tracer
131threads' priority. That is generally not needed because these threads hava
132priority *FIFO:95* by default, which is a common priority used by real-time
133kernel developers to analyze scheduling delays.
134
135SEE 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
141AUTHOR
142------
143Written by Daniel Bristot de Oliveira <bristot@kernel.org>
144
145.. include:: common_appendix.rst
146