128 lines
5.9 KiB
ReStructuredText
128 lines
5.9 KiB
ReStructuredText
|
====================
|
||
|
|
rtla-timerlat-top
|
||
|
|
====================
|
||
|
|
-------------------------------------------
|
||
|
|
Measures the operating system timer latency
|
||
|
|
-------------------------------------------
|
||
|
|
|
||
|
|
:Manual section: 1
|
||
|
|
|
||
|
|
SYNOPSIS
|
||
|
|
========
|
||
|
|
**rtla timerlat top** [*OPTIONS*] ...
|
||
|
|
|
||
|
|
DESCRIPTION
|
||
|
|
===========
|
||
|
|
|
||
|
|
.. include:: common_timerlat_description.rst
|
||
|
|
|
||
|
|
The **rtla timerlat top** displays a summary of the periodic output
|
||
|
|
from the *timerlat* tracer. It also provides information for each
|
||
|
|
operating system noise via the **osnoise:** tracepoints that can be
|
||
|
|
seem with the option **-T**.
|
||
|
|
|
||
|
|
OPTIONS
|
||
|
|
=======
|
||
|
|
|
||
|
|
.. include:: common_timerlat_options.rst
|
||
|
|
|
||
|
|
.. include:: common_top_options.rst
|
||
|
|
|
||
|
|
.. include:: common_options.rst
|
||
|
|
|
||
|
|
.. include:: common_timerlat_aa.rst
|
||
|
|
|
||
|
|
EXAMPLE
|
||
|
|
=======
|
||
|
|
|
||
|
|
In the example below, the timerlat tracer is dispatched in cpus *1-23* in the
|
||
|
|
automatic trace mode, instructing the tracer to stop if a *40 us* latency or
|
||
|
|
higher is found::
|
||
|
|
|
||
|
|
# timerlat -a 40 -c 1-23 -q
|
||
|
|
Timer Latency
|
||
|
|
0 00:00:12 | IRQ Timer Latency (us) | Thread Timer Latency (us)
|
||
|
|
CPU COUNT | cur min avg max | cur min avg max
|
||
|
|
1 #12322 | 0 0 1 15 | 10 3 9 31
|
||
|
|
2 #12322 | 3 0 1 12 | 10 3 9 23
|
||
|
|
3 #12322 | 1 0 1 21 | 8 2 8 34
|
||
|
|
4 #12322 | 1 0 1 17 | 10 2 11 33
|
||
|
|
5 #12322 | 0 0 1 12 | 8 3 8 25
|
||
|
|
6 #12322 | 1 0 1 14 | 16 3 11 35
|
||
|
|
7 #12322 | 0 0 1 14 | 9 2 8 29
|
||
|
|
8 #12322 | 1 0 1 22 | 9 3 9 34
|
||
|
|
9 #12322 | 0 0 1 14 | 8 2 8 24
|
||
|
|
10 #12322 | 1 0 0 12 | 9 3 8 24
|
||
|
|
11 #12322 | 0 0 0 15 | 6 2 7 29
|
||
|
|
12 #12321 | 1 0 0 13 | 5 3 8 23
|
||
|
|
13 #12319 | 0 0 1 14 | 9 3 9 26
|
||
|
|
14 #12321 | 1 0 0 13 | 6 2 8 24
|
||
|
|
15 #12321 | 1 0 1 15 | 12 3 11 27
|
||
|
|
16 #12318 | 0 0 1 13 | 7 3 10 24
|
||
|
|
17 #12319 | 0 0 1 13 | 11 3 9 25
|
||
|
|
18 #12318 | 0 0 0 12 | 8 2 8 20
|
||
|
|
19 #12319 | 0 0 1 18 | 10 2 9 28
|
||
|
|
20 #12317 | 0 0 0 20 | 9 3 8 34
|
||
|
|
21 #12318 | 0 0 0 13 | 8 3 8 28
|
||
|
|
22 #12319 | 0 0 1 11 | 8 3 10 22
|
||
|
|
23 #12320 | 28 0 1 28 | 41 3 11 41
|
||
|
|
rtla timerlat hit stop tracing
|
||
|
|
## CPU 23 hit stop tracing, analyzing it ##
|
||
|
|
IRQ handler delay: 27.49 us (65.52 %)
|
||
|
|
IRQ latency: 28.13 us
|
||
|
|
Timerlat IRQ duration: 9.59 us (22.85 %)
|
||
|
|
Blocking thread: 3.79 us (9.03 %)
|
||
|
|
objtool:49256 3.79 us
|
||
|
|
Blocking thread stacktrace
|
||
|
|
-> timerlat_irq
|
||
|
|
-> __hrtimer_run_queues
|
||
|
|
-> hrtimer_interrupt
|
||
|
|
-> __sysvec_apic_timer_interrupt
|
||
|
|
-> sysvec_apic_timer_interrupt
|
||
|
|
-> asm_sysvec_apic_timer_interrupt
|
||
|
|
-> _raw_spin_unlock_irqrestore
|
||
|
|
-> cgroup_rstat_flush_locked
|
||
|
|
-> cgroup_rstat_flush_irqsafe
|
||
|
|
-> mem_cgroup_flush_stats
|
||
|
|
-> mem_cgroup_wb_stats
|
||
|
|
-> balance_dirty_pages
|
||
|
|
-> balance_dirty_pages_ratelimited_flags
|
||
|
|
-> btrfs_buffered_write
|
||
|
|
-> btrfs_do_write_iter
|
||
|
|
-> vfs_write
|
||
|
|
-> __x64_sys_pwrite64
|
||
|
|
-> do_syscall_64
|
||
|
|
-> entry_SYSCALL_64_after_hwframe
|
||
|
|
------------------------------------------------------------------------
|
||
|
|
Thread latency: 41.96 us (100%)
|
||
|
|
|
||
|
|
The system has exit from idle latency!
|
||
|
|
Max timerlat IRQ latency from idle: 17.48 us in cpu 4
|
||
|
|
Saving trace to timerlat_trace.txt
|
||
|
|
|
||
|
|
In this case, the major factor was the delay suffered by the *IRQ handler*
|
||
|
|
that handles **timerlat** wakeup: *65.52%*. This can be caused by the
|
||
|
|
current thread masking interrupts, which can be seen in the blocking
|
||
|
|
thread stacktrace: the current thread (*objtool:49256*) disabled interrupts
|
||
|
|
via *raw spin lock* operations inside mem cgroup, while doing write
|
||
|
|
syscall in a btrfs file system.
|
||
|
|
|
||
|
|
The raw trace is saved in the **timerlat_trace.txt** file for further analysis.
|
||
|
|
|
||
|
|
Note that **rtla timerlat** was dispatched without changing *timerlat* tracer
|
||
|
|
threads' priority. That is generally not needed because these threads hava
|
||
|
|
priority *FIFO:95* by default, which is a common priority used by real-time
|
||
|
|
kernel developers to analyze scheduling delays.
|
||
|
|
|
||
|
|
SEE ALSO
|
||
|
|
--------
|
||
|
|
**rtla-timerlat**\(1), **rtla-timerlat-hist**\(1)
|
||
|
|
|
||
|
|
*timerlat* tracer documentation: <https://www.kernel.org/doc/html/latest/trace/timerlat-tracer.html>
|
||
|
|
|
||
|
|
AUTHOR
|
||
|
|
------
|
||
|
|
Written by Daniel Bristot de Oliveira <bristot@kernel.org>
|
||
|
|
|
||
|
|
.. include:: common_appendix.rst
|