.\" Man page generated from reStructuredText.
.
.TH RTLA-TIMERLAT-TOP 1 "" "" ""
.SH NAME
rtla-timerlat-top \- Measures the operating system timer latency
.
.nr rst2man-indent-level 0
.
.de1 rstReportMargin
\\$1 \\n[an-margin]
level \\n[rst2man-indent-level]
level margin: \\n[rst2man-indent\\n[rst2man-indent-level]]
-
\\n[rst2man-indent0]
\\n[rst2man-indent1]
\\n[rst2man-indent2]
..
.de1 INDENT
.\" .rstReportMargin pre:
. RS \\$1
. nr rst2man-indent\\n[rst2man-indent-level] \\n[an-margin]
. nr rst2man-indent-level +1
.\" .rstReportMargin post:
..
.de UNINDENT
. RE
.\" indent \\n[an-margin]
.\" old: \\n[rst2man-indent\\n[rst2man-indent-level]]
.nr rst2man-indent-level -1
.\" new: \\n[rst2man-indent\\n[rst2man-indent-level]]
.in \\n[rst2man-indent\\n[rst2man-indent-level]]u
..
.SH SYNOPSIS
.sp
\fBrtla timerlat top\fP [\fIOPTIONS\fP] ...
.SH DESCRIPTION
.sp
The \fBrtla timerlat\fP tool is an interface for the \fItimerlat\fP tracer. The
\fItimerlat\fP tracer dispatches a kernel thread per\-cpu. These threads
set a periodic timer to wake themselves up and go back to sleep. After
the wakeup, they collect and generate useful information for the
debugging of operating system timer latency.
.sp
The \fItimerlat\fP tracer outputs information in two ways. It periodically
prints the timer latency at the timer \fIIRQ\fP handler and the \fIThread\fP
handler. It also enable the trace of the most relevant information via
\fBosnoise:\fP tracepoints.
.sp
The \fBrtla timerlat top\fP displays a summary of the periodic output
from the \fItimerlat\fP tracer. It also provides information for each
operating system noise via the \fBosnoise:\fP tracepoints that can be
seem with the option \fB\-T\fP\&.
.SH OPTIONS
.sp
\fB\-a\fP, \fB\-\-auto\fP \fIus\fP
.INDENT 0.0
.INDENT 3.5
Set the automatic trace mode. This mode sets some commonly used options
while debugging the system. It is equivalent to use \fB\-T\fP \fIus\fP \fB\-s\fP \fIus\fP
\fB\-t\fP\&. By default, \fItimerlat\fP tracer uses FIFO:95 for \fItimerlat\fP threads,
thus equilavent to \fB\-P\fP \fIf:95\fP\&.
.UNINDENT
.UNINDENT
.sp
\fB\-p\fP, \fB\-\-period\fP \fIus\fP
.INDENT 0.0
.INDENT 3.5
Set the \fItimerlat\fP tracer period in microseconds.
.UNINDENT
.UNINDENT
.sp
\fB\-i\fP, \fB\-\-irq\fP \fIus\fP
.INDENT 0.0
.INDENT 3.5
Stop trace if the \fIIRQ\fP latency is higher than the argument in us.
.UNINDENT
.UNINDENT
.sp
\fB\-T\fP, \fB\-\-thread\fP \fIus\fP
.INDENT 0.0
.INDENT 3.5
Stop trace if the \fIThread\fP latency is higher than the argument in us.
.UNINDENT
.UNINDENT
.sp
\fB\-s\fP, \fB\-\-stack\fP \fIus\fP
.INDENT 0.0
.INDENT 3.5
Save the stack trace at the \fIIRQ\fP if a \fIThread\fP latency is higher than the
argument in us.
.UNINDENT
.UNINDENT
.INDENT 0.0
.TP
.B \fB\-\-dma\-latency\fP \fIus\fP
Set the /dev/cpu_dma_latency to \fIus\fP, aiming to bound exit from idle latencies.
\fIcyclictest\fP sets this value to \fI0\fP by default, use \fB\-\-dma\-latency\fP \fI0\fP to have
similar results.
.UNINDENT
.sp
\fB\-q\fP, \fB\-\-quiet\fP
.INDENT 0.0
.INDENT 3.5
Print only a summary at the end of the session.
.UNINDENT
.UNINDENT
.sp
\fB\-c\fP, \fB\-\-cpus\fP \fIcpu\-list\fP
.INDENT 0.0
.INDENT 3.5
Set the osnoise tracer to run the sample threads in the cpu\-list.
.UNINDENT
.UNINDENT
.sp
\fB\-d\fP, \fB\-\-duration\fP \fItime[s|m|h|d]\fP
.INDENT 0.0
.INDENT 3.5
Set the duration of the session.
.UNINDENT
.UNINDENT
.sp
\fB\-D\fP, \fB\-\-debug\fP
.INDENT 0.0
.INDENT 3.5
Print debug info.
.UNINDENT
.UNINDENT
.sp
\fB\-t\fP, \fB\-\-trace\fP[\fI=file\fP]
.INDENT 0.0
.INDENT 3.5
Save the stopped trace to [\fIfile|osnoise_trace.txt\fP].
.UNINDENT
.UNINDENT
.sp
\fB\-e\fP, \fB\-\-event\fP \fIsys:event\fP
.INDENT 0.0
.INDENT 3.5
Enable an event in the trace (\fB\-t\fP) session. The argument can be a specific event, e.g., \fB\-e\fP \fIsched:sched_switch\fP, or all events of a system group, e.g., \fB\-e\fP \fIsched\fP\&. Multiple \fB\-e\fP are allowed. It is only active when \fB\-t\fP or \fB\-a\fP are set.
.UNINDENT
.UNINDENT
.sp
\fB\-\-filter\fP \fI<filter>\fP
.INDENT 0.0
.INDENT 3.5
Filter the previous \fB\-e\fP \fIsys:event\fP event with \fI<filter>\fP\&. For further information about event filtering see \fI\%https://www.kernel.org/doc/html/latest/trace/events.html#event\-filtering\fP\&.
.UNINDENT
.UNINDENT
.INDENT 0.0
.TP
.B \fB\-\-trigger\fP \fI<trigger>\fP
Enable a trace event trigger to the previous \fB\-e\fP \fIsys:event\fP\&.
If the \fIhist:\fP trigger is activated, the output histogram will be automatically saved to a file named \fIsystem_event_hist.txt\fP\&.
For example, the command:
.sp
rtla <command> <mode> \-t \-e osnoise:irq_noise \-\-trigger="hist:key=desc,duration/1000:sort=desc,duration/1000:vals=hitcount"
.sp
Will automatically save the content of the histogram associated to \fIosnoise:irq_noise\fP event in \fIosnoise_irq_noise_hist.txt\fP\&.
.sp
For further information about event trigger see \fI\%https://www.kernel.org/doc/html/latest/trace/events.html#event\-triggers\fP\&.
.UNINDENT
.sp
\fB\-P\fP, \fB\-\-priority\fP \fIo:prio|r:prio|f:prio|d:runtime:period\fP
.INDENT 0.0
.INDENT 3.5
Set scheduling parameters to the osnoise tracer threads, the format to set the priority are:
.INDENT 0.0
.IP \(bu 2
\fIo:prio\fP \- use SCHED_OTHER with \fIprio\fP;
.IP \(bu 2
\fIr:prio\fP \- use SCHED_RR with \fIprio\fP;
.IP \(bu 2
\fIf:prio\fP \- use SCHED_FIFO with \fIprio\fP;
.IP \(bu 2
\fId:runtime[us|ms|s]:period[us|ms|s]\fP \- use SCHED_DEADLINE with \fIruntime\fP and \fIperiod\fP in nanoseconds.
.UNINDENT
.UNINDENT
.UNINDENT
.sp
\fB\-h\fP, \fB\-\-help\fP
.INDENT 0.0
.INDENT 3.5
Print help menu.
.UNINDENT
.UNINDENT
.SH EXAMPLE
.sp
In the example below, the \fItimerlat\fP tracer is set to capture the stack trace at
the IRQ handler, printing it to the buffer if the \fIThread\fP timer latency is
higher than \fI30 us\fP\&. It is also set to stop the session if a \fIThread\fP timer
latency higher than \fI30 us\fP is hit. Finally, it is set to save the trace
buffer if the stop condition is hit:
.INDENT 0.0
.INDENT 3.5
.sp
.nf
.ft C
[root@alien ~]# rtla timerlat top \-s 30 \-T 30 \-t
                 Timer Latency
  0 00:00:59   |          IRQ Timer Latency (us)        |         Thread Timer Latency (us)
CPU COUNT      |      cur       min       avg       max |      cur       min       avg       max
  0 #58634     |        1         0         1        10 |       11         2        10        23
  1 #58634     |        1         0         1         9 |       12         2         9        23
  2 #58634     |        0         0         1        11 |       10         2         9        23
  3 #58634     |        1         0         1        11 |       11         2         9        24
  4 #58634     |        1         0         1        10 |       11         2         9        26
  5 #58634     |        1         0         1         8 |       10         2         9        25
  6 #58634     |       12         0         1        12 |       30         2        10        30 <\-\-\- CPU with spike
  7 #58634     |        1         0         1         9 |       11         2         9        23
  8 #58633     |        1         0         1         9 |       11         2         9        26
  9 #58633     |        1         0         1         9 |       10         2         9        26
 10 #58633     |        1         0         1        13 |       11         2         9        28
 11 #58633     |        1         0         1        13 |       12         2         9        24
 12 #58633     |        1         0         1         8 |       10         2         9        23
 13 #58633     |        1         0         1        10 |       10         2         9        22
 14 #58633     |        1         0         1        18 |       12         2         9        27
 15 #58633     |        1         0         1        10 |       11         2         9        28
 16 #58633     |        0         0         1        11 |        7         2         9        26
 17 #58633     |        1         0         1        13 |       10         2         9        24
 18 #58633     |        1         0         1         9 |       13         2         9        22
 19 #58633     |        1         0         1        10 |       11         2         9        23
 20 #58633     |        1         0         1        12 |       11         2         9        28
 21 #58633     |        1         0         1        14 |       11         2         9        24
 22 #58633     |        1         0         1         8 |       11         2         9        22
 23 #58633     |        1         0         1        10 |       11         2         9        27
timerlat hit stop tracing
saving trace to timerlat_trace.txt
[root@alien bristot]# tail \-60 timerlat_trace.txt
[...]
    timerlat/5\-79755   [005] .......   426.271226: #58634 context thread timer_latency     10823 ns
            sh\-109404  [006] dnLh213   426.271247: #58634 context    irq timer_latency     12505 ns
            sh\-109404  [006] dNLh313   426.271258: irq_noise: local_timer:236 start 426.271245463 duration 12553 ns
            sh\-109404  [006] d...313   426.271263: thread_noise:       sh:109404 start 426.271245853 duration 4769 ns
    timerlat/6\-79756   [006] .......   426.271264: #58634 context thread timer_latency     30328 ns
    timerlat/6\-79756   [006] ....1..   426.271265: <stack trace>
=> timerlat_irq
=> __hrtimer_run_queues
=> hrtimer_interrupt
=> __sysvec_apic_timer_interrupt
=> sysvec_apic_timer_interrupt
=> asm_sysvec_apic_timer_interrupt
=> _raw_spin_unlock_irqrestore                        <\-\-\-\- spinlock that disabled interrupt.
=> try_to_wake_up
=> autoremove_wake_function
=> __wake_up_common
=> __wake_up_common_lock
=> ep_poll_callback
=> __wake_up_common
=> __wake_up_common_lock
=> fsnotify_add_event
=> inotify_handle_inode_event
=> fsnotify
=> __fsnotify_parent
=> __fput
=> task_work_run
=> exit_to_user_mode_prepare
=> syscall_exit_to_user_mode
=> do_syscall_64
=> entry_SYSCALL_64_after_hwframe
=> 0x7265000001378c
=> 0x10000cea7
=> 0x25a00000204a
=> 0x12e302d00000000
=> 0x19b51010901b6
=> 0x283ce00726500
=> 0x61ea308872
=> 0x00000fe3
          bash\-109109  [007] d..h...   426.271265: #58634 context    irq timer_latency      1211 ns
    timerlat/6\-79756   [006] .......   426.271267: timerlat_main: stop tracing hit on cpu 6
.ft P
.fi
.UNINDENT
.UNINDENT
.sp
In the trace, it is possible the notice that the \fIIRQ\fP timer latency was
already high, accounting \fI12505 ns\fP\&. The IRQ delay was caused by the
\fIbash\-109109\fP process that disabled IRQs in the wake\-up path
(\fI_try_to_wake_up()\fP function). The duration of the IRQ handler that woke
up the timerlat thread, informed with the \fBosnoise:irq_noise\fP event, was
also high and added more \fI12553 ns\fP to the Thread latency. Finally, the
\fBosnoise:thread_noise\fP added by the currently running thread (including
the scheduling overhead) added more \fI4769 ns\fP\&. Summing up these values,
the \fIThread\fP timer latency accounted for \fI30328 ns\fP\&.
.sp
The primary reason for this high value is the wake\-up path that was hit
twice during this case: when the \fIbash\-109109\fP was waking up a thread
and then when the \fItimerlat\fP thread was awakened. This information can
then be used as the starting point of a more fine\-grained analysis.
.sp
Note that \fBrtla timerlat\fP was dispatched without changing \fItimerlat\fP tracer
threads\(aq priority. That is generally not needed because these threads hava
priority \fIFIFO:95\fP by default, which is a common priority used by real\-time
kernel developers to analyze scheduling delays.
.SS SEE ALSO
.sp
\fBrtla\-timerlat\fP(1), \fBrtla\-timerlat\-hist\fP(1)
.sp
\fItimerlat\fP tracer documentation: <\fI\%https://www.kernel.org/doc/html/latest/trace/timerlat\-tracer.html\fP>
.SS AUTHOR
.sp
Written by Daniel Bristot de Oliveira <\fI\%bristot@kernel.org\fP>
.SH REPORTING BUGS
.sp
Report bugs to <\fI\%linux\-kernel@vger.kernel.org\fP>
and <\fI\%linux\-trace\-devel@vger.kernel.org\fP>
.SH LICENSE
.sp
\fBrtla\fP is Free Software licensed under the GNU GPLv2
.SH COPYING
.sp
Copyright (C) 2021 Red Hat, Inc. Free use of this software is granted under
the terms of the GNU Public License (GPL).
.\" Generated by docutils manpage writer.
.