From 02d89917ef68acbe65c7cc2323f1db4429879878 Mon Sep 17 00:00:00 2001 From: Daniel Bristot de Oliveira Date: Fri, 4 Aug 2023 17:52:11 +0200 Subject: rtla/timerlat_aa: Zero thread sum after every sample analysis The thread thread_thread_sum accounts for thread interference during a single activation. It was not being zeroed, so it was accumulating thread interference over all activations. It was not that visible when timerlat was the highest priority. Link: https://lore.kernel.org/lkml/97bff55b0141f2d01b47d9450a5672fde147b89a.1691162043.git.bristot@kernel.org Fixes: 27e348b221f6 ("rtla/timerlat: Add auto-analysis core") Signed-off-by: Daniel Bristot de Oliveira --- tools/tracing/rtla/src/timerlat_aa.c | 1 + 1 file changed, 1 insertion(+) (limited to 'tools') diff --git a/tools/tracing/rtla/src/timerlat_aa.c b/tools/tracing/rtla/src/timerlat_aa.c index e0ffe69c271c..dec5b4c4511e 100644 --- a/tools/tracing/rtla/src/timerlat_aa.c +++ b/tools/tracing/rtla/src/timerlat_aa.c @@ -159,6 +159,7 @@ static int timerlat_aa_irq_latency(struct timerlat_aa_data *taa_data, taa_data->thread_nmi_sum = 0; taa_data->thread_irq_sum = 0; taa_data->thread_softirq_sum = 0; + taa_data->thread_thread_sum = 0; taa_data->thread_blocking_duration = 0; taa_data->timer_irq_start_time = 0; taa_data->timer_irq_duration = 0; -- cgit v1.2.3 From 6c73daf26420b97fb8b4a620e4ffee5c1f9d44d1 Mon Sep 17 00:00:00 2001 From: Daniel Bristot de Oliveira Date: Fri, 4 Aug 2023 17:52:12 +0200 Subject: rtla/timerlat_aa: Fix negative IRQ delay When estimating the IRQ timer delay, we are dealing with two different clock sources: the external clock source that timerlat uses as a reference and the clock used by the tracer. There are also two moments: the time reading the clock and the timer in which the event is placed in the buffer (the trace event timestamp). If the processor is slow or there is some hardware noise, the difference between the timestamp and the external clock, read can be longer than the IRQ handler delay, resulting in a negative time. If so, set IRQ to start delay as 0. In the end, it is less near-zero and relevant then the noise. Link: https://lore.kernel.org/lkml/a066fb667c7136d86dcddb3c7ccd72587db3e7c7.1691162043.git.bristot@kernel.org Fixes: 27e348b221f6 ("rtla/timerlat: Add auto-analysis core") Signed-off-by: Daniel Bristot de Oliveira --- tools/tracing/rtla/src/timerlat_aa.c | 18 +++++++++++++++++- 1 file changed, 17 insertions(+), 1 deletion(-) (limited to 'tools') diff --git a/tools/tracing/rtla/src/timerlat_aa.c b/tools/tracing/rtla/src/timerlat_aa.c index dec5b4c4511e..baf1efda0581 100644 --- a/tools/tracing/rtla/src/timerlat_aa.c +++ b/tools/tracing/rtla/src/timerlat_aa.c @@ -338,7 +338,23 @@ static int timerlat_aa_irq_handler(struct trace_seq *s, struct tep_record *recor taa_data->timer_irq_start_time = start; taa_data->timer_irq_duration = duration; - taa_data->timer_irq_start_delay = taa_data->timer_irq_start_time - expected_start; + /* + * We are dealing with two different clock sources: the + * external clock source that timerlat uses as a reference + * and the clock used by the tracer. There are also two + * moments: the time reading the clock and the timer in + * which the event is placed in the buffer (the trace + * event timestamp). If the processor is slow or there + * is some hardware noise, the difference between the + * timestamp and the external clock read can be longer + * than the IRQ handler delay, resulting in a negative + * time. If so, set IRQ start delay as 0. In the end, + * it is less relevant than the noise. + */ + if (expected_start < taa_data->timer_irq_start_time) + taa_data->timer_irq_start_delay = taa_data->timer_irq_start_time - expected_start; + else + taa_data->timer_irq_start_delay = 0; /* * not exit from idle. -- cgit v1.2.3 From 301deca09b254965661d3e971f1a60ac2ce41f5f Mon Sep 17 00:00:00 2001 From: Daniel Bristot de Oliveira Date: Fri, 4 Aug 2023 17:52:13 +0200 Subject: rtla/timerlat_aa: Fix previous IRQ delay for IRQs that happens after thread sample timerlat auto-analysis takes note of all IRQs, before or after the execution of the timerlat thread. Because we cannot go backward in the trace (we will fix it when moving to trace-cmd lib?), timerlat aa take note of the last IRQ execution in the waiting for the IRQ state, and then print it if it is executed after the expected timer IRQ starting time. After the thread sample, the timerlat starts recording the next IRQs as "previous" irq for the next occurrence. However, if an IRQ happens after the thread measurement but before the tracing stops, it is classified as a previous IRQ. That is not wrong, as it can be "previous" for the subsequent activation. What is wrong is considering it as a potential source for the last activation. Ignore the IRQ interference that happens after the IRQ starting time for now. A future improvement for timerlat can be either keeping a list of previous IRQ execution or using the trace-cmd library. Still, it requires further investigation - it is a new feature. Link: https://lore.kernel.org/lkml/a44a3f5c801dcc697bacf7325b65d4a5b0460537.1691162043.git.bristot@kernel.org Fixes: 27e348b221f6 ("rtla/timerlat: Add auto-analysis core") Signed-off-by: Daniel Bristot de Oliveira --- tools/tracing/rtla/src/timerlat_aa.c | 13 ++++++++----- 1 file changed, 8 insertions(+), 5 deletions(-) (limited to 'tools') diff --git a/tools/tracing/rtla/src/timerlat_aa.c b/tools/tracing/rtla/src/timerlat_aa.c index baf1efda0581..7093fd5333be 100644 --- a/tools/tracing/rtla/src/timerlat_aa.c +++ b/tools/tracing/rtla/src/timerlat_aa.c @@ -545,7 +545,7 @@ static int timerlat_aa_kworker_start_handler(struct trace_seq *s, struct tep_rec static void timerlat_thread_analysis(struct timerlat_aa_data *taa_data, int cpu, int irq_thresh, int thread_thresh) { - unsigned long long exp_irq_ts; + long long exp_irq_ts; int total; int irq; @@ -562,12 +562,15 @@ static void timerlat_thread_analysis(struct timerlat_aa_data *taa_data, int cpu, /* * Expected IRQ arrival time using the trace clock as the base. + * + * TODO: Add a list of previous IRQ, and then run the list backwards. */ 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\t up to %9.2f us\n", - ns_to_usf(taa_data->prev_irq_duration)); + if (exp_irq_ts < taa_data->prev_irq_timstamp + taa_data->prev_irq_duration) { + if (taa_data->prev_irq_timstamp < taa_data->timer_irq_start_time) + printf(" Previous IRQ interference: \t\t up to %9.2f us\n", + ns_to_usf(taa_data->prev_irq_duration)); + } /* * The delay that the IRQ suffered before starting. -- cgit v1.2.3 From e8c44d3b713b96cda055a23b21e8c4f931dd159f Mon Sep 17 00:00:00 2001 From: Daniel Bristot de Oliveira Date: Fri, 15 Sep 2023 15:02:32 +0200 Subject: rtla/timerlat: Do not stop user-space if a cpu is offline If no CPU list is passed, timerlat in user-space will dispatch one thread per sysconf(_SC_NPROCESSORS_CONF). However, not all CPU might be available, for instance, if HT is disabled. Currently, rtla timerlat is stopping the session if an user-space thread cannot set affinity to a CPU, or if a running user-space thread is killed. However, this is too restrictive. So, reduce the error to a debug message, and rtla timerlat run as long as there is at least one user-space thread alive. Link: https://lore.kernel.org/lkml/59cf2c882900ab7de91c6ee33b382ac7fa6b4ed0.1694781909.git.bristot@kernel.org Fixes: cdca4f4e5e8e ("rtla/timerlat_top: Add timerlat user-space support") Signed-off-by: Daniel Bristot de Oliveira --- tools/tracing/rtla/src/timerlat_u.c | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) (limited to 'tools') diff --git a/tools/tracing/rtla/src/timerlat_u.c b/tools/tracing/rtla/src/timerlat_u.c index 05e310696dd5..01dbf9a6b5a5 100644 --- a/tools/tracing/rtla/src/timerlat_u.c +++ b/tools/tracing/rtla/src/timerlat_u.c @@ -45,7 +45,7 @@ static int timerlat_u_main(int cpu, struct timerlat_u_params *params) retval = sched_setaffinity(gettid(), sizeof(set), &set); if (retval == -1) { - err_msg("Error setting user thread affinity\n"); + debug_msg("Error setting user thread affinity %d, is the CPU online?\n", cpu); exit(1); } @@ -193,7 +193,9 @@ void *timerlat_u_dispatcher(void *data) procs_count--; } } - break; + + if (!procs_count) + break; } sleep(1); -- cgit v1.2.3