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