From: Daniel Bristot de Oliveira <bristot@kernel.org>
To: Steven Rostedt <rostedt@goodmis.org>
Cc: Tao Zhou <tao.zhou@linux.dev>,
Daniel Bristot de Oliveira <bristot@kernel.org>,
Ingo Molnar <mingo@redhat.com>, Tom Zanussi <zanussi@kernel.org>,
Masami Hiramatsu <mhiramat@kernel.org>,
Juri Lelli <juri.lelli@redhat.com>,
Clark Williams <williams@redhat.com>,
John Kacur <jkacur@redhat.com>,
Peter Zijlstra <peterz@infradead.org>,
Thomas Gleixner <tglx@linutronix.de>,
Sebastian Andrzej Siewior <bigeasy@linutronix.de>,
linux-rt-users@vger.kernel.org,
linux-trace-devel@vger.kernel.org, linux-kernel@vger.kernel.org
Subject: [PATCH V8 13/14] rtla: Add rtla timerlat top documentation
Date: Mon, 29 Nov 2021 12:07:51 +0100 [thread overview]
Message-ID: <df06fa7801571078e43d77002c6645bdc49f779a.1638182284.git.bristot@kernel.org> (raw)
In-Reply-To: <cover.1638182284.git.bristot@kernel.org>
Man page for rtla timerlat top mode.
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Ingo Molnar <mingo@redhat.com>
Cc: Tom Zanussi <zanussi@kernel.org>
Cc: Masami Hiramatsu <mhiramat@kernel.org>
Cc: Juri Lelli <juri.lelli@redhat.com>
Cc: Clark Williams <williams@redhat.com>
Cc: John Kacur <jkacur@redhat.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
Cc: Daniel Bristot de Oliveira <bristot@kernel.org>
Cc: linux-rt-users@vger.kernel.org
Cc: linux-trace-devel@vger.kernel.org
Cc: linux-kernel@vger.kernel.org
Signed-off-by: Daniel Bristot de Oliveira <bristot@kernel.org>
---
.../tools/rtla/common_timerlat_options.rst | 16 ++
.../tools/rtla/rtla-timerlat-top.rst | 145 ++++++++++++++++++
2 files changed, 161 insertions(+)
create mode 100644 Documentation/tools/rtla/common_timerlat_options.rst
create mode 100644 Documentation/tools/rtla/rtla-timerlat-top.rst
diff --git a/Documentation/tools/rtla/common_timerlat_options.rst b/Documentation/tools/rtla/common_timerlat_options.rst
new file mode 100644
index 000000000000..e9c1bfd55d48
--- /dev/null
+++ b/Documentation/tools/rtla/common_timerlat_options.rst
@@ -0,0 +1,16 @@
+**-p**, **--period** *us*
+
+ Set the *timerlat* tracer period in microseconds.
+
+**-i**, **--irq** *us*
+
+ Stop trace if the *IRQ* latency is higher than the argument in us.
+
+**-T**, **--thread** *us*
+
+ Stop trace if the *Thread* latency is higher than the argument in us.
+
+**-s**, **--stack** *us*
+
+ Save the stack trace at the *IRQ* if a *Thread* latency is higher than the
+ argument in us.
diff --git a/Documentation/tools/rtla/rtla-timerlat-top.rst b/Documentation/tools/rtla/rtla-timerlat-top.rst
new file mode 100644
index 000000000000..1c321de1c171
--- /dev/null
+++ b/Documentation/tools/rtla/rtla-timerlat-top.rst
@@ -0,0 +1,145 @@
+====================
+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
+
+EXAMPLE
+=======
+
+In the example below, the *timerlat* tracer is set to capture the stack trace at
+the IRQ handler, printing it to the buffer if the *Thread* timer latency is
+higher than *30 us*. It is also set to stop the session if a *Thread* timer
+latency higher than *30 us* is hit. Finally, it is set to save the trace
+buffer if the stop condition is hit::
+
+ [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
+
+In the trace, it is possible the notice that the *IRQ* timer latency was
+already high, accounting *12505 ns*. The IRQ delay was caused by the
+*bash-109109* process that disabled IRQs in the wake-up path
+(*_try_to_wake_up()* function). The duration of the IRQ handler that woke
+up the timerlat thread, informed with the **osnoise:irq_noise** event, was
+also high and added more *12553 ns* to the Thread latency. Finally, the
+**osnoise:thread_noise** added by the currently running thread (including
+the scheduling overhead) added more *4769 ns*. Summing up these values,
+the *Thread* timer latency accounted for *30328 ns*.
+
+The primary reason for this high value is the wake-up path that was hit
+twice during this case: when the *bash-109109* was waking up a thread
+and then when the *timerlat* thread was awakened. This information can
+then be used as the starting point of a more fine-grained 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
--
2.31.1
next prev parent reply other threads:[~2021-11-29 11:12 UTC|newest]
Thread overview: 29+ messages / expand[flat|nested] mbox.gz Atom feed top
2021-11-29 11:07 [PATCH V8 00/14] RTLA: An interface for osnoise/timerlat tracers Daniel Bristot de Oliveira
2021-11-29 11:07 ` [PATCH V8 01/14] rtla: Real-Time Linux Analysis tool Daniel Bristot de Oliveira
2021-11-29 11:07 ` [PATCH V8 02/14] rtla: Helper functions for rtla Daniel Bristot de Oliveira
2021-12-03 9:07 ` Tao Zhou
2021-12-03 14:52 ` Daniel Bristot de Oliveira
2021-11-29 11:07 ` [PATCH V8 03/14] rtla: Add osnoise tool Daniel Bristot de Oliveira
2021-11-30 15:35 ` Tao Zhou
2021-12-02 15:18 ` Daniel Bristot de Oliveira
2021-12-08 22:14 ` Steven Rostedt
2021-12-08 22:13 ` Steven Rostedt
2021-12-09 16:15 ` Daniel Bristot de Oliveira
2021-11-29 11:07 ` [PATCH V8 04/14] rtla/osnoise: Add osnoise top mode Daniel Bristot de Oliveira
2021-12-04 18:04 ` Daniel Bristot de Oliveira
2021-11-29 11:07 ` [PATCH V8 05/14] rtla/osnoise: Add the hist mode Daniel Bristot de Oliveira
2021-11-29 11:07 ` [PATCH V8 06/14] rtla: Add timerlat tool and timelart top mode Daniel Bristot de Oliveira
2021-12-03 9:13 ` Tao Zhou
2021-12-03 17:41 ` Daniel Bristot de Oliveira
2021-11-29 11:07 ` [PATCH V8 07/14] rtla/timerlat: Add timerlat hist mode Daniel Bristot de Oliveira
2021-12-03 9:17 ` Tao Zhou
2021-12-03 17:42 ` Daniel Bristot de Oliveira
2021-11-29 11:07 ` [PATCH V8 08/14] rtla: Add Documentation Daniel Bristot de Oliveira
2021-11-29 11:07 ` [PATCH V8 09/14] rtla: Add rtla osnoise man page Daniel Bristot de Oliveira
2021-11-29 11:07 ` [PATCH V8 10/14] rtla: Add rtla osnoise top documentation Daniel Bristot de Oliveira
2021-11-29 11:07 ` [PATCH V8 11/14] rtla: Add rtla osnoise hist documentation Daniel Bristot de Oliveira
2021-11-29 11:07 ` [PATCH V8 12/14] rtla: Add rtla timerlat documentation Daniel Bristot de Oliveira
2021-11-29 11:07 ` Daniel Bristot de Oliveira [this message]
2021-11-29 11:07 ` [PATCH V8 14/14] rtla: Add rtla timerlat hist documentation Daniel Bristot de Oliveira
2021-12-04 13:25 ` [PATCH V8 00/14] RTLA: An interface for osnoise/timerlat tracers Tao Zhou
2021-12-04 14:16 ` Daniel Bristot de Oliveira
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=df06fa7801571078e43d77002c6645bdc49f779a.1638182284.git.bristot@kernel.org \
--to=bristot@kernel.org \
--cc=bigeasy@linutronix.de \
--cc=jkacur@redhat.com \
--cc=juri.lelli@redhat.com \
--cc=linux-kernel@vger.kernel.org \
--cc=linux-rt-users@vger.kernel.org \
--cc=linux-trace-devel@vger.kernel.org \
--cc=mhiramat@kernel.org \
--cc=mingo@redhat.com \
--cc=peterz@infradead.org \
--cc=rostedt@goodmis.org \
--cc=tao.zhou@linux.dev \
--cc=tglx@linutronix.de \
--cc=williams@redhat.com \
--cc=zanussi@kernel.org \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).