1==================== 2rtla-timerlat-top 3==================== 4------------------------------------------- 5Measures the operating system timer latency 6------------------------------------------- 7 8:Manual section: 1 9 10SYNOPSIS 11======== 12**rtla timerlat top** [*OPTIONS*] ... 13 14DESCRIPTION 15=========== 16 17.. include:: common_timerlat_description.rst 18 19The **rtla timerlat top** displays a summary of the periodic output 20from the *timerlat* tracer. It also provides information for each 21operating system noise via the **osnoise:** tracepoints that can be 22seem with the option **-T**. 23 24OPTIONS 25======= 26 27.. include:: common_timerlat_options.rst 28 29.. include:: common_top_options.rst 30 31.. include:: common_options.rst 32 33EXAMPLE 34======= 35 36In the example below, the *timerlat* tracer is set to capture the stack trace at 37the IRQ handler, printing it to the buffer if the *Thread* timer latency is 38higher than *30 us*. It is also set to stop the session if a *Thread* timer 39latency higher than *30 us* is hit. Finally, it is set to save the trace 40buffer if the stop condition is hit:: 41 42 [root@alien ~]# rtla timerlat top -s 30 -t 30 -T 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 115In the trace, it is possible the notice that the *IRQ* timer latency was 116already 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 119up the timerlat thread, informed with the **osnoise:irq_noise** event, was 120also high and added more *12553 ns* to the Thread latency. Finally, the 121**osnoise:thread_noise** added by the currently running thread (including 122the scheduling overhead) added more *4769 ns*. Summing up these values, 123the *Thread* timer latency accounted for *30328 ns*. 124 125The primary reason for this high value is the wake-up path that was hit 126twice during this case: when the *bash-109109* was waking up a thread 127and then when the *timerlat* thread was awakened. This information can 128then be used as the starting point of a more fine-grained analysis. 129 130Note that **rtla timerlat** was dispatched without changing *timerlat* tracer 131threads' priority. That is generally not needed because these threads hava 132priority *FIFO:95* by default, which is a common priority used by real-time 133kernel developers to analyze scheduling delays. 134 135SEE 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 141AUTHOR 142------ 143Written by Daniel Bristot de Oliveira <bristot@kernel.org> 144 145.. include:: common_appendix.rst 146