rpms
/
rtla
7
0
Fork 0
Code Issues Pull Requests Releases Activity

Add rtla timerlat auto analysis 

Resolves: rhbz#2175292
jiraProject == RHELPLAN-150657

Signed-off-by: John Kacur <jkacur@redhat.com>
This commit is contained in:
John Kacur 2023-07-14 15:38:54 -04:00
parent f6b8fb4dda
commit 6bdff9a0a5
8 changed files with 1884 additions and 1 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

216
Documentation-rtla-Add-timerlat-top-auto-analysis-op.patch Normal file
View File

@ -0,0 +1,216 @@
From ce6cc6f70cad4d703ddfe99d74f33990617c0a3c Mon Sep 17 00:00:00 2001
From: Daniel Bristot de Oliveira <bristot@kernel.org>
Date: Tue, 31 Jan 2023 16:38:55 +0100
Subject: [PATCH] Documentation/rtla: Add timerlat-top auto-analysis options
Add the new options to the man page, as well as updating the
example to include the new output.
Link: https://lkml.kernel.org/r/a3f5fb49432a55c3323b18725fc6e702f16ccc79.1675179318.git.bristot@kernel.org
Cc: Daniel Bristot de Oliveira <bristot@kernel.org>
Cc: Jonathan Corbet <corbet@lwn.net>
Signed-off-by: Daniel Bristot de Oliveira <bristot@kernel.org>
Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
---
common_timerlat_aa.rst | 7 ++
rtla-timerlat-top.rst | 164 ++++++++++++++++++-----------------------
2 files changed, 80 insertions(+), 91 deletions(-)
create mode 100644 Documentation/tools/rtla/common_timerlat_aa.rst
diff --git a/Documentation/common_timerlat_aa.rst b/Documentation/common_timerlat_aa.rst
new file mode 100644
index 000000000000..077029e6b289
--- /dev/null
+++ b/Documentation/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/rtla-timerlat-top.rst b/Documentation/rtla-timerlat-top.rst
index 7c4e4b109493..73799c1150ad 100644
--- a/Documentation/rtla-timerlat-top.rst
+++ b/Documentation/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
--
2.40.1

1056
rtla-timerlat-Add-auto-analysis-core.patch Normal file
View File

File diff suppressed because it is too large Load Diff

164
rtla-timerlat-Add-auto-analysis-only-option.patch Normal file
View File

