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 <<
34 <<
35 **--aa-only** *us* <<
36 <<
37 Set stop tracing conditions and run wi <<
38 Print the auto-analysis if the system <<
39 is useful to reduce rtla timerlat CPU, <<
40 collecting the statistics. <<
41 <<
42 EXAMPLE 33 EXAMPLE
43 ======= 34 =======
44 35
45 In the example below, the timerlat tracer is d !! 36 In the example below, the *timerlat* tracer is set to capture the stack trace at
46 automatic trace mode, instructing the tracer t !! 37 the IRQ handler, printing it to the buffer if the *Thread* timer latency is
47 higher is found:: !! 38 higher than *30 us*. It is also set to stop the session if a *Thread* timer
48 !! 39 latency higher than *30 us* is hit. Finally, it is set to save the trace
49 # timerlat -a 40 -c 1-23 -q !! 40 buffer if the stop condition is hit::
50 Timer Lat !! 41
51 0 00:00:12 | IRQ Timer Latency !! 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)
52 CPU COUNT | cur min av 45 CPU COUNT | cur min avg max | cur min avg max
53 1 #12322 | 0 0 !! 46 0 #58634 | 1 0 1 10 | 11 2 10 23
54 2 #12322 | 3 0 !! 47 1 #58634 | 1 0 1 9 | 12 2 9 23
55 3 #12322 | 1 0 !! 48 2 #58634 | 0 0 1 11 | 10 2 9 23
56 4 #12322 | 1 0 !! 49 3 #58634 | 1 0 1 11 | 11 2 9 24
57 5 #12322 | 0 0 !! 50 4 #58634 | 1 0 1 10 | 11 2 9 26
58 6 #12322 | 1 0 !! 51 5 #58634 | 1 0 1 8 | 10 2 9 25
59 7 #12322 | 0 0 !! 52 6 #58634 | 12 0 1 12 | 30 2 10 30 <--- CPU with spike
60 8 #12322 | 1 0 !! 53 7 #58634 | 1 0 1 9 | 11 2 9 23
61 9 #12322 | 0 0 !! 54 8 #58633 | 1 0 1 9 | 11 2 9 26
62 10 #12322 | 1 0 !! 55 9 #58633 | 1 0 1 9 | 10 2 9 26
63 11 #12322 | 0 0 !! 56 10 #58633 | 1 0 1 13 | 11 2 9 28
64 12 #12321 | 1 0 !! 57 11 #58633 | 1 0 1 13 | 12 2 9 24
65 13 #12319 | 0 0 !! 58 12 #58633 | 1 0 1 8 | 10 2 9 23
66 14 #12321 | 1 0 !! 59 13 #58633 | 1 0 1 10 | 10 2 9 22
67 15 #12321 | 1 0 !! 60 14 #58633 | 1 0 1 18 | 12 2 9 27
68 16 #12318 | 0 0 !! 61 15 #58633 | 1 0 1 10 | 11 2 9 28
69 17 #12319 | 0 0 !! 62 16 #58633 | 0 0 1 11 | 7 2 9 26
70 18 #12318 | 0 0 !! 63 17 #58633 | 1 0 1 13 | 10 2 9 24
71 19 #12319 | 0 0 !! 64 18 #58633 | 1 0 1 9 | 13 2 9 22
72 20 #12317 | 0 0 !! 65 19 #58633 | 1 0 1 10 | 11 2 9 23
73 21 #12318 | 0 0 !! 66 20 #58633 | 1 0 1 12 | 11 2 9 28
74 22 #12319 | 0 0 !! 67 21 #58633 | 1 0 1 14 | 11 2 9 24
75 23 #12320 | 28 0 !! 68 22 #58633 | 1 0 1 8 | 11 2 9 22
76 rtla timerlat hit stop tracing !! 69 23 #58633 | 1 0 1 10 | 11 2 9 27
77 ## CPU 23 hit stop tracing, analyzing it ## !! 70 timerlat hit stop tracing
78 IRQ handler delay: !! 71 saving trace to timerlat_trace.txt
79 IRQ latency: !! 72 [root@alien bristot]# tail -60 timerlat_trace.txt
80 Timerlat IRQ duration: !! 73 [...]
81 Blocking thread: !! 74 timerlat/5-79755 [005] ....... 426.271226: #58634 context thread timer_latency 10823 ns
82 objtool:49256 !! 75 sh-109404 [006] dnLh213 426.271247: #58634 context irq timer_latency 12505 ns
83 Blocking thread stacktrace !! 76 sh-109404 [006] dNLh313 426.271258: irq_noise: local_timer:236 start 426.271245463 duration 12553 ns
84 -> timerlat_irq !! 77 sh-109404 [006] d...313 426.271263: thread_noise: sh:109404 start 426.271245853 duration 4769 ns
85 -> __hrtimer_run_queues !! 78 timerlat/6-79756 [006] ....... 426.271264: #58634 context thread timer_latency 30328 ns
86 -> hrtimer_interrupt !! 79 timerlat/6-79756 [006] ....1.. 426.271265: <stack trace>
87 -> __sysvec_apic_timer_interru !! 80 => timerlat_irq
88 -> sysvec_apic_timer_interrupt !! 81 => __hrtimer_run_queues
89 -> asm_sysvec_apic_timer_inter !! 82 => hrtimer_interrupt
90 -> _raw_spin_unlock_irqrestore !! 83 => __sysvec_apic_timer_interrupt
91 -> cgroup_rstat_flush_locked !! 84 => sysvec_apic_timer_interrupt
92 -> cgroup_rstat_flush_irqsafe !! 85 => asm_sysvec_apic_timer_interrupt
93 -> mem_cgroup_flush_stats !! 86 => _raw_spin_unlock_irqrestore <---- spinlock that disabled interrupt.
94 -> mem_cgroup_wb_stats !! 87 => try_to_wake_up
95 -> balance_dirty_pages !! 88 => autoremove_wake_function
96 -> balance_dirty_pages_ratelim !! 89 => __wake_up_common
97 -> btrfs_buffered_write !! 90 => __wake_up_common_lock
98 -> btrfs_do_write_iter !! 91 => ep_poll_callback
99 -> vfs_write !! 92 => __wake_up_common
100 -> __x64_sys_pwrite64 !! 93 => __wake_up_common_lock
101 -> do_syscall_64 !! 94 => fsnotify_add_event
102 -> entry_SYSCALL_64_after_hwfr !! 95 => inotify_handle_inode_event
103 -------------------------------------------- !! 96 => fsnotify
104 Thread latency: !! 97 => __fsnotify_parent
105 !! 98 => __fput
106 The system has exit from idle latency! !! 99 => task_work_run
107 Max timerlat IRQ latency from idle: 17.48 !! 100 => exit_to_user_mode_prepare
108 Saving trace to timerlat_trace.txt !! 101 => syscall_exit_to_user_mode
109 !! 102 => do_syscall_64
110 In this case, the major factor was the delay s !! 103 => entry_SYSCALL_64_after_hwframe
111 that handles **timerlat** wakeup: *65.52%*. Th !! 104 => 0x7265000001378c
112 current thread masking interrupts, which can b !! 105 => 0x10000cea7
113 thread stacktrace: the current thread (*objtoo !! 106 => 0x25a00000204a
114 via *raw spin lock* operations inside mem cgro !! 107 => 0x12e302d00000000
115 syscall in a btrfs file system. !! 108 => 0x19b51010901b6
116 !! 109 => 0x283ce00726500
117 The raw trace is saved in the **timerlat_trace !! 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.
118 129
119 Note that **rtla timerlat** was dispatched wit 130 Note that **rtla timerlat** was dispatched without changing *timerlat* tracer
120 threads' priority. That is generally not neede !! 131 threads' priority. That is generally not needed because these threads hava
121 priority *FIFO:95* by default, which is a comm 132 priority *FIFO:95* by default, which is a common priority used by real-time
122 kernel developers to analyze scheduling delays 133 kernel developers to analyze scheduling delays.
123 134
124 SEE ALSO 135 SEE ALSO
125 -------- 136 --------
126 **rtla-timerlat**\(1), **rtla-timerlat-hist**\ 137 **rtla-timerlat**\(1), **rtla-timerlat-hist**\(1)
127 138
128 *timerlat* tracer documentation: <https://www. 139 *timerlat* tracer documentation: <https://www.kernel.org/doc/html/latest/trace/timerlat-tracer.html>
129 140
130 AUTHOR 141 AUTHOR
131 ------ 142 ------
132 Written by Daniel Bristot de Oliveira <bristot@ 143 Written by Daniel Bristot de Oliveira <bristot@kernel.org>
133 144
134 .. include:: common_appendix.rst 145 .. 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.