0001 ====================
0002 rtla-timerlat-top
0003 ====================
0004 -------------------------------------------
0005 Measures the operating system timer latency
0006 -------------------------------------------
0007
0008 :Manual section: 1
0009
0010 SYNOPSIS
0011 ========
0012 **rtla timerlat top** [*OPTIONS*] ...
0013
0014 DESCRIPTION
0015 ===========
0016
0017 .. include:: common_timerlat_description.rst
0018
0019 The **rtla timerlat top** displays a summary of the periodic output
0020 from the *timerlat* tracer. It also provides information for each
0021 operating system noise via the **osnoise:** tracepoints that can be
0022 seem with the option **-T**.
0023
0024 OPTIONS
0025 =======
0026
0027 .. include:: common_timerlat_options.rst
0028
0029 .. include:: common_top_options.rst
0030
0031 .. include:: common_options.rst
0032
0033 EXAMPLE
0034 =======
0035
0036 In the example below, the *timerlat* tracer is set to capture the stack trace at
0037 the IRQ handler, printing it to the buffer if the *Thread* timer latency is
0038 higher than *30 us*. It is also set to stop the session if a *Thread* timer
0039 latency higher than *30 us* is hit. Finally, it is set to save the trace
0040 buffer if the stop condition is hit::
0041
0042 [root@alien ~]# rtla timerlat top -s 30 -t 30 -T
0043 Timer Latency
0044 0 00:00:59 | IRQ Timer Latency (us) | Thread Timer Latency (us)
0045 CPU COUNT | cur min avg max | cur min avg max
0046 0 #58634 | 1 0 1 10 | 11 2 10 23
0047 1 #58634 | 1 0 1 9 | 12 2 9 23
0048 2 #58634 | 0 0 1 11 | 10 2 9 23
0049 3 #58634 | 1 0 1 11 | 11 2 9 24
0050 4 #58634 | 1 0 1 10 | 11 2 9 26
0051 5 #58634 | 1 0 1 8 | 10 2 9 25
0052 6 #58634 | 12 0 1 12 | 30 2 10 30 <--- CPU with spike
0053 7 #58634 | 1 0 1 9 | 11 2 9 23
0054 8 #58633 | 1 0 1 9 | 11 2 9 26
0055 9 #58633 | 1 0 1 9 | 10 2 9 26
0056 10 #58633 | 1 0 1 13 | 11 2 9 28
0057 11 #58633 | 1 0 1 13 | 12 2 9 24
0058 12 #58633 | 1 0 1 8 | 10 2 9 23
0059 13 #58633 | 1 0 1 10 | 10 2 9 22
0060 14 #58633 | 1 0 1 18 | 12 2 9 27
0061 15 #58633 | 1 0 1 10 | 11 2 9 28
0062 16 #58633 | 0 0 1 11 | 7 2 9 26
0063 17 #58633 | 1 0 1 13 | 10 2 9 24
0064 18 #58633 | 1 0 1 9 | 13 2 9 22
0065 19 #58633 | 1 0 1 10 | 11 2 9 23
0066 20 #58633 | 1 0 1 12 | 11 2 9 28
0067 21 #58633 | 1 0 1 14 | 11 2 9 24
0068 22 #58633 | 1 0 1 8 | 11 2 9 22
0069 23 #58633 | 1 0 1 10 | 11 2 9 27
0070 timerlat hit stop tracing
0071 saving trace to timerlat_trace.txt
0072 [root@alien bristot]# tail -60 timerlat_trace.txt
0073 [...]
0074 timerlat/5-79755 [005] ....... 426.271226: #58634 context thread timer_latency 10823 ns
0075 sh-109404 [006] dnLh213 426.271247: #58634 context irq timer_latency 12505 ns
0076 sh-109404 [006] dNLh313 426.271258: irq_noise: local_timer:236 start 426.271245463 duration 12553 ns
0077 sh-109404 [006] d...313 426.271263: thread_noise: sh:109404 start 426.271245853 duration 4769 ns
0078 timerlat/6-79756 [006] ....... 426.271264: #58634 context thread timer_latency 30328 ns
0079 timerlat/6-79756 [006] ....1.. 426.271265: <stack trace>
0080 => timerlat_irq
0081 => __hrtimer_run_queues
0082 => hrtimer_interrupt
0083 => __sysvec_apic_timer_interrupt
0084 => sysvec_apic_timer_interrupt
0085 => asm_sysvec_apic_timer_interrupt
0086 => _raw_spin_unlock_irqrestore <---- spinlock that disabled interrupt.
0087 => try_to_wake_up
0088 => autoremove_wake_function
0089 => __wake_up_common
0090 => __wake_up_common_lock
0091 => ep_poll_callback
0092 => __wake_up_common
0093 => __wake_up_common_lock
0094 => fsnotify_add_event
0095 => inotify_handle_inode_event
0096 => fsnotify
0097 => __fsnotify_parent
0098 => __fput
0099 => task_work_run
0100 => exit_to_user_mode_prepare
0101 => syscall_exit_to_user_mode
0102 => do_syscall_64
0103 => entry_SYSCALL_64_after_hwframe
0104 => 0x7265000001378c
0105 => 0x10000cea7
0106 => 0x25a00000204a
0107 => 0x12e302d00000000
0108 => 0x19b51010901b6
0109 => 0x283ce00726500
0110 => 0x61ea308872
0111 => 0x00000fe3
0112 bash-109109 [007] d..h... 426.271265: #58634 context irq timer_latency 1211 ns
0113 timerlat/6-79756 [006] ....... 426.271267: timerlat_main: stop tracing hit on cpu 6
0114
0115 In the trace, it is possible the notice that the *IRQ* timer latency was
0116 already high, accounting *12505 ns*. The IRQ delay was caused by the
0117 *bash-109109* process that disabled IRQs in the wake-up path
0118 (*_try_to_wake_up()* function). The duration of the IRQ handler that woke
0119 up the timerlat thread, informed with the **osnoise:irq_noise** event, was
0120 also high and added more *12553 ns* to the Thread latency. Finally, the
0121 **osnoise:thread_noise** added by the currently running thread (including
0122 the scheduling overhead) added more *4769 ns*. Summing up these values,
0123 the *Thread* timer latency accounted for *30328 ns*.
0124
0125 The primary reason for this high value is the wake-up path that was hit
0126 twice during this case: when the *bash-109109* was waking up a thread
0127 and then when the *timerlat* thread was awakened. This information can
0128 then be used as the starting point of a more fine-grained analysis.
0129
0130 Note that **rtla timerlat** was dispatched without changing *timerlat* tracer
0131 threads' priority. That is generally not needed because these threads hava
0132 priority *FIFO:95* by default, which is a common priority used by real-time
0133 kernel developers to analyze scheduling delays.
0134
0135 SEE ALSO
0136 --------
0137 **rtla-timerlat**\(1), **rtla-timerlat-hist**\(1)
0138
0139 *timerlat* tracer documentation: <https://www.kernel.org/doc/html/latest/trace/timerlat-tracer.html>
0140
0141 AUTHOR
0142 ------
0143 Written by Daniel Bristot de Oliveira <bristot@kernel.org>
0144
0145 .. include:: common_appendix.rst