@ -0,0 +1,164 @@
From 9fa48a2477de747b644c778a1e35d679cabcd917 Mon Sep 17 00:00:00 2001
From: Daniel Bristot de Oliveira <bristot@kernel.org>
Date: Wed, 29 Mar 2023 18:23:32 +0200
Subject: [PATCH 7/8] rtla/timerlat: Add auto-analysis only option
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 <corbet@lwn.net>
Signed-off-by: Daniel Bristot de Oliveira <bristot@kernel.org>
Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
---
src/timerlat_top.c | 49 +++++++++++++++++++++++++++++++++++++++++-----
1 file changed, 44 insertions(+), 5 deletions(-)
diff --git a/src/timerlat_top.c b/src/timerlat_top.c
index eea5b3357e27..92c658c64f28 100644
--- a/src/timerlat_top.c
+++ b/src/timerlat_top.c
@@ -33,6 +33,7 @@ struct timerlat_top_params {
int set_sched;
int dma_latency;
int no_aa;
+ int aa_only;
int dump_tasks;
struct sched_attr sched_param;
struct trace_events *events;
@@ -142,10 +143,12 @@ timerlat_top_handler(struct trace_seq *s, struct tep_record *record,
top = container_of(trace, struct osnoise_tool, trace);
params = top->params;
- tep_get_field_val(s, event, "context", record, &thread, 1);
- tep_get_field_val(s, event, "timer_latency", record, &latency, 1);
+ if (!params->aa_only) {
+ tep_get_field_val(s, event, "context", record, &thread, 1);
+ tep_get_field_val(s, event, "timer_latency", record, &latency, 1);
- timerlat_top_update(top, cpu, thread, latency);
+ timerlat_top_update(top, cpu, thread, latency);
+ }
if (!params->no_aa)
timerlat_aa_handler(s, record, event, context);
@@ -250,6 +253,9 @@ timerlat_print_stats(struct timerlat_top_params *params, struct osnoise_tool *to
static int nr_cpus = -1;
int i;
+ if (params->aa_only)
+ return;
+
if (nr_cpus == -1)
nr_cpus = sysconf(_SC_NPROCESSORS_CONF);
@@ -279,10 +285,11 @@ static void timerlat_top_usage(char *usage)
"",
" usage: rtla timerlat [top] [-h] [-q] [-a us] [-d s] [-D] [-n] [-p us] [-i us] [-T us] [-s us] \\",
" [[-t[=file]] [-e sys[:event]] [--filter <filter>] [--trigger <trigger>] [-c cpu-list] \\",
- " [-P priority] [--dma-latency us]",
+ " [-P priority] [--dma-latency us] [--aa-only us]",
"",
" -h/--help: print this menu",
" -a/--auto: set automatic trace mode, stopping the session if argument in us latency is hit",
+ " --aa-only us: stop if <us> latency is hit, only printing the auto analysis (reduces CPU usage)",
" -p/--period us: timerlat period in us",
" -i/--irq us: stop trace if the irq latency is higher than the argument in us",
" -T/--thread us: stop trace if the thread latency is higher than the argument in us",
@@ -362,13 +369,14 @@ static struct timerlat_top_params
{"dma-latency", required_argument, 0, '2'},
{"no-aa", no_argument, 0, '3'},
{"dump-tasks", no_argument, 0, '4'},
+ {"aa-only", required_argument, 0, '5'},
{0, 0, 0, 0}
};
/* getopt_long stores the option index here. */
int option_index = 0;
- c = getopt_long(argc, argv, "a:c:d:De:hi:np:P:qs:t::T:0:1:2:34",
+ c = getopt_long(argc, argv, "a:c:d:De:hi:np:P:qs:t::T:0:1:2:345:",
long_options, &option_index);
/* detect the end of the options. */
@@ -389,6 +397,20 @@ static struct timerlat_top_params
/* set trace */
params->trace_output = "timerlat_trace.txt";
break;
+ case '5':
+ /* it is here because it is similar to -a */
+ auto_thresh = get_llong_from_str(optarg);
+
+ /* set thread stop to auto_thresh */
+ params->stop_total_us = auto_thresh;
+ params->stop_us = auto_thresh;
+
+ /* get stack trace */
+ params->print_stack = auto_thresh;
+
+ /* set aa_only to avoid parsing the trace */
+ params->aa_only = 1;
+ break;
case 'c':
retval = parse_cpu_list(optarg, &params->monitored_cpus);
if (retval)
@@ -503,6 +525,9 @@ static struct timerlat_top_params
if (!params->stop_us && !params->stop_total_us)
params->no_aa = 1;
+ if (params->no_aa && params->aa_only)
+ timerlat_top_usage("--no-aa and --aa-only are mutually exclusive!");
+
return params;
}
@@ -634,6 +659,7 @@ int timerlat_top_main(int argc, char *argv[])
struct trace_instance *trace;
int dma_latency_fd = -1;
int return_value = 1;
+ char *max_lat;
int retval;
params = timerlat_top_parse_args(argc, argv);
@@ -700,6 +726,9 @@ int timerlat_top_main(int argc, char *argv[])
while (!stop_tracing) {
sleep(params->sleep_time);
+ if (params->aa_only && !trace_is_off(&top->trace, &record->trace))
+ continue;
+
retval = tracefs_iterate_raw_events(trace->tep,
trace->inst,
NULL,
@@ -733,6 +762,16 @@ int timerlat_top_main(int argc, char *argv[])
printf(" Saving trace to %s\n", params->trace_output);
save_trace_to_file(record->trace.inst, params->trace_output);
}
+ } else if (params->aa_only) {
+ /*
+ * If the trace did not stop with --aa-only, at least print the
+ * max known latency.
+ */
+ max_lat = tracefs_instance_file_read(trace->inst, "tracing_max_latency", NULL);
+ if (max_lat) {
+ printf(" Max latency was %s\n", max_lat);
+ free(max_lat);
+ }
}
out_top:
--
2.40.1

293
rtla-timerlat-Add-auto-analysis-support-to-timerlat.patch Normal file
View File

@ -0,0 +1,293 @@
From 5def33df84d2326ebf5f29ae9ddc702a4593c337 Mon Sep 17 00:00:00 2001
From: Daniel Bristot de Oliveira <bristot@kernel.org>
Date: Tue, 31 Jan 2023 16:38:54 +0100
Subject: [PATCH 4/8] rtla/timerlat: Add auto-analysis support to timerlat top
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 <bristot@kernel.org>
Cc: Jonathan Corbet <corbet@lwn.net>
Signed-off-by: Daniel Bristot de Oliveira <bristot@kernel.org>
Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
---
src/timerlat_top.c | 46 ++++++++++++++++++++++++++++++++++++++++++++--
1 file changed, 44 insertions(+), 2 deletions(-)
diff --git a/src/timerlat_top.c b/src/timerlat_top.c
index 334271935222..eea5b3357e27 100644
--- a/src/timerlat_top.c
+++ b/src/timerlat_top.c
@@ -10,10 +10,12 @@
#include <unistd.h>
#include <stdio.h>
#include <time.h>
+#include <errno.h>
#include "utils.h"
#include "osnoise.h"
#include "timerlat.h"
+#include "timerlat_aa.h"
struct timerlat_top_params {
char *cpus;
@@ -30,6 +32,8 @@ struct timerlat_top_params {
int quiet;
int set_sched;
int dma_latency;
+ int no_aa;
+ int dump_tasks;
struct sched_attr sched_param;
struct trace_events *events;
};
@@ -130,17 +134,22 @@ timerlat_top_handler(struct trace_seq *s, struct tep_record *record,
struct tep_event *event, void *context)
{
struct trace_instance *trace = context;
+ struct timerlat_top_params *params;
unsigned long long latency, thread;
struct osnoise_tool *top;
int cpu = record->cpu;
top = container_of(trace, struct osnoise_tool, trace);
+ params = top->params;
tep_get_field_val(s, event, "context", record, &thread, 1);
tep_get_field_val(s, event, "timer_latency", record, &latency, 1);
timerlat_top_update(top, cpu, thread, latency);
+ if (!params->no_aa)
+ timerlat_aa_handler(s, record, event, context);
+
return 0;
}
@@ -281,11 +290,13 @@ static void timerlat_top_usage(char *usage)
" -c/--cpus cpus: run the tracer only on the given cpus",
" -d/--duration time[m|h|d]: duration of the session in seconds",
" -D/--debug: print debug info",
+ " --dump-tasks: prints the task running on all CPUs if stop conditions are met (depends on !--no-aa)",
" -t/--trace[=file]: save the stopped trace to [file|timerlat_trace.txt]",
" -e/--event <sys:event>: enable the <sys:event> in the trace instance, multiple -e are allowed",
" --filter <command>: enable a trace event filter to the previous -e event",
" --trigger <command>: enable a trace event trigger to the previous -e event",
" -n/--nano: display data in nanoseconds",
+ " --no-aa: disable auto-analysis, reducing rtla timerlat cpu usage",
" -q/--quiet print only a summary at the end",
" --dma-latency us: set /dev/cpu_dma_latency latency <us> to reduce exit from idle latency",
" -P/--priority o:prio|r:prio|f:prio|d:runtime:period : set scheduling parameters",
@@ -349,13 +360,15 @@ static struct timerlat_top_params
{"trigger", required_argument, 0, '0'},
{"filter", required_argument, 0, '1'},
{"dma-latency", required_argument, 0, '2'},
+ {"no-aa", no_argument, 0, '3'},
+ {"dump-tasks", no_argument, 0, '4'},
{0, 0, 0, 0}
};
/* getopt_long stores the option index here. */
int option_index = 0;
- c = getopt_long(argc, argv, "a:c:d:De:hi:np:P:qs:t::T:0:1:2:",
+ c = getopt_long(argc, argv, "a:c:d:De:hi:np:P:qs:t::T:0:1:2:34",
long_options, &option_index);
/* detect the end of the options. */
@@ -368,13 +381,13 @@ static struct timerlat_top_params
/* set thread stop to auto_thresh */
params->stop_total_us = auto_thresh;
+ params->stop_us = auto_thresh;
/* get stack trace */
params->print_stack = auto_thresh;
/* set trace */
params->trace_output = "timerlat_trace.txt";
-
break;
case 'c':
retval = parse_cpu_list(optarg, &params->monitored_cpus);
@@ -437,6 +450,7 @@ static struct timerlat_top_params
params->trace_output = &optarg[1];
else
params->trace_output = "timerlat_trace.txt";
+
break;
case '0': /* trigger */
if (params->events) {
@@ -467,6 +481,12 @@ static struct timerlat_top_params
exit(EXIT_FAILURE);
}
break;
+ case '3': /* no-aa */
+ params->no_aa = 1;
+ break;
+ case '4':
+ params->dump_tasks = 1;
+ break;
default:
timerlat_top_usage("Invalid option");
}
@@ -477,6 +497,12 @@ static struct timerlat_top_params
exit(EXIT_FAILURE);
}
+ /*
+ * Auto analysis only happens if stop tracing, thus:
+ */
+ if (!params->stop_us && !params->stop_total_us)
+ params->no_aa = 1;
+
return params;
}
@@ -547,6 +573,7 @@ static struct osnoise_tool
{
struct osnoise_tool *top;
int nr_cpus;
+ int retval;
nr_cpus = sysconf(_SC_NPROCESSORS_CONF);
@@ -563,6 +590,16 @@ static struct osnoise_tool
tep_register_event_handler(top->trace.tep, -1, "ftrace", "timerlat",
timerlat_top_handler, top);
+ /*
+ * If no auto analysis, we are ready.
+ */
+ if (params->no_aa)
+ return top;
+
+ retval = timerlat_aa_init(top, nr_cpus, params->dump_tasks);
+ if (retval)
+ goto out_err;
+
return top;
out_err:
@@ -688,6 +725,10 @@ int timerlat_top_main(int argc, char *argv[])
if (trace_is_off(&top->trace, &record->trace)) {
printf("rtla timerlat hit stop tracing\n");
+
+ if (!params->no_aa)
+ timerlat_auto_analysis(params->stop_us, params->stop_total_us);
+
if (params->trace_output) {
printf(" Saving trace to %s\n", params->trace_output);
save_trace_to_file(record->trace.inst, params->trace_output);
@@ -701,6 +742,7 @@ int timerlat_top_main(int argc, char *argv[])
params->events = NULL;
out_free:
timerlat_free_top(top->data);
+ timerlat_aa_destroy();
osnoise_destroy_tool(record);
osnoise_destroy_tool(top);
free(params);
--
2.40.1

48
rtla-timerlat-Fix-Previous-IRQ-auto-analysis-line.patch Normal file
View File

@ -0,0 +1,48 @@
From 82253a271aae9271fcf0aaa5e0ecc6dd38fb872b Mon Sep 17 00:00:00 2001
From: Daniel Bristot de Oliveira <bristot@kernel.org>
Date: Fri, 24 Mar 2023 20:26:42 +0100
Subject: [PATCH 8/8] rtla/timerlat: Fix "Previous IRQ" auto analysis' line
The "Previous IRQ interference" line is misaligned and without
a \n, breaking the tool's output:
## CPU 12 hit stop tracing, analyzing it ##
Previous IRQ interference: up to 2.22 us IRQ handler delay: 18.06 us (0.00 %)
IRQ latency: 18.52 us
Timerlat IRQ duration: 4.41 us (0.00 %)
Blocking thread: 216.93 us (0.03 %)
Fix the output:
## CPU 7 hit stop tracing, analyzing it ##
Previous IRQ interference: up to 8.93 us
IRQ handler delay: 0.98 us (0.00 %)
IRQ latency: 2.95 us
Timerlat IRQ duration: 11.26 us (0.03 %)
Link: https://lore.kernel.org/linux-trace-devel/8b5819077f15ccf24745c9bf3205451e16ee32d9.1679685525.git.bristot@kernel.org
Fixes: 27e348b221f6 ("rtla/timerlat: Add auto-analysis core")
Cc: Masami Hiramatsu <mhiramat@kernel.org>
Signed-off-by: Daniel Bristot de Oliveira <bristot@kernel.org>
Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
---
src/timerlat_aa.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/src/timerlat_aa.c b/src/timerlat_aa.c
index ec4e0f4b0e6c..1843fff66da5 100644
--- a/src/timerlat_aa.c
+++ b/src/timerlat_aa.c
@@ -548,7 +548,7 @@ static void timerlat_thread_analysis(struct timerlat_aa_data *taa_data, int cpu,
exp_irq_ts = taa_data->timer_irq_start_time - taa_data->timer_irq_start_delay;
if (exp_irq_ts < taa_data->prev_irq_timstamp + taa_data->prev_irq_duration)
- printf(" Previous IRQ interference: \t up to %9.2f us",
+ printf(" Previous IRQ interference: \t\t up to %9.2f us\n",
ns_to_usf(taa_data->prev_irq_duration));
/*
--
2.40.1

21
rtla.spec
View File

@ -1,6 +1,6 @@
Name: rtla
Version: 5.14.0
Release: 6%{?dist}
Release: 7%{?dist}
Summary: Real-Time Linux Analysis tools
License: GPLv2
@ -20,6 +20,13 @@ Requires: libtracefs >= 1.3.1
# Patches
Patch1: rtla-Fix-exit-status-when-returning-from-calls-to-usage.patch
Patch2: Documentation-rtla-Correct-command-line-example.patch
Patch3: tools-tracing-rtla-osnoise_hist-use-total-duration-f.patch
Patch4: tools-tracing-rtla-osnoise_hist-display-average-with.patch
Patch5: rtla-timerlat-Add-auto-analysis-core.patch
Patch6: rtla-timerlat-Add-auto-analysis-support-to-timerlat.patch
Patch7: rtla-timerlat-Add-auto-analysis-only-option.patch
Patch8: rtla-timerlat-Fix-Previous-IRQ-auto-analysis-line.patch
Patch9: Documentation-rtla-Add-timerlat-top-auto-analysis-op.patch
%description
The rtla meta-tool includes a set of commands that aims to analyze
@ -32,6 +39,13 @@ about the properties and root causes of unexpected results.
%setup -q -n %{name}-%{version}
%patch1 -p1
%patch2 -p1
%patch3 -p1
%patch4 -p1
%patch5 -p1
%patch6 -p1
%patch7 -p1
%patch8 -p1
%patch9 -p1
%build
@ -67,6 +81,11 @@ make DESTDIR=%{buildroot} -C Documentation install
%changelog
* Fri Jul 14 2023 John Kacur <jkacur@redhat.com> - 5.14.0-7
- Add rtla timerlat auto analysis
Resolves: rhbz#2175292
jiraProject == RHELPLAN-150657
* Tue May 09 2023 John Kacur <jkacur@redhat.com> - 5.14.0-6
- Forward port the tests directory for ci testing
Resolves: rhbz#2196611

36
tools-tracing-rtla-osnoise_hist-display-average-with.patch Normal file
View File

@ -0,0 +1,36 @@
From 1fab1469b66baf7847298b205e5c4aff47c2ae8a Mon Sep 17 00:00:00 2001
From: Andreas Ziegler <br015@umbiko.net>
Date: Tue, 3 Jan 2023 11:34:00 +0100
Subject: [PATCH 2/8] tools/tracing/rtla: osnoise_hist: display average with
two-digit precision
Calculate average value in osnoise-hist summary with two-digit
precision to avoid displaying too optimitic results.
Link: https://lkml.kernel.org/r/20230103103400.275566-3-br015@umbiko.net
Signed-off-by: Andreas Ziegler <br015@umbiko.net>
Acked-by: Daniel Bristot de Oliveira <bristot@kernel.org>
Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
---
src/osnoise_hist.c | 4 ++--
1 file changed, 2 insertions(+), 2 deletions(-)
diff --git a/src/osnoise_hist.c b/src/osnoise_hist.c
index fe34452fc4ec..13e1233690bb 100644
--- a/src/osnoise_hist.c
+++ b/src/osnoise_hist.c
@@ -335,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, " - ");
}
--
2.40.1

51
tools-tracing-rtla-osnoise_hist-use-total-duration-f.patch Normal file
View File

@ -0,0 +1,51 @@
From fe137a4fe0e77eb95396cfc5c3dd7df404421aa4 Mon Sep 17 00:00:00 2001
From: Andreas Ziegler <br015@umbiko.net>
Date: Tue, 3 Jan 2023 11:33:59 +0100
Subject: [PATCH 1/8] tools/tracing/rtla: osnoise_hist: use total duration for
average calculation
Sampled durations must be weighted by observed quantity, to arrive at a correct
average duration value.
Perform calculation of total duration by summing (duration * count).
Link: https://lkml.kernel.org/r/20230103103400.275566-2-br015@umbiko.net
Fixes: 829a6c0b5698 ("rtla/osnoise: Add the hist mode")
Signed-off-by: Andreas Ziegler <br015@umbiko.net>
Acked-by: Daniel Bristot de Oliveira <bristot@kernel.org>
Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
---
src/osnoise_hist.c | 5 ++++-
1 file changed, 4 insertions(+), 1 deletion(-)
diff --git a/src/osnoise_hist.c b/src/osnoise_hist.c
index 5d7ea479ac89..fe34452fc4ec 100644
--- a/src/osnoise_hist.c
+++ b/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)
--
2.40.1