Commit df337d01 authored by Daniel Bristot de Oliveira's avatar Daniel Bristot de Oliveira Committed by Steven Rostedt
Browse files

rtla: Add rtla timerlat top documentation 

Man page for rtla timerlat top mode.

Link: https://lkml.kernel.org/r/58c3d6212e6c6f1f012deb2e998dd082da92075f.1639158831.git.bristot@kernel.org



Cc: Tao Zhou <tao.zhou@linux.dev>
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: default avatarDaniel Bristot de Oliveira <bristot@kernel.org>
Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
parent 29380d40

Documentation/tools/rtla/common_timerlat_options.rst

0 → 100644
+16 −0
Original line number Diff line number Diff line 
**-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.

Documentation/tools/rtla/rtla-timerlat-top.rst

0 → 100644
+145 −0
Original line number Diff line number Diff line 
====================

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