kernel/linux.git/tools/tracing/rtla/src/timerlat_top.c, branch v6.3

rtla/timerlat: Add auto-analysis support to timerlat top

2023-02-02T15:48:04+00:00

Currently, timerlat top displays the timerlat tracer latency results, saving the intuitive timerlat trace for the developer to analyze. This patch goes a step forward in the automaton of the scheduling latency analysis by providing a summary of the root cause of a latency higher than the passed "stop tracing" parameter if the trace stops. The output is intuitive enough for non-expert users to have a general idea of the root cause by looking at each factor's contribution percentage while keeping the technical detail in the output for more expert users to start an in dept debug or to correlate a root cause with an existing one. The terminology is in line with recent industry and academic publications to facilitate the understanding of both audiences. Here is one example of tool output: ----------------------------------------- %< ----------------------------------------------------- # taskset -c 0 timerlat -a 40 -c 1-23 -q Timer Latency 0 00:00:12 | IRQ Timer Latency (us) | Thread Timer Latency (us) CPU COUNT | cur min avg max | cur min avg max 1 #12322 | 0 0 1 15 | 10 3 9 31 2 #12322 | 3 0 1 12 | 10 3 9 23 3 #12322 | 1 0 1 21 | 8 2 8 34 4 #12322 | 1 0 1 17 | 10 2 11 33 5 #12322 | 0 0 1 12 | 8 3 8 25 6 #12322 | 1 0 1 14 | 16 3 11 35 7 #12322 | 0 0 1 14 | 9 2 8 29 8 #12322 | 1 0 1 22 | 9 3 9 34 9 #12322 | 0 0 1 14 | 8 2 8 24 10 #12322 | 1 0 0 12 | 9 3 8 24 11 #12322 | 0 0 0 15 | 6 2 7 29 12 #12321 | 1 0 0 13 | 5 3 8 23 13 #12319 | 0 0 1 14 | 9 3 9 26 14 #12321 | 1 0 0 13 | 6 2 8 24 15 #12321 | 1 0 1 15 | 12 3 11 27 16 #12318 | 0 0 1 13 | 7 3 10 24 17 #12319 | 0 0 1 13 | 11 3 9 25 18 #12318 | 0 0 0 12 | 8 2 8 20 19 #12319 | 0 0 1 18 | 10 2 9 28 20 #12317 | 0 0 0 20 | 9 3 8 34 21 #12318 | 0 0 0 13 | 8 3 8 28 22 #12319 | 0 0 1 11 | 8 3 10 22 23 #12320 | 28 0 1 28 | 41 3 11 41 rtla timerlat hit stop tracing ## CPU 23 hit stop tracing, analyzing it ## IRQ handler delay: 27.49 us (65.52 %) IRQ latency: 28.13 us Timerlat IRQ duration: 9.59 us (22.85 %) Blocking thread: 3.79 us (9.03 %) objtool:49256 3.79 us Blocking thread stacktrace -> timerlat_irq -> __hrtimer_run_queues -> hrtimer_interrupt -> __sysvec_apic_timer_interrupt -> sysvec_apic_timer_interrupt -> asm_sysvec_apic_timer_interrupt -> _raw_spin_unlock_irqrestore -> cgroup_rstat_flush_locked -> cgroup_rstat_flush_irqsafe -> mem_cgroup_flush_stats -> mem_cgroup_wb_stats -> balance_dirty_pages -> balance_dirty_pages_ratelimited_flags -> btrfs_buffered_write -> btrfs_do_write_iter -> vfs_write -> __x64_sys_pwrite64 -> do_syscall_64 -> entry_SYSCALL_64_after_hwframe ------------------------------------------------------------------------ Thread latency: 41.96 us (100%) The system has exit from idle latency! Max timerlat IRQ latency from idle: 17.48 us in cpu 4 Saving trace to timerlat_trace.txt ----------------------------------------- >% ----------------------------------------------------- In this case, the major factor was the delay suffered by the IRQ handler that handles timerlat wakeup: 65.52 %. This can be caused by the current thread masking interrupts, which can be seen in the blocking thread stacktrace: the current thread (objtool:49256) disabled interrupts via raw spin lock operations inside mem cgroup, while doing write syscall in a btrfs file system. A simple search for the function name on Google shows that this is a legit case for disabling the interrupts: cgroup: Use irqsave in cgroup_rstat_flush_locked() lore.kernel.org/linux-mm/20220301122143.1521823-2-bigeasy@linutronix.de/ The output also prints other reasons for the latency root cause, such as: - an IRQ that happened before the IRQ handler that caused delays - The interference from NMI, IRQ, Softirq, and Threads The details about how these factors affect the scheduling latency can be found here: https://bristot.me/demystifying-the-real-time-linux-latency/ Link: https://lkml.kernel.org/r/3d45f40e630317f51ac6d678e2d96d310e495729.1675179318.git.bristot@kernel.org Cc: Daniel Bristot de Oliveira Cc: Jonathan Corbet Signed-off-by: Daniel Bristot de Oliveira Signed-off-by: Steven Rostedt (Google)

