diff options
| -rw-r--r-- | Documentation/tools/rtla/common_timerlat_aa.rst | 7 | ||||
| -rw-r--r-- | Documentation/tools/rtla/index.rst | 1 | ||||
| -rw-r--r-- | Documentation/tools/rtla/rtla-hwnoise.rst | 107 | ||||
| -rw-r--r-- | Documentation/tools/rtla/rtla-timerlat-top.rst | 164 | ||||
| -rw-r--r-- | tools/tracing/rtla/Makefile | 2 | ||||
| -rw-r--r-- | tools/tracing/rtla/src/osnoise.c | 117 | ||||
| -rw-r--r-- | tools/tracing/rtla/src/osnoise.h | 7 | ||||
| -rw-r--r-- | tools/tracing/rtla/src/osnoise_hist.c | 9 | ||||
| -rw-r--r-- | tools/tracing/rtla/src/osnoise_top.c | 84 | ||||
| -rw-r--r-- | tools/tracing/rtla/src/rtla.c | 4 | ||||
| -rw-r--r-- | tools/tracing/rtla/src/timerlat_aa.c | 990 | ||||
| -rw-r--r-- | tools/tracing/rtla/src/timerlat_aa.h | 12 | ||||
| -rw-r--r-- | tools/tracing/rtla/src/timerlat_top.c | 46 | ||||
| -rw-r--r-- | tools/tracing/rtla/src/utils.h | 3 | ||||
| -rw-r--r-- | tools/verification/rv/src/in_kernel.c | 2 |
15 files changed, 1442 insertions, 113 deletions
diff --git a/Documentation/tools/rtla/common_timerlat_aa.rst b/Documentation/tools/rtla/common_timerlat_aa.rst new file mode 100644 index 000000000000..077029e6b289 --- /dev/null +++ b/Documentation/tools/rtla/common_timerlat_aa.rst @@ -0,0 +1,7 @@ +**--dump-tasks** + + prints the task running on all CPUs if stop conditions are met (depends on !--no-aa) + +**--no-aa** + + disable auto-analysis, reducing rtla timerlat cpu usage diff --git a/Documentation/tools/rtla/index.rst b/Documentation/tools/rtla/index.rst index 840f0bf3e803..05d2652e4072 100644 --- a/Documentation/tools/rtla/index.rst +++ b/Documentation/tools/rtla/index.rst @@ -17,6 +17,7 @@ behavior on specific hardware. rtla-timerlat rtla-timerlat-hist rtla-timerlat-top + rtla-hwnoise .. only:: subproject and html diff --git a/Documentation/tools/rtla/rtla-hwnoise.rst b/Documentation/tools/rtla/rtla-hwnoise.rst new file mode 100644 index 000000000000..fb1c52bbc00b --- /dev/null +++ b/Documentation/tools/rtla/rtla-hwnoise.rst @@ -0,0 +1,107 @@ +.. SPDX-License-Identifier: GPL-2.0 + +============ +rtla-hwnoise +============ +------------------------------------------ +Detect and quantify hardware-related noise +------------------------------------------ + +:Manual section: 1 + +SYNOPSIS +======== + +**rtla hwnoise** [*OPTIONS*] + +DESCRIPTION +=========== + +**rtla hwnoise** collects the periodic summary from the *osnoise* tracer +running with *interrupts disabled*. By disabling interrupts, and the scheduling +of threads as a consequence, only non-maskable interrupts and hardware-related +noise is allowed. + +The tool also allows the configurations of the *osnoise* tracer and the +collection of the tracer output. + +OPTIONS +======= +.. include:: common_osnoise_options.rst + +.. include:: common_top_options.rst + +.. include:: common_options.rst + +EXAMPLE +======= +In the example below, the **rtla hwnoise** tool is set to run on CPUs *1-7* +on a system with 8 cores/16 threads with hyper-threading enabled. + +The tool is set to detect any noise higher than *one microsecond*, +to run for *ten minutes*, displaying a summary of the report at the +end of the session:: + + # rtla hwnoise -c 1-7 -T 1 -d 10m -q + Hardware-related Noise + duration: 0 00:10:00 | time is in us + CPU Period Runtime Noise % CPU Aval Max Noise Max Single HW NMI + 1 #599 599000000 138 99.99997 3 3 4 74 + 2 #599 599000000 85 99.99998 3 3 4 75 + 3 #599 599000000 86 99.99998 4 3 6 75 + 4 #599 599000000 81 99.99998 4 4 2 75 + 5 #599 599000000 85 99.99998 2 2 2 75 + 6 #599 599000000 76 99.99998 2 2 0 75 + 7 #599 599000000 77 99.99998 3 3 0 75 + + +The first column shows the *CPU*, and the second column shows how many +*Periods* the tool ran during the session. The *Runtime* is the time +the tool effectively runs on the CPU. The *Noise* column is the sum of +all noise that the tool observed, and the *% CPU Aval* is the relation +between the *Runtime* and *Noise*. + +The *Max Noise* column is the maximum hardware noise the tool detected in a +single period, and the *Max Single* is the maximum single noise seen. + +The *HW* and *NMI* columns show the total number of *hardware* and *NMI* noise +occurrence observed by the tool. + +For example, *CPU 3* ran *599* periods of *1 second Runtime*. The CPU received +*86 us* of noise during the entire execution, leaving *99.99997 %* of CPU time +for the application. In the worst single period, the CPU caused *4 us* of +noise to the application, but it was certainly caused by more than one single +noise, as the *Max Single* noise was of *3 us*. The CPU has *HW noise,* at a +rate of *six occurrences*/*ten minutes*. The CPU also has *NMIs*, at a higher +frequency: around *seven per second*. + +The tool should report *0* hardware-related noise in the ideal situation. +For example, by disabling hyper-threading to remove the hardware noise, +and disabling the TSC watchdog to remove the NMI (it is possible to identify +this using tracing options of **rtla hwnoise**), it was possible to reach +the ideal situation in the same hardware:: + + # rtla hwnoise -c 1-7 -T 1 -d 10m -q + Hardware-related Noise + duration: 0 00:10:00 | time is in us + CPU Period Runtime Noise % CPU Aval Max Noise Max Single HW NMI + 1 #599 599000000 0 100.00000 0 0 0 0 + 2 #599 599000000 0 100.00000 0 0 0 0 + 3 #599 599000000 0 100.00000 0 0 0 0 + 4 #599 599000000 0 100.00000 0 0 0 0 + 5 #599 599000000 0 100.00000 0 0 0 0 + 6 #599 599000000 0 100.00000 0 0 0 0 + 7 #599 599000000 0 100.00000 0 0 0 0 + +SEE ALSO +======== + +**rtla-osnoise**\(1) + +Osnoise tracer documentation: <https://www.kernel.org/doc/html/latest/trace/osnoise-tracer.html> + +AUTHOR +====== +Written by Daniel Bristot de Oliveira <bristot@kernel.org> + +.. include:: common_appendix.rst diff --git a/Documentation/tools/rtla/rtla-timerlat-top.rst b/Documentation/tools/rtla/rtla-timerlat-top.rst index 7c4e4b109493..73799c1150ad 100644 --- a/Documentation/tools/rtla/rtla-timerlat-top.rst +++ b/Documentation/tools/rtla/rtla-timerlat-top.rst @@ -30,102 +30,84 @@ OPTIONS .. include:: common_options.rst +.. include:: common_timerlat_aa.rst + EXAMPLE ======= -In the example below, the *timerlat* tracer is set to capture the stack trace at -the IRQ handler, printing it to the buffer if the *Thread* timer latency is -higher than *30 us*. It is also set to stop the session if a *Thread* timer -latency higher than *30 us* is hit. Finally, it is set to save the trace -buffer if the stop condition is hit:: +In the example below, the timerlat tracer is dispatched in cpus *1-23* in the +automatic trace mode, instructing the tracer to stop if a *40 us* latency or +higher is found:: - [root@alien ~]# rtla timerlat top -s 30 -T 30 -t - Timer Latency - 0 00:00:59 | IRQ Timer Latency (us) | Thread Timer Latency (us) + # 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 - 0 #58634 | 1 0 1 10 | 11 2 10 23 - 1 #58634 | 1 0 1 9 | 12 2 9 23 - 2 #58634 | 0 0 1 11 | 10 2 9 23 - 3 #58634 | 1 0 1 11 | 11 2 9 24 - 4 #58634 | 1 0 1 10 | 11 2 9 26 - 5 #58634 | 1 0 1 8 | 10 2 9 25 - 6 #58634 | 12 0 1 12 | 30 2 10 30 <--- CPU with spike - 7 #58634 | 1 0 1 9 | 11 2 9 23 - 8 #58633 | 1 0 1 9 | 11 2 9 26 - 9 #58633 | 1 0 1 9 | 10 2 9 26 - 10 #58633 | 1 0 1 13 | 11 2 9 28 - 11 #58633 | 1 0 1 13 | 12 2 9 24 - 12 #58633 | 1 0 1 8 | 10 2 9 23 - 13 #58633 | 1 0 1 10 | 10 2 9 22 - 14 #58633 | 1 0 1 18 | 12 2 9 27 - 15 #58633 | 1 0 1 10 | 11 2 9 28 - 16 #58633 | 0 0 1 11 | 7 2 9 26 - 17 #58633 | 1 0 1 13 | 10 2 9 24 - 18 #58633 | 1 0 1 9 | 13 2 9 22 - 19 #58633 | 1 0 1 10 | 11 2 9 23 - 20 #58633 | 1 0 1 12 | 11 2 9 28 - 21 #58633 | 1 0 1 14 | 11 2 9 24 - 22 #58633 | 1 0 1 8 | 11 2 9 22 - 23 #58633 | 1 0 1 10 | 11 2 9 27 - timerlat hit stop tracing - saving trace to timerlat_trace.txt - [root@alien bristot]# tail -60 timerlat_trace.txt - [...] - timerlat/5-79755 [005] ....... 426.271226: #58634 context thread timer_latency 10823 ns - sh-109404 [006] dnLh213 426.271247: #58634 context irq timer_latency 12505 ns - sh-109404 [006] dNLh313 426.271258: irq_noise: local_timer:236 start 426.271245463 duration 12553 ns - sh-109404 [006] d...313 426.271263: thread_noise: sh:109404 start 426.271245853 duration 4769 ns - timerlat/6-79756 [006] ....... 426.271264: #58634 context thread timer_latency 30328 ns - timerlat/6-79756 [006] ....1.. 426.271265: <stack trace> - => timerlat_irq - => __hrtimer_run_queues - => hrtimer_interrupt - => __sysvec_apic_timer_interrupt - => sysvec_apic_timer_interrupt - => asm_sysvec_apic_timer_interrupt - => _raw_spin_unlock_irqrestore <---- spinlock that disabled interrupt. - => try_to_wake_up - => autoremove_wake_function - => __wake_up_common - => __wake_up_common_lock - => ep_poll_callback - => __wake_up_common - => __wake_up_common_lock - => fsnotify_add_event - => inotify_handle_inode_event - => fsnotify - => __fsnotify_parent - => __fput - => task_work_run - => exit_to_user_mode_prepare - => syscall_exit_to_user_mode - => do_syscall_64 - => entry_SYSCALL_64_after_hwframe - => 0x7265000001378c - => 0x10000cea7 - => 0x25a00000204a - => 0x12e302d00000000 - => 0x19b51010901b6 - => 0x283ce00726500 - => 0x61ea308872 - => 0x00000fe3 - bash-109109 [007] d..h... 426.271265: #58634 context irq timer_latency 1211 ns - timerlat/6-79756 [006] ....... 426.271267: timerlat_main: stop tracing hit on cpu 6 - -In the trace, it is possible the notice that the *IRQ* timer latency was -already high, accounting *12505 ns*. The IRQ delay was caused by the -*bash-109109* process that disabled IRQs in the wake-up path -(*_try_to_wake_up()* function). The duration of the IRQ handler that woke -up the timerlat thread, informed with the **osnoise:irq_noise** event, was -also high and added more *12553 ns* to the Thread latency. Finally, the -**osnoise:thread_noise** added by the currently running thread (including -the scheduling overhead) added more *4769 ns*. Summing up these values, -the *Thread* timer latency accounted for *30328 ns*. - -The primary reason for this high value is the wake-up path that was hit -twice during this case: when the *bash-109109* was waking up a thread -and then when the *timerlat* thread was awakened. This information can -then be used as the starting point of a more fine-grained analysis. + 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. + +The raw trace is saved in the **timerlat_trace.txt** file for further analysis. Note that **rtla timerlat** was dispatched without changing *timerlat* tracer threads' priority. That is generally not needed because these threads hava diff --git a/tools/tracing/rtla/Makefile b/tools/tracing/rtla/Makefile index 22e28b76f800..2456a399eb9a 100644 --- a/tools/tracing/rtla/Makefile +++ b/tools/tracing/rtla/Makefile @@ -119,6 +119,8 @@ install: doc_install $(STRIP) $(DESTDIR)$(BINDIR)/rtla @test ! -f $(DESTDIR)$(BINDIR)/osnoise || rm $(DESTDIR)$(BINDIR)/osnoise ln -s rtla $(DESTDIR)$(BINDIR)/osnoise + @test ! -f $(DESTDIR)$(BINDIR)/hwnoise || rm $(DESTDIR)$(BINDIR)/hwnoise + ln -s rtla $(DESTDIR)$(BINDIR)/hwnoise @test ! -f $(DESTDIR)$(BINDIR)/timerlat || rm $(DESTDIR)$(BINDIR)/timerlat ln -s rtla $(DESTDIR)$(BINDIR)/timerlat diff --git a/tools/tracing/rtla/src/osnoise.c b/tools/tracing/rtla/src/osnoise.c index 4dee343909b1..3ca7a3853943 100644 --- a/tools/tracing/rtla/src/osnoise.c +++ b/tools/tracing/rtla/src/osnoise.c @@ -734,6 +734,113 @@ void osnoise_put_tracing_thresh(struct osnoise_context *context) context->orig_tracing_thresh = OSNOISE_OPTION_INIT_VAL; } +static int osnoise_options_get_option(char *option) +{ + char *options = tracefs_instance_file_read(NULL, "osnoise/options", NULL); + char no_option[128]; + int retval = 0; + char *opt; + + if (!options) + return OSNOISE_OPTION_INIT_VAL; + + /* + * Check first if the option is disabled. + */ + snprintf(no_option, sizeof(no_option), "NO_%s", option); + + opt = strstr(options, no_option); + if (opt) + goto out_free; + + /* + * Now that it is not disabled, if the string is there, it is + * enabled. If the string is not there, the option does not exist. + */ + opt = strstr(options, option); + if (opt) + retval = 1; + else + retval = OSNOISE_OPTION_INIT_VAL; + +out_free: + free(options); + return retval; +} + +static int osnoise_options_set_option(char *option, bool onoff) +{ + char no_option[128]; + + if (onoff) + return tracefs_instance_file_write(NULL, "osnoise/options", option); + + snprintf(no_option, sizeof(no_option), "NO_%s", option); + + return tracefs_instance_file_write(NULL, "osnoise/options", no_option); +} + +static int osnoise_get_irq_disable(struct osnoise_context *context) +{ + if (context->opt_irq_disable != OSNOISE_OPTION_INIT_VAL) + return context->opt_irq_disable; + + if (context->orig_opt_irq_disable != OSNOISE_OPTION_INIT_VAL) + return context->orig_opt_irq_disable; + + context->orig_opt_irq_disable = osnoise_options_get_option("OSNOISE_IRQ_DISABLE"); + + return context->orig_opt_irq_disable; +} + +int osnoise_set_irq_disable(struct osnoise_context *context, bool onoff) +{ + int opt_irq_disable = osnoise_get_irq_disable(context); + int retval; + + if (opt_irq_disable == OSNOISE_OPTION_INIT_VAL) + return -1; + + if (opt_irq_disable == onoff) + return 0; + + retval = osnoise_options_set_option("OSNOISE_IRQ_DISABLE", onoff); + if (retval < 0) + return -1; + + context->opt_irq_disable = onoff; + + return 0; +} + +static void osnoise_restore_irq_disable(struct osnoise_context *context) +{ + int retval; + + if (context->orig_opt_irq_disable == OSNOISE_OPTION_INIT_VAL) + return; + + if (context->orig_opt_irq_disable == context->opt_irq_disable) + goto out_done; + + retval = osnoise_options_set_option("OSNOISE_IRQ_DISABLE", context->orig_opt_irq_disable); + if (retval < 0) + err_msg("Could not restore original OSNOISE_IRQ_DISABLE option\n"); + +out_done: + context->orig_opt_irq_disable = OSNOISE_OPTION_INIT_VAL; +} + +static void osnoise_put_irq_disable(struct osnoise_context *context) +{ + osnoise_restore_irq_disable(context); + + if (context->orig_opt_irq_disable == OSNOISE_OPTION_INIT_VAL) + return; + + context->orig_opt_irq_disable = OSNOISE_OPTION_INIT_VAL; +} + /* * enable_osnoise - enable osnoise tracer in the trace_instance */ @@ -798,6 +905,9 @@ struct osnoise_context *osnoise_context_alloc(void) context->orig_tracing_thresh = OSNOISE_OPTION_INIT_VAL; context->tracing_thresh = OSNOISE_OPTION_INIT_VAL; + context->orig_opt_irq_disable = OSNOISE_OPTION_INIT_VAL; + context->opt_irq_disable = OSNOISE_OPTION_INIT_VAL; + osnoise_get_context(context); return context; @@ -824,6 +934,7 @@ void osnoise_put_context(struct osnoise_context *context) osnoise_put_timerlat_period_us(context); osnoise_put_print_stack(context); osnoise_put_tracing_thresh(context); + osnoise_put_irq_disable(context); free(context); } @@ -958,3 +1069,9 @@ usage: osnoise_usage(1); exit(1); } + +int hwnoise_main(int argc, char *argv[]) +{ + osnoise_top_main(argc, argv); + exit(0); +} diff --git a/tools/tracing/rtla/src/osnoise.h b/tools/tracing/rtla/src/osnoise.h index 04a4384cc544..4dcf22ccd704 100644 --- a/tools/tracing/rtla/src/osnoise.h +++ b/tools/tracing/rtla/src/osnoise.h @@ -38,6 +38,10 @@ struct osnoise_context { /* -1 as init value because 0 is disabled */ long long orig_print_stack; long long print_stack; + + /* -1 as init value because 0 is off */ + int orig_opt_irq_disable; + int opt_irq_disable; }; /* @@ -79,6 +83,8 @@ void osnoise_restore_print_stack(struct osnoise_context *context); int osnoise_set_print_stack(struct osnoise_context *context, long long print_stack); +int osnoise_set_irq_disable(struct osnoise_context *context, bool onoff); + /* * osnoise_tool - osnoise based tool definition. */ @@ -97,3 +103,4 @@ struct osnoise_tool *osnoise_init_trace_tool(char *tracer); int osnoise_hist_main(int argc, char *argv[]); int osnoise_top_main(int argc, char **argv); int osnoise_main(int argc, char **argv); +int hwnoise_main(int argc, char **argv); diff --git a/tools/tracing/rtla/src/osnoise_hist.c b/tools/tracing/rtla/src/osnoise_hist.c index 5d7ea479ac89..13e1233690bb 100644 --- a/tools/tracing/rtla/src/osnoise_hist.c +++ b/tools/tracing/rtla/src/osnoise_hist.c @@ -121,6 +121,7 @@ static void osnoise_hist_update_multiple(struct osnoise_tool *tool, int cpu, { struct osnoise_hist_params *params = tool->params; struct osnoise_hist_data *data = tool->data; + unsigned long long total_duration; int entries = data->entries; int bucket; int *hist; @@ -131,10 +132,12 @@ static void osnoise_hist_update_multiple(struct osnoise_tool *tool, int cpu, if (data->bucket_size) bucket = duration / data->bucket_size; + total_duration = duration * count; + hist = data->hist[cpu].samples; data->hist[cpu].count += count; update_min(&data->hist[cpu].min_sample, &duration); - update_sum(&data->hist[cpu].sum_sample, &duration); + update_sum(&data->hist[cpu].sum_sample, &total_duration); update_max(&data->hist[cpu].max_sample, &duration); if (bucket < entries) @@ -332,8 +335,8 @@ osnoise_print_summary(struct osnoise_hist_params *params, continue; if (data->hist[cpu].count) - trace_seq_printf(trace->seq, "%9llu ", - data->hist[cpu].sum_sample / data->hist[cpu].count); + trace_seq_printf(trace->seq, "%9.2f ", + ((double) data->hist[cpu].sum_sample) / data->hist[cpu].count); else trace_seq_printf(trace->seq, " - "); } diff --git a/tools/tracing/rtla/src/osnoise_top.c b/tools/tracing/rtla/src/osnoise_top.c index 76479bfb2922..562f2e4b18c5 100644 --- a/tools/tracing/rtla/src/osnoise_top.c +++ b/tools/tracing/rtla/src/osnoise_top.c @@ -14,6 +14,11 @@ #include "osnoise.h" #include "utils.h" +enum osnoise_mode { + MODE_OSNOISE = 0, + MODE_HWNOISE +}; + /* * osnoise top parameters */ @@ -32,6 +37,7 @@ struct osnoise_top_params { int set_sched; struct sched_attr sched_param; struct trace_events *events; + enum osnoise_mode mode; }; struct osnoise_top_cpu { @@ -143,15 +149,23 @@ osnoise_top_handler(struct trace_seq *s, struct tep_record *record, */ static void osnoise_top_header(struct osnoise_tool *top) { + struct osnoise_top_params *params = top->params; struct trace_seq *s = top->trace.seq; char duration[26]; get_duration(top->start_time, duration, sizeof(duration)); trace_seq_printf(s, "\033[2;37;40m"); - trace_seq_printf(s, " Operating System Noise"); - trace_seq_printf(s, " "); - trace_seq_printf(s, " "); + trace_seq_printf(s, " "); + + if (params->mode == MODE_OSNOISE) { + trace_seq_printf(s, "Operating System Noise"); + trace_seq_printf(s, " "); + } else if (params->mode == MODE_HWNOISE) { + trace_seq_printf(s, "Hardware-related Noise"); + } + + trace_seq_printf(s, " "); trace_seq_printf(s, "\033[0;0;0m"); trace_seq_printf(s, "\n"); @@ -162,7 +176,14 @@ static void osnoise_top_header(struct osnoise_tool *top) trace_seq_printf(s, " Noise "); trace_seq_printf(s, " %% CPU Aval "); trace_seq_printf(s, " Max Noise Max Single "); - trace_seq_printf(s, " HW NMI IRQ Softirq Thread"); + trace_seq_printf(s, " HW NMI"); + + if (params->mode == MODE_HWNOISE) + goto eol; + + trace_seq_printf(s, " IRQ Softirq Thread"); + +eol: trace_seq_printf(s, "\033[0;0;0m"); trace_seq_printf(s, "\n"); } @@ -181,6 +202,7 @@ static void clear_terminal(struct trace_seq *seq) */ static void osnoise_top_print(struct osnoise_tool *tool, int cpu) { + struct osnoise_top_params *params = tool->params; struct trace_seq *s = tool->trace.seq; struct osnoise_top_cpu *cpu_data; struct osnoise_top_data *data; @@ -205,6 +227,12 @@ static void osnoise_top_print(struct osnoise_tool *tool, int cpu) trace_seq_printf(s, "%12llu ", cpu_data->hw_count); trace_seq_printf(s, "%12llu ", cpu_data->nmi_count); + + if (params->mode == MODE_HWNOISE) { + trace_seq_printf(s, "\n"); + return; + } + trace_seq_printf(s, "%12llu ", cpu_data->irq_count); trace_seq_printf(s, "%12llu ", cpu_data->softirq_count); trace_seq_printf(s, "%12llu\n", cpu_data->thread_count); @@ -241,12 +269,12 @@ osnoise_print_stats(struct osnoise_top_params *params, struct osnoise_tool *top) /* * osnoise_top_usage - prints osnoise top usage message */ -void osnoise_top_usage(char *usage) +static void osnoise_top_usage(struct osnoise_top_params *params, char *usage) { int i; static const char * const msg[] = { - " usage: rtla osnoise [top] [-h] [-q] [-D] [-d s] [-a us] [-p us] [-r us] [-s us] [-S us] \\", + " [-h] [-q] [-D] [-d s] [-a us] [-p us] [-r us] [-s us] [-S us] \\", " [-T us] [-t[=file]] [-e sys[:event]] [--filter <filter>] [--trigger <trigger>] \\", " [-c cpu-list] [-P priority]", "", @@ -277,9 +305,22 @@ void osnoise_top_usage(char *usage) if (usage) fprintf(stderr, "%s\n", usage); - fprintf(stderr, "rtla osnoise top: a per-cpu summary of the OS noise (version %s)\n", + if (params->mode == MODE_OSNOISE) { + fprintf(stderr, + "rtla osnoise top: a per-cpu summary of the OS noise (version %s)\n", VERSION); + fprintf(stderr, " usage: rtla osnoise [top]"); + } + + if (params->mode == MODE_HWNOISE) { + fprintf(stderr, + "rtla hwnoise: a summary of hardware-related noise (version %s)\n", + VERSION); + + fprintf(stderr, " usage: rtla hwnoise"); + } + for (i = 0; msg[i]; i++) fprintf(stderr, "%s\n", msg[i]); exit(1); @@ -299,6 +340,9 @@ struct osnoise_top_params *osnoise_top_parse_args(int argc, char **argv) if (!params) exit(1); + if (strcmp(argv[0], "hwnoise") == 0) + params->mode = MODE_HWNOISE; + while (1) { static struct option long_options[] = { {"auto", required_argument, 0, 'a'}, @@ -345,7 +389,7 @@ struct osnoise_top_params *osnoise_top_parse_args(int argc, char **argv) case 'c': retval = parse_cpu_list(optarg, ¶ms->monitored_cpus); if (retval) - osnoise_top_usage("\nInvalid -c cpu list\n"); + osnoise_top_usage(params, "\nInvalid -c cpu list\n"); params->cpus = optarg; break; case 'D': @@ -354,7 +398,7 @@ struct osnoise_top_params *osnoise_top_parse_args(int argc, char **argv) case 'd': params->duration = parse_seconds_duration(optarg); if (!params->duration) - osnoise_top_usage("Invalid -D duration\n"); + osnoise_top_usage(params, "Invalid -D duration\n"); break; case 'e': tevent = trace_event_alloc(optarg); @@ -370,17 +414,17 @@ struct osnoise_top_params *osnoise_top_parse_args(int argc, char **argv) break; case 'h': case '?': - osnoise_top_usage(NULL); + osnoise_top_usage(params, NULL); break; case 'p': params->period = get_llong_from_str(optarg); if (params->period > 10000000) - osnoise_top_usage("Period longer than 10 s\n"); + osnoise_top_usage(params, "Period longer than 10 s\n"); break; case 'P': retval = parse_prio(optarg, ¶ms->sched_param); if (retval == -1) - osnoise_top_usage("Invalid -P priority"); + osnoise_top_usage(params, "Invalid -P priority"); params->set_sched = 1; break; case 'q': @@ -389,7 +433,7 @@ struct osnoise_top_params *osnoise_top_parse_args(int argc, char **argv) case 'r': params->runtime = get_llong_from_str(optarg); if (params->runtime < 100) - osnoise_top_usage("Runtime shorter than 100 us\n"); + osnoise_top_usage(params, "Runtime shorter than 100 us\n"); break; case 's': params->stop_us = get_llong_from_str(optarg); @@ -415,7 +459,7 @@ struct osnoise_top_params *osnoise_top_parse_args(int argc, char **argv) exit(EXIT_FAILURE); } } else { - osnoise_top_usage("--trigger requires a previous -e\n"); + osnoise_top_usage(params, "--trigger requires a previous -e\n"); } break; case '1': /* filter */ @@ -426,11 +470,11 @@ struct osnoise_top_params *osnoise_top_parse_args(int argc, char **argv) exit(EXIT_FAILURE); } } else { - osnoise_top_usage("--filter requires a previous -e\n"); + osnoise_top_usage(params, "--filter requires a previous -e\n"); } break; default: - osnoise_top_usage("Invalid option"); + osnoise_top_usage(params, "Invalid option"); } } @@ -495,6 +539,14 @@ osnoise_top_apply_config(struct osnoise_tool *tool, struct osnoise_top_params *p } } + if (params->mode == MODE_HWNOISE) { + retval = osnoise_set_irq_disable(tool->context, 1); + if (retval) { + err_msg("Failed to set OSNOISE_IRQ_DISABLE option\n"); + goto out_err; + } + } + return 0; out_err: diff --git a/tools/tracing/rtla/src/rtla.c b/tools/tracing/rtla/src/rtla.c index 52e8f1825281..7635c70123ab 100644 --- a/tools/tracing/rtla/src/rtla.c +++ b/tools/tracing/rtla/src/rtla.c @@ -26,6 +26,7 @@ static void rtla_usage(int err) "", " commands:", " osnoise - gives information about the operating system noise (osnoise)", + " hwnoise - gives information about hardware-related noise", " timerlat - measures the timer irq and thread latency", "", NULL, @@ -47,6 +48,9 @@ int run_command(int argc, char **argv, int start_position) if (strcmp(argv[start_position], "osnoise") == 0) { osnoise_main(argc-start_position, &argv[start_position]); goto ran; + } else if (strcmp(argv[start_position], "hwnoise") == 0) { + hwnoise_main(argc-start_position, &argv[start_position]); + goto ran; } else if (strcmp(argv[start_position], "timerlat") == 0) { timerlat_main(argc-start_position, &argv[start_position]); goto ran; diff --git a/tools/tracing/rtla/src/timerlat_aa.c b/tools/tracing/rtla/src/timerlat_aa.c new file mode 100644 index 000000000000..ec4e0f4b0e6c --- /dev/null +++ b/tools/tracing/rtla/src/timerlat_aa.c @@ -0,0 +1,990 @@ +// SPDX-License-Identifier: GPL-2.0 +/* + * Copyright (C) 2023 Red Hat Inc, Daniel Bristot de Oliveira <bristot@kernel.org> + */ + +#include <stdlib.h> +#include <errno.h> +#include "utils.h" +#include "osnoise.h" +#include "timerlat.h" + +enum timelat_state { + TIMERLAT_INIT = 0, + TIMERLAT_WAITING_IRQ, + TIMERLAT_WAITING_THREAD, +}; + +#define MAX_COMM 24 + +/* + * Per-cpu data statistics and data. + */ +struct timerlat_aa_data { + /* Current CPU state */ + int curr_state; + + /* timerlat IRQ latency */ + unsigned long long tlat_irq_seqnum; + unsigned long long tlat_irq_latency; + unsigned long long tlat_irq_timstamp; + + /* timerlat Thread latency */ + unsigned long long tlat_thread_seqnum; + unsigned long long tlat_thread_latency; + unsigned long long tlat_thread_timstamp; + + /* + * Information about the thread running when the IRQ + * arrived. + * + * This can be blocking or interference, depending on the |