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