rtla: Fix tracer name

2022-08-10T15:43:59+00:00

The correct tracer name is timerlat and not timelat. Link: https://lore.kernel.org/linux-trace-devel/20220808180343.22262-1-alexandre.vicenzi@suse.com Signed-off-by: Alexandre Vicenzi Signed-off-by: Steven Rostedt (Google)

rtla: Avoid record NULL pointer dereference

2022-05-26T19:18:28+00:00

Fix the following null/deref_null.cocci errors: ./tools/tracing/rtla/src/osnoise_hist.c:870:31-36: ERROR: record is NULL but dereferenced. ./tools/tracing/rtla/src/osnoise_top.c:650:31-36: ERROR: record is NULL but dereferenced. ./tools/tracing/rtla/src/timerlat_hist.c:905:31-36: ERROR: record is NULL but dereferenced. ./tools/tracing/rtla/src/timerlat_top.c:700:31-36: ERROR: record is NULL but dereferenced. "record" is NULL before calling osnoise_init_trace_tool. Add a tag "out_free" to avoid dereferring a NULL pointer. Link: https://lkml.kernel.org/r/ae0e4500d383db0884eb2820286afe34ca303778.1651247710.git.bristot@kernel.org Link: https://lore.kernel.org/r/20220408151406.34823-1-wanjiabing@vivo.com/ Cc: kael_w@yeah.net Cc: Daniel Bristot de Oliveira Fixes: 51d64c3a1819 ("rtla: Add -e/--event support") Acked-by: Daniel Bristot de Oliveira Signed-off-by: Wan Jiabing Signed-off-by: Daniel Bristot de Oliveira Signed-off-by: Steven Rostedt (Google)

rtla: Tools main loop cleanup

2022-03-15T18:36:50+00:00

I probably started using "do {} while();", but changed all but osnoise_top to "while(){};" leaving the ; behind. Cleanup the main loop code, making all tools use "while() {}" Changcheng Deng reported this problem, as reported by coccicheck: Fix the following coccicheck review: ./tools/tracing/rtla/src/timerlat_hist.c: 800: 2-3: Unneeded semicolon ./tools/tracing/rtla/src/osnoise_hist.c: 776: 2-3: Unneeded semicolon ./tools/tracing/rtla/src/timerlat_top.c: 596: 2-3: Unneeded semicolon Link: https://lkml.kernel.org/r/3c1642110aa87c396f5da4a037dabc72dbb9c601.1646247211.git.bristot@kernel.org Cc: Daniel Bristot de Oliveira Cc: Clark Williams Cc: Juri Lelli Cc: Jonathan Corbet Reported-by: Changcheng Deng Reported-by: Zeal Robot Signed-off-by: Daniel Bristot de Oliveira Signed-off-by: Steven Rostedt (Google)

rtla/timerlat: Add --dma-latency option

2022-03-15T18:36:50+00:00

