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