summaryrefslogtreecommitdiff
path: root/Documentation/tools/rtla/rtla-timerlat-top.rst
blob: 1c321de1c171efdc01a52f86b40025e5e8a88239 (plain)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
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