[linux-block.git] / Documentation / tools / rtla / rtla-timerlat-top.rst

====================
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
Commit	Line	Data
df337d01 DBO	1	====================
	2	rtla-timerlat-top
	3	====================
	4	-------------------------------------------
	5	Measures the operating system timer latency
	6	-------------------------------------------
	7
	8	:Manual section: 1
	9
	10	SYNOPSIS
	11	========
	12	rtla timerlat top [OPTIONS] ...
	13
	14	DESCRIPTION
	15	===========
	16
	17	.. include:: common_timerlat_description.rst
	18
	19	The rtla timerlat top displays a summary of the periodic output
	20	from the timerlat tracer. It also provides information for each
	21	operating system noise via the osnoise: tracepoints that can be
	22	seem with the option -T.
	23
	24	OPTIONS
	25	=======
	26
	27	.. include:: common_timerlat_options.rst
	28
	29	.. include:: common_top_options.rst
	30
	31	.. include:: common_options.rst
	32
	33	EXAMPLE
	34	=======
	35
	36	In the example below, the timerlat tracer is set to capture the stack trace at
	37	the IRQ handler, printing it to the buffer if the Thread timer latency is
	38	higher than 30 us. It is also set to stop the session if a Thread timer
	39	latency higher than 30 us is hit. Finally, it is set to save the trace
	40	buffer if the stop condition is hit::
	41
877d95dc	42	[root@alien ~]# rtla timerlat top -s 30 -T 30 -t
df337d01 DBO	43	Timer Latency
	44	0 00:00:59 \| IRQ Timer Latency (us) \| Thread Timer Latency (us)
	45	CPU COUNT \| cur min avg max \| cur min avg max
	46	0 #58634 \| 1 0 1 10 \| 11 2 10 23
	47	1 #58634 \| 1 0 1 9 \| 12 2 9 23
	48	2 #58634 \| 0 0 1 11 \| 10 2 9 23
	49	3 #58634 \| 1 0 1 11 \| 11 2 9 24
	50	4 #58634 \| 1 0 1 10 \| 11 2 9 26
	51	5 #58634 \| 1 0 1 8 \| 10 2 9 25
	52	6 #58634 \| 12 0 1 12 \| 30 2 10 30 <--- CPU with spike
	53	7 #58634 \| 1 0 1 9 \| 11 2 9 23
	54	8 #58633 \| 1 0 1 9 \| 11 2 9 26
	55	9 #58633 \| 1 0 1 9 \| 10 2 9 26
	56	10 #58633 \| 1 0 1 13 \| 11 2 9 28
	57	11 #58633 \| 1 0 1 13 \| 12 2 9 24
	58	12 #58633 \| 1 0 1 8 \| 10 2 9 23
	59	13 #58633 \| 1 0 1 10 \| 10 2 9 22
	60	14 #58633 \| 1 0 1 18 \| 12 2 9 27
	61	15 #58633 \| 1 0 1 10 \| 11 2 9 28
	62	16 #58633 \| 0 0 1 11 \| 7 2 9 26
	63	17 #58633 \| 1 0 1 13 \| 10 2 9 24
	64	18 #58633 \| 1 0 1 9 \| 13 2 9 22
	65	19 #58633 \| 1 0 1 10 \| 11 2 9 23
	66	20 #58633 \| 1 0 1 12 \| 11 2 9 28
	67	21 #58633 \| 1 0 1 14 \| 11 2 9 24
	68	22 #58633 \| 1 0 1 8 \| 11 2 9 22
	69	23 #58633 \| 1 0 1 10 \| 11 2 9 27
	70	timerlat hit stop tracing
	71	saving trace to timerlat_trace.txt
	72	[root@alien bristot]# tail -60 timerlat_trace.txt
	73	[...]
	74	timerlat/5-79755 [005] ....... 426.271226: #58634 context thread timer_latency 10823 ns
	75	sh-109404 [006] dnLh213 426.271247: #58634 context irq timer_latency 12505 ns
	76	sh-109404 [006] dNLh313 426.271258: irq_noise: local_timer:236 start 426.271245463 duration 12553 ns
	77	sh-109404 [006] d...313 426.271263: thread_noise: sh:109404 start 426.271245853 duration 4769 ns
	78	timerlat/6-79756 [006] ....... 426.271264: #58634 context thread timer_latency 30328 ns
	79	timerlat/6-79756 [006] ....1.. 426.271265: <stack trace>
	80	=> timerlat_irq
	81	=> __hrtimer_run_queues
	82	=> hrtimer_interrupt
	83	=> __sysvec_apic_timer_interrupt
	84	=> sysvec_apic_timer_interrupt
	85	=> asm_sysvec_apic_timer_interrupt
	86	=> _raw_spin_unlock_irqrestore <---- spinlock that disabled interrupt.
	87	=> try_to_wake_up
	88	=> autoremove_wake_function
	89	=> __wake_up_common
	90	=> __wake_up_common_lock
	91	=> ep_poll_callback
	92	=> __wake_up_common
	93	=> __wake_up_common_lock
	94	=> fsnotify_add_event
	95	=> inotify_handle_inode_event
	96	=> fsnotify
	97	=> __fsnotify_parent
	98	=> __fput
	99	=> task_work_run
	100	=> exit_to_user_mode_prepare
	101	=> syscall_exit_to_user_mode
	102	=> do_syscall_64
	103	=> entry_SYSCALL_64_after_hwframe
	104	=> 0x7265000001378c
	105	=> 0x10000cea7
	106	=> 0x25a00000204a
107	=> 0x12e302d00000000
108	=> 0x19b51010901b6
109	=> 0x283ce00726500
110	=> 0x61ea308872
111	=> 0x00000fe3
112	bash-109109 [007] d..h... 426.271265: #58634 context irq timer_latency 1211 ns
113	timerlat/6-79756 [006] ....... 426.271267: timerlat_main: stop tracing hit on cpu 6
114
115	In the trace, it is possible the notice that the IRQ timer latency was
116	already high, accounting 12505 ns. The IRQ delay was caused by the
117	bash-109109 process that disabled IRQs in the wake-up path
118	(_try_to_wake_up() function). The duration of the IRQ handler that woke
119	up the timerlat thread, informed with the osnoise:irq_noise event, was
120	also high and added more 12553 ns to the Thread latency. Finally, the
121	osnoise:thread_noise added by the currently running thread (including
122	the scheduling overhead) added more 4769 ns. Summing up these values,
123	the Thread timer latency accounted for 30328 ns.
124
125	The primary reason for this high value is the wake-up path that was hit
126	twice during this case: when the bash-109109 was waking up a thread
127	and then when the timerlat thread was awakened. This information can
128	then be used as the starting point of a more fine-grained analysis.
129
130	Note that rtla timerlat was dispatched without changing timerlat tracer
131	threads' priority. That is generally not needed because these threads hava
132	priority FIFO:95 by default, which is a common priority used by real-time
133	kernel developers to analyze scheduling delays.
134
135	SEE ALSO
136	--------
137	rtla-timerlat\(1), rtla-timerlat-hist\(1)
138
139	timerlat tracer documentation: <https://www.kernel.org/doc/html/latest/trace/timerlat-tracer.html>
140
141	AUTHOR
142	------
143	Written by Daniel Bristot de Oliveira <bristot@kernel.org>
144
145	.. include:: common_appendix.rst