lkml.org 
[lkml]   [2021]   [Dec]   [10]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    Patch in this message
    /
    From
    Subject[PATCH V9 13/14] rtla: Add rtla timerlat top documentation
    Date
    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
    \
     
     \ /
      Last update: 2021-12-10 19:15    [W:4.218 / U:0.144 seconds]
    ©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site