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

rtla/timerlat_top: Add timerlat user-space support

2023-06-13T20:38:51+00:00

Add the support for running timerlat threads in user-space. In this mode, enabled with -u/--user-threads, timerlat dispatches user-space processes that will loop in the timerlat_fd, measuring the overhead for going to user-space and then returning to the kernel - in addition to the existing measurements. Here is one example of the tool's output with -u enabled: $ sudo timerlat top -u -d 600 -q Timer Latency 0 00:10:01 | IRQ Timer Latency (us) | Thread Timer Latency (us) | Ret user Timer Latency (us) CPU COUNT | cur min avg max | cur min avg max | cur min avg max 0 #600001 | 0 0 0 3 | 2 1 2 9 | 3 2 3 15 1 #600001 | 0 0 0 2 | 2 1 2 13 | 2 2 3 18 2 #600001 | 0 0 0 10 | 2 1 2 16 | 3 2 3 20 3 #600001 | 0 0 0 7 | 2 1 2 10 | 3 2 3 11 4 #600000 | 0 0 0 16 | 2 1 2 41 | 3 2 3 58 5 #600000 | 0 0 0 3 | 2 1 2 10 | 3 2 3 13 6 #600000 | 0 0 0 5 | 2 1 2 7 | 3 2 3 10 7 #600000 | 0 0 0 1 | 2 1 2 7 | 3 2 3 10 The tuning setup like -p or -C work for the user-space threads as well. Link: https://lkml.kernel.org/r/758ad2292a0a1d884138d08219e1a0f572d257a2.1686066600.git.bristot@kernel.org Cc: William White Cc: Jonathan Corbet Tested-by: Juri Lelli Signed-off-by: Daniel Bristot de Oliveira Signed-off-by: Steven Rostedt (Google)

rtla: Start the tracers after creating all instances

2023-06-13T20:37:05+00:00

Group all start tracing after finishing creating all instances. The tracing instance starts first for the case of hitting a stop tracing while enabling other instances. The trace instance is the one with most valuable information. Link: https://lkml.kernel.org/r/67da7a703a56f75d7cd46568525145a65501a7e8.1686066600.git.bristot@kernel.org Cc: William White Cc: Jonathan Corbet Tested-by: Juri Lelli Signed-off-by: Daniel Bristot de Oliveira Signed-off-by: Steven Rostedt (Google)

rtla/timerlat: Give timerlat auto analysis its own instance

2023-06-13T20:31:35+00:00

Currently, the auto-analysis is attached to the timerlat top instance. The idea was to avoid creating another instance just for that, so one instance could be reused. The drawback is that, by doing so, the auto-analysis run for the entire session, consuming CPU time. On my 24 box CPUs for timerlat with a 100 us period consumed 50 % with auto analysis, but only 16 % without. By creating an instance for auto-analysis, we can keep the processing stopped until a stop tracing condition is hit. Once it happens, timerlat auto-analysis can use its own trace instance to parse only the end of the trace. By doing so, auto-analysis stop consuming cpu time when it is not needed. If the --aa-only is passed, the timerlat top instance is reused for auto analysis. Link: https://lkml.kernel.org/r/346b7168c1bae552a415715ec6d23c129a43bdb7.1686066600.git.bristot@kernel.org Cc: William White Cc: Jonathan Corbet Tested-by: Juri Lelli Signed-off-by: Daniel Bristot de Oliveira Signed-off-by: Steven Rostedt (Google)

rtla: Automatically move rtla to a house-keeping cpu

2023-06-13T20:30:13+00:00

When the user sets -c try to move rtla out of the , even without an -H option. This is useful to avoid having rtla interfering with the workload. This works by removing from rtla's current affinity. If rtla fails to move itself away it is not that of a problem as this is an automatic measure. Link: https://lkml.kernel.org/r/c54304d90c777310fb85a3e658d1449173759aab.1686066600.git.bristot@kernel.org Cc: William White Cc: Jonathan Corbet Tested-by: Juri Lelli Signed-off-by: Daniel Bristot de Oliveira Signed-off-by: Steven Rostedt (Google)

rtla: Change monitored_cpus from char * to cpu_set_t

2023-06-13T20:28:56+00:00

Use a cpumask instead of a char *, reducing memory footprint and code. No functional change, and in preparation for auto house-keeping. Link: https://lkml.kernel.org/r/54c46293261d13cb1042d0314486539eeb45fe5d.1686066600.git.bristot@kernel.org Cc: William White Cc: Jonathan Corbet Tested-by: Juri Lelli Signed-off-by: Daniel Bristot de Oliveira Signed-off-by: Steven Rostedt (Google)

rtla: Add --house-keeping option

2023-06-13T20:26:03+00:00

To avoid having rtla interfering with the measurement threads, add an option for the user to set the CPUs in which rtla should run. For instance: # rtla timerlat top -H 0 -c 1-7 Will place rtla in the CPU 0, while running the measurement threads in the CPU 1-7. Link: https://lkml.kernel.org/r/6a6c78a579a96ba8b02ae67ee1e0ba2cb5e03c4a.1686066600.git.bristot@kernel.org Cc: William White Cc: Jonathan Corbet Tested-by: Juri Lelli Suggested-by: Juri Lelli Signed-off-by: Daniel Bristot de Oliveira Signed-off-by: Steven Rostedt (Google)

rtla: Add -C cgroup support

2023-06-13T20:25:13+00:00

The -C option sets a cgroup to the tracer's threads. If the -C option is passed without arguments, the tracer's thread will inherit rtla's cgroup. Otherwise, the threads will be placed on the cgroup passed to the option. Link: https://lkml.kernel.org/r/cb051477331d292f17c08bf1d66f0e0384bbe5a5.1686066600.git.bristot@kernel.org Cc: William White Cc: Jonathan Corbet Tested-by: Juri Lelli Signed-off-by: Daniel Bristot de Oliveira Signed-off-by: Steven Rostedt (Google)

rtla/timerlat: Add auto-analysis only option

2023-04-25T23:26:17+00:00

Parsing and formating timerlat data might consume a reasonable amount of CPU time on very large systems, or when timerlat has a too short period. Add an option to run timerlat with auto-analysis enabled while skipping the statistics parsing. In this mode, rtla timerlat periodically checks if the tracing is on, going to sleep waiting for the stop tracing condition to stop tracing, or for the tracing session to finish. If the stop tracing condition is hit, the tool prints the auto analysis. Otherwise, the tool prints the max observed latency and exit. The max observed latency is captured via tracing_max_latency. Link: https://lore.kernel.org/linux-trace-devel/4dc514d1d5dc353c537a466a9b5af44c266b6da2.1680106912.git.bristot@kernel.org Cc: Jonathan Corbet Signed-off-by: Daniel Bristot de Oliveira Signed-off-by: Steven Rostedt (Google)

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)