135 lines · plain
1====================2rtla-timerlat-top3====================4-------------------------------------------5Measures the operating system timer latency6-------------------------------------------7 8:Manual section: 19 10SYNOPSIS11========12**rtla timerlat top** [*OPTIONS*] ...13 14DESCRIPTION15===========16 17.. include:: common_timerlat_description.rst18 19The **rtla timerlat top** displays a summary of the periodic output20from the *timerlat* tracer. It also provides information for each21operating system noise via the **osnoise:** tracepoints that can be22seem with the option **-T**.23 24OPTIONS25=======26 27.. include:: common_timerlat_options.rst28 29.. include:: common_top_options.rst30 31.. include:: common_options.rst32 33.. include:: common_timerlat_aa.rst34 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 option39 is useful to reduce rtla timerlat CPU, enabling the debug without the overhead of40 collecting the statistics.41 42EXAMPLE43=======44 45In the example below, the timerlat tracer is dispatched in cpus *1-23* in the46automatic trace mode, instructing the tracer to stop if a *40 us* latency or47higher is found::48 49 # timerlat -a 40 -c 1-23 -q50 Timer Latency51 0 00:00:12 | IRQ Timer Latency (us) | Thread Timer Latency (us)52 CPU COUNT | cur min avg max | cur min avg max53 1 #12322 | 0 0 1 15 | 10 3 9 3154 2 #12322 | 3 0 1 12 | 10 3 9 2355 3 #12322 | 1 0 1 21 | 8 2 8 3456 4 #12322 | 1 0 1 17 | 10 2 11 3357 5 #12322 | 0 0 1 12 | 8 3 8 2558 6 #12322 | 1 0 1 14 | 16 3 11 3559 7 #12322 | 0 0 1 14 | 9 2 8 2960 8 #12322 | 1 0 1 22 | 9 3 9 3461 9 #12322 | 0 0 1 14 | 8 2 8 2462 10 #12322 | 1 0 0 12 | 9 3 8 2463 11 #12322 | 0 0 0 15 | 6 2 7 2964 12 #12321 | 1 0 0 13 | 5 3 8 2365 13 #12319 | 0 0 1 14 | 9 3 9 2666 14 #12321 | 1 0 0 13 | 6 2 8 2467 15 #12321 | 1 0 1 15 | 12 3 11 2768 16 #12318 | 0 0 1 13 | 7 3 10 2469 17 #12319 | 0 0 1 13 | 11 3 9 2570 18 #12318 | 0 0 0 12 | 8 2 8 2071 19 #12319 | 0 0 1 18 | 10 2 9 2872 20 #12317 | 0 0 0 20 | 9 3 8 3473 21 #12318 | 0 0 0 13 | 8 3 8 2874 22 #12319 | 0 0 1 11 | 8 3 10 2275 23 #12320 | 28 0 1 28 | 41 3 11 4176 rtla timerlat hit stop tracing77 ## CPU 23 hit stop tracing, analyzing it ##78 IRQ handler delay: 27.49 us (65.52 %)79 IRQ latency: 28.13 us80 Timerlat IRQ duration: 9.59 us (22.85 %)81 Blocking thread: 3.79 us (9.03 %)82 objtool:49256 3.79 us83 Blocking thread stacktrace84 -> timerlat_irq85 -> __hrtimer_run_queues86 -> hrtimer_interrupt87 -> __sysvec_apic_timer_interrupt88 -> sysvec_apic_timer_interrupt89 -> asm_sysvec_apic_timer_interrupt90 -> _raw_spin_unlock_irqrestore91 -> cgroup_rstat_flush_locked92 -> cgroup_rstat_flush_irqsafe93 -> mem_cgroup_flush_stats94 -> mem_cgroup_wb_stats95 -> balance_dirty_pages96 -> balance_dirty_pages_ratelimited_flags97 -> btrfs_buffered_write98 -> btrfs_do_write_iter99 -> vfs_write100 -> __x64_sys_pwrite64101 -> do_syscall_64102 -> entry_SYSCALL_64_after_hwframe103 ------------------------------------------------------------------------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 4108 Saving trace to timerlat_trace.txt109 110In this case, the major factor was the delay suffered by the *IRQ handler*111that handles **timerlat** wakeup: *65.52%*. This can be caused by the112current thread masking interrupts, which can be seen in the blocking113thread stacktrace: the current thread (*objtool:49256*) disabled interrupts114via *raw spin lock* operations inside mem cgroup, while doing write115syscall in a btrfs file system.116 117The raw trace is saved in the **timerlat_trace.txt** file for further analysis.118 119Note that **rtla timerlat** was dispatched without changing *timerlat* tracer120threads' priority. That is generally not needed because these threads have121priority *FIFO:95* by default, which is a common priority used by real-time122kernel developers to analyze scheduling delays.123 124SEE ALSO125--------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 130AUTHOR131------132Written by Daniel Bristot de Oliveira <bristot@kernel.org>133 134.. include:: common_appendix.rst135