1.. |tool| replace:: timerlat top 2 3==================== 4rtla-timerlat-top 5==================== 6------------------------------------------- 7Measures the operating system timer latency 8------------------------------------------- 9 10:Manual section: 1 11 12SYNOPSIS 13======== 14**rtla timerlat top** [*OPTIONS*] ... 15 16DESCRIPTION 17=========== 18 19.. include:: common_timerlat_description.rst 20 21The **rtla timerlat top** displays a summary of the periodic output 22from the *timerlat* tracer. It also provides information for each 23operating system noise via the **osnoise:** tracepoints that can be 24seem with the option **-T**. 25 26OPTIONS 27======= 28 29.. include:: common_timerlat_options.rst 30 31.. include:: common_top_options.rst 32 33.. include:: common_options.rst 34 35.. include:: common_timerlat_aa.rst 36 37**--aa-only** *us* 38 39 Set stop tracing conditions and run without collecting and displaying statistics. 40 Print the auto-analysis if the system hits the stop tracing condition. This option 41 is useful to reduce rtla timerlat CPU, enabling the debug without the overhead of 42 collecting the statistics. 43 44EXAMPLE 45======= 46 47In the example below, the timerlat tracer is dispatched in cpus *1-23* in the 48automatic trace mode, instructing the tracer to stop if a *40 us* latency or 49higher is found:: 50 51 # timerlat -a 40 -c 1-23 -q 52 Timer Latency 53 0 00:00:12 | IRQ Timer Latency (us) | Thread Timer Latency (us) 54 CPU COUNT | cur min avg max | cur min avg max 55 1 #12322 | 0 0 1 15 | 10 3 9 31 56 2 #12322 | 3 0 1 12 | 10 3 9 23 57 3 #12322 | 1 0 1 21 | 8 2 8 34 58 4 #12322 | 1 0 1 17 | 10 2 11 33 59 5 #12322 | 0 0 1 12 | 8 3 8 25 60 6 #12322 | 1 0 1 14 | 16 3 11 35 61 7 #12322 | 0 0 1 14 | 9 2 8 29 62 8 #12322 | 1 0 1 22 | 9 3 9 34 63 9 #12322 | 0 0 1 14 | 8 2 8 24 64 10 #12322 | 1 0 0 12 | 9 3 8 24 65 11 #12322 | 0 0 0 15 | 6 2 7 29 66 12 #12321 | 1 0 0 13 | 5 3 8 23 67 13 #12319 | 0 0 1 14 | 9 3 9 26 68 14 #12321 | 1 0 0 13 | 6 2 8 24 69 15 #12321 | 1 0 1 15 | 12 3 11 27 70 16 #12318 | 0 0 1 13 | 7 3 10 24 71 17 #12319 | 0 0 1 13 | 11 3 9 25 72 18 #12318 | 0 0 0 12 | 8 2 8 20 73 19 #12319 | 0 0 1 18 | 10 2 9 28 74 20 #12317 | 0 0 0 20 | 9 3 8 34 75 21 #12318 | 0 0 0 13 | 8 3 8 28 76 22 #12319 | 0 0 1 11 | 8 3 10 22 77 23 #12320 | 28 0 1 28 | 41 3 11 41 78 rtla timerlat hit stop tracing 79 ## CPU 23 hit stop tracing, analyzing it ## 80 IRQ handler delay: 27.49 us (65.52 %) 81 IRQ latency: 28.13 us 82 Timerlat IRQ duration: 9.59 us (22.85 %) 83 Blocking thread: 3.79 us (9.03 %) 84 objtool:49256 3.79 us 85 Blocking thread stacktrace 86 -> timerlat_irq 87 -> __hrtimer_run_queues 88 -> hrtimer_interrupt 89 -> __sysvec_apic_timer_interrupt 90 -> sysvec_apic_timer_interrupt 91 -> asm_sysvec_apic_timer_interrupt 92 -> _raw_spin_unlock_irqrestore 93 -> cgroup_rstat_flush_locked 94 -> cgroup_rstat_flush_irqsafe 95 -> mem_cgroup_flush_stats 96 -> mem_cgroup_wb_stats 97 -> balance_dirty_pages 98 -> balance_dirty_pages_ratelimited_flags 99 -> btrfs_buffered_write 100 -> btrfs_do_write_iter 101 -> vfs_write 102 -> __x64_sys_pwrite64 103 -> do_syscall_64 104 -> entry_SYSCALL_64_after_hwframe 105 ------------------------------------------------------------------------ 106 Thread latency: 41.96 us (100%) 107 108 The system has exit from idle latency! 109 Max timerlat IRQ latency from idle: 17.48 us in cpu 4 110 Saving trace to timerlat_trace.txt 111 112In this case, the major factor was the delay suffered by the *IRQ handler* 113that handles **timerlat** wakeup: *65.52%*. This can be caused by the 114current thread masking interrupts, which can be seen in the blocking 115thread stacktrace: the current thread (*objtool:49256*) disabled interrupts 116via *raw spin lock* operations inside mem cgroup, while doing write 117syscall in a btrfs file system. 118 119The raw trace is saved in the **timerlat_trace.txt** file for further analysis. 120 121Note that **rtla timerlat** was dispatched without changing *timerlat* tracer 122threads' priority. That is generally not needed because these threads have 123priority *FIFO:95* by default, which is a common priority used by real-time 124kernel developers to analyze scheduling delays. 125 126SEE ALSO 127-------- 128**rtla-timerlat**\(1), **rtla-timerlat-hist**\(1) 129 130*timerlat* tracer documentation: <https://www.kernel.org/doc/html/latest/trace/timerlat-tracer.html> 131 132AUTHOR 133------ 134Written by Daniel Bristot de Oliveira <bristot@kernel.org> 135 136.. include:: common_appendix.rst 137