Add the --dma-latency to set /dev/cpu_dma_latency to the specified value, this aims to avoid having exit from idle states latencies that could be influencing the analysis. Link: https://lkml.kernel.org/r/72ddb0d913459f13217086dadafad88a7c46dd28.1646247211.git.bristot@kernel.org Cc: Daniel Bristot de Oliveira Cc: Clark Williams Cc: Juri Lelli Cc: Jonathan Corbet Signed-off-by: Daniel Bristot de Oliveira Signed-off-by: Steven Rostedt (Google)

rtla: Check for trace off also in the trace instance

2022-03-15T18:36:50+00:00

With the addition of --trigger option, it is also possible to stop the trace from the -t tracing instance using the traceoff trigger. Make rtla tools to check if the trace is stopped also in the trace instance, stopping the execution of the tool. Link: https://lkml.kernel.org/r/59fc7c6f23dddd5c8b7ef1782cf3da51ea2ce0f5.1646247211.git.bristot@kernel.org Cc: Daniel Bristot de Oliveira Cc: Clark Williams Cc: Juri Lelli Cc: Jonathan Corbet Signed-off-by: Daniel Bristot de Oliveira Signed-off-by: Steven Rostedt (Google)

rtla: Add --filter support

2022-03-15T18:36:50+00:00

Add --filter option. This option enables a trace event filtering of the previous -e sys:event argument. This option is available for all current tools. Link: https://lkml.kernel.org/r/509d70b6348d3e5bcbf1f07ab725ce08d063149a.1646247211.git.bristot@kernel.org Cc: Daniel Bristot de Oliveira Cc: Clark Williams Cc: Juri Lelli Cc: Jonathan Corbet Signed-off-by: Daniel Bristot de Oliveira Signed-off-by: Steven Rostedt (Google)

rtla: Add --trigger support

2022-03-15T18:36:49+00:00

Add --trigger option. This option enables a trace event trigger to the previous -e sys:event argument, allowing some advanced tracing options. For instance, in a system with CPUs 2:23 isolated, it is possible to get a stack trace of thread wakeup targeting those CPUs while running osnoise with the following command line: # osnoise top -c 2-23 -a 50 -e sched:sched_wakeup --trigger="stacktrace if target_cpu >= 2" This option is available for all current tools. Link: https://lkml.kernel.org/r/07d2983d5f71261d4da89dbaf02efcad100ab8ee.1646247211.git.bristot@kernel.org Cc: Daniel Bristot de Oliveira Cc: Clark Williams Cc: Juri Lelli Cc: Jonathan Corbet Signed-off-by: Daniel Bristot de Oliveira Signed-off-by: Steven Rostedt (Google)

rtla: Add -e/--event support

2022-03-15T18:36:49+00:00

Add -e/--event option. This option enables an event in the trace (-t) session. The argument can be a specific event, e.g., -e sched:sched_switch, or all events of a system group, e.g., -e sched. Multiple -e are allowed. It is only active when -t or -a are set. This option is available for all current tools. Link: https://lkml.kernel.org/r/6a3b753be9b1e811953995f7f21a86918ad13390.1646247211.git.bristot@kernel.org Cc: Daniel Bristot de Oliveira Cc: Clark Williams Cc: Juri Lelli Cc: Jonathan Corbet Signed-off-by: Daniel Bristot de Oliveira Signed-off-by: Steven Rostedt (Google)

rtla/timerlat: Add the automatic trace option

2022-03-15T18:36:49+00:00

Add the -a/--auto option. This option sets some commonly used options while debugging the system. It aims to help users produce reports in the field, reducing the number of arguments passed to the tool in the first approach to a problem. It is equivalent to setting osnoise/stop_tracing_total_us and print_stack with the argument, and saving the trace to timerlat_trace.txt file if the trace is stopped automatically. Link: https://lkml.kernel.org/r/92438f7ef132c731f538cebdf77850300afe04a5.1646247211.git.bristot@kernel.org Cc: Daniel Bristot de Oliveira Cc: Clark Williams Cc: Juri Lelli Cc: Jonathan Corbet Signed-off-by: Daniel Bristot de Oliveira Signed-off-by: Steven Rostedt (Google)