* [PATCH 2/2] rtla/timerlat: Make timerlat_hist_cpu->*_count unsigned long long
2024-10-11 12:10 [PATCH 1/2] rtla/timerlat: Make timerlat_top_cpu->*_count unsigned long long tglozar
@ 2024-10-11 12:10 ` tglozar
2024-10-11 15:10 ` John Kacur
2024-10-11 15:09 ` [PATCH 1/2] rtla/timerlat: Make timerlat_top_cpu->*_count " John Kacur
2024-10-11 17:23 ` Steven Rostedt
2 siblings, 1 reply; 6+ messages in thread
From: tglozar @ 2024-10-11 12:10 UTC (permalink / raw)
To: rostedt
Cc: linux-trace-kernel, linux-kernel, jkacur, lgoncalv, Tomas Glozar,
Attila Fazekas
From: Tomas Glozar <tglozar@redhat.com>
Do the same fix as in previous commit also for timerlat-hist.
Reported-by: Attila Fazekas <afazekas@redhat.com>
Signed-off-by: Tomas Glozar <tglozar@redhat.com>
---
tools/tracing/rtla/src/timerlat_hist.c | 18 +++++++++---------
1 file changed, 9 insertions(+), 9 deletions(-)
diff --git a/tools/tracing/rtla/src/timerlat_hist.c b/tools/tracing/rtla/src/timerlat_hist.c
index a3907c390d67..bbeaba8b5183 100644
--- a/tools/tracing/rtla/src/timerlat_hist.c
+++ b/tools/tracing/rtla/src/timerlat_hist.c
@@ -62,9 +62,9 @@ struct timerlat_hist_cpu {
int *thread;
int *user;
- int irq_count;
- int thread_count;
- int user_count;
+ unsigned long long irq_count;
+ unsigned long long thread_count;
+ unsigned long long user_count;
unsigned long long min_irq;
unsigned long long sum_irq;
@@ -304,15 +304,15 @@ timerlat_print_summary(struct timerlat_hist_params *params,
continue;
if (!params->no_irq)
- trace_seq_printf(trace->seq, "%9d ",
+ trace_seq_printf(trace->seq, "%9llu ",
data->hist[cpu].irq_count);
if (!params->no_thread)
- trace_seq_printf(trace->seq, "%9d ",
+ trace_seq_printf(trace->seq, "%9llu ",
data->hist[cpu].thread_count);
if (params->user_hist)
- trace_seq_printf(trace->seq, "%9d ",
+ trace_seq_printf(trace->seq, "%9llu ",
data->hist[cpu].user_count);
}
trace_seq_printf(trace->seq, "\n");
@@ -488,15 +488,15 @@ timerlat_print_stats_all(struct timerlat_hist_params *params,
trace_seq_printf(trace->seq, "count:");
if (!params->no_irq)
- trace_seq_printf(trace->seq, "%9d ",
+ trace_seq_printf(trace->seq, "%9llu ",
sum.irq_count);
if (!params->no_thread)
- trace_seq_printf(trace->seq, "%9d ",
+ trace_seq_printf(trace->seq, "%9llu ",
sum.thread_count);
if (params->user_hist)
- trace_seq_printf(trace->seq, "%9d ",
+ trace_seq_printf(trace->seq, "%9llu ",
sum.user_count);
trace_seq_printf(trace->seq, "\n");
--
2.47.0
^ permalink raw reply related [flat|nested] 6+ messages in thread* Re: [PATCH 2/2] rtla/timerlat: Make timerlat_hist_cpu->*_count unsigned long long
2024-10-11 12:10 ` [PATCH 2/2] rtla/timerlat: Make timerlat_hist_cpu->*_count " tglozar
@ 2024-10-11 15:10 ` John Kacur
0 siblings, 0 replies; 6+ messages in thread
From: John Kacur @ 2024-10-11 15:10 UTC (permalink / raw)
To: Tomas Glozar
Cc: rostedt, linux-trace-kernel, linux-kernel, lgoncalv,
Attila Fazekas
On Fri, 11 Oct 2024, tglozar@redhat.com wrote:
> From: Tomas Glozar <tglozar@redhat.com>
>
> Do the same fix as in previous commit also for timerlat-hist.
>
> Reported-by: Attila Fazekas <afazekas@redhat.com>
> Signed-off-by: Tomas Glozar <tglozar@redhat.com>
> ---
> tools/tracing/rtla/src/timerlat_hist.c | 18 +++++++++---------
> 1 file changed, 9 insertions(+), 9 deletions(-)
>
> diff --git a/tools/tracing/rtla/src/timerlat_hist.c b/tools/tracing/rtla/src/timerlat_hist.c
> index a3907c390d67..bbeaba8b5183 100644
> --- a/tools/tracing/rtla/src/timerlat_hist.c
> +++ b/tools/tracing/rtla/src/timerlat_hist.c
> @@ -62,9 +62,9 @@ struct timerlat_hist_cpu {
> int *thread;
> int *user;
>
> - int irq_count;
> - int thread_count;
> - int user_count;
> + unsigned long long irq_count;
> + unsigned long long thread_count;
> + unsigned long long user_count;
>
> unsigned long long min_irq;
> unsigned long long sum_irq;
> @@ -304,15 +304,15 @@ timerlat_print_summary(struct timerlat_hist_params *params,
> continue;
>
> if (!params->no_irq)
> - trace_seq_printf(trace->seq, "%9d ",
> + trace_seq_printf(trace->seq, "%9llu ",
> data->hist[cpu].irq_count);
>
> if (!params->no_thread)
> - trace_seq_printf(trace->seq, "%9d ",
> + trace_seq_printf(trace->seq, "%9llu ",
> data->hist[cpu].thread_count);
>
> if (params->user_hist)
> - trace_seq_printf(trace->seq, "%9d ",
> + trace_seq_printf(trace->seq, "%9llu ",
> data->hist[cpu].user_count);
> }
> trace_seq_printf(trace->seq, "\n");
> @@ -488,15 +488,15 @@ timerlat_print_stats_all(struct timerlat_hist_params *params,
> trace_seq_printf(trace->seq, "count:");
>
> if (!params->no_irq)
> - trace_seq_printf(trace->seq, "%9d ",
> + trace_seq_printf(trace->seq, "%9llu ",
> sum.irq_count);
>
> if (!params->no_thread)
> - trace_seq_printf(trace->seq, "%9d ",
> + trace_seq_printf(trace->seq, "%9llu ",
> sum.thread_count);
>
> if (params->user_hist)
> - trace_seq_printf(trace->seq, "%9d ",
> + trace_seq_printf(trace->seq, "%9llu ",
> sum.user_count);
>
> trace_seq_printf(trace->seq, "\n");
> --
> 2.47.0
>
>
>
Reviewed by: John Kacur <jkacur@redhat.com>
Tested by: John Kacur <jkacur@redhat.com>
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [PATCH 1/2] rtla/timerlat: Make timerlat_top_cpu->*_count unsigned long long
2024-10-11 12:10 [PATCH 1/2] rtla/timerlat: Make timerlat_top_cpu->*_count unsigned long long tglozar
2024-10-11 12:10 ` [PATCH 2/2] rtla/timerlat: Make timerlat_hist_cpu->*_count " tglozar
@ 2024-10-11 15:09 ` John Kacur
2024-10-11 17:23 ` Steven Rostedt
2 siblings, 0 replies; 6+ messages in thread
From: John Kacur @ 2024-10-11 15:09 UTC (permalink / raw)
To: Tomas Glozar
Cc: Steven Rostedt, linux-trace-kernel, LKML, lgoncalv,
Attila Fazekas
On Fri, 11 Oct 2024, tglozar@redhat.com wrote:
> From: Tomas Glozar <tglozar@redhat.com>
>
> Most fields of struct timerlat_top_cpu are unsigned long long, but the
> fields {irq,thread,user}_count are int (32-bit signed).
>
> This leads to overflow when tracing on a large number of CPUs for a long
> enough time:
> $ rtla timerlat top -a20 -c 1-127 -d 12h
> ...
> 0 12:00:00 | IRQ Timer Latency (us) | Thread Timer Latency (us)
> CPU COUNT | cur min avg max | cur min avg max
> 1 #43200096 | 0 0 1 2 | 3 2 6 12
> ...
> 127 #43200096 | 0 0 1 2 | 3 2 5 11
> ALL #119144 e4 | 0 5 4 | 2 28 16
>
> The average latency should be 0-1 for IRQ and 5-6 for thread, but is
> reported as 5 and 28, about 4 to 5 times more, due to the count
> overflowing when summed over all CPUs: 43200096 * 127 = 5486412192,
> however, 1191444898 (= 5486412192 mod MAX_INT) is reported instead, as
> seen on the last line of the output, and the averages are thus ~4.6
> times higher than they should be (5486412192 / 1191444898 = ~4.6).
>
> Fix the issue by changing {irq,thread,user}_count fields to unsigned
> long long, similarly to other fields in struct timerlat_top_cpu and to
> the count variable in timerlat_top_print_sum.
>
> Reported-by: Attila Fazekas <afazekas@redhat.com>
> Signed-off-by: Tomas Glozar <tglozar@redhat.com>
> ---
> tools/tracing/rtla/src/timerlat_top.c | 8 ++++----
> 1 file changed, 4 insertions(+), 4 deletions(-)
>
> diff --git a/tools/tracing/rtla/src/timerlat_top.c b/tools/tracing/rtla/src/timerlat_top.c
> index 210b0f533534..ee7c291fc9bb 100644
> --- a/tools/tracing/rtla/src/timerlat_top.c
> +++ b/tools/tracing/rtla/src/timerlat_top.c
> @@ -54,9 +54,9 @@ struct timerlat_top_params {
> };
>
> struct timerlat_top_cpu {
> - int irq_count;
> - int thread_count;
> - int user_count;
> + unsigned long long irq_count;
> + unsigned long long thread_count;
> + unsigned long long user_count;
>
> unsigned long long cur_irq;
> unsigned long long min_irq;
> @@ -280,7 +280,7 @@ static void timerlat_top_print(struct osnoise_tool *top, int cpu)
> /*
> * Unless trace is being lost, IRQ counter is always the max.
> */
> - trace_seq_printf(s, "%3d #%-9d |", cpu, cpu_data->irq_count);
> + trace_seq_printf(s, "%3d #%-9llu |", cpu, cpu_data->irq_count);
>
> if (!cpu_data->irq_count) {
> trace_seq_printf(s, "%s %s %s %s |", no_value, no_value, no_value, no_value);
> --
> 2.47.0
>
>
>
Reviewed by: John Kacur <jkacur@redhat.com>
Tested by: John Kacur <jkacur@redhat.com>
^ permalink raw reply [flat|nested] 6+ messages in thread* Re: [PATCH 1/2] rtla/timerlat: Make timerlat_top_cpu->*_count unsigned long long
2024-10-11 12:10 [PATCH 1/2] rtla/timerlat: Make timerlat_top_cpu->*_count unsigned long long tglozar
2024-10-11 12:10 ` [PATCH 2/2] rtla/timerlat: Make timerlat_hist_cpu->*_count " tglozar
2024-10-11 15:09 ` [PATCH 1/2] rtla/timerlat: Make timerlat_top_cpu->*_count " John Kacur
@ 2024-10-11 17:23 ` Steven Rostedt
2024-10-14 8:57 ` Tomas Glozar
2 siblings, 1 reply; 6+ messages in thread
From: Steven Rostedt @ 2024-10-11 17:23 UTC (permalink / raw)
To: tglozar; +Cc: linux-trace-kernel, linux-kernel, jkacur, lgoncalv,
Attila Fazekas
On Fri, 11 Oct 2024 14:10:14 +0200
tglozar@redhat.com wrote:
> From: Tomas Glozar <tglozar@redhat.com>
>
> Most fields of struct timerlat_top_cpu are unsigned long long, but the
> fields {irq,thread,user}_count are int (32-bit signed).
>
> This leads to overflow when tracing on a large number of CPUs for a long
> enough time:
> $ rtla timerlat top -a20 -c 1-127 -d 12h
> ...
> 0 12:00:00 | IRQ Timer Latency (us) | Thread Timer Latency (us)
> CPU COUNT | cur min avg max | cur min avg max
> 1 #43200096 | 0 0 1 2 | 3 2 6 12
> ...
> 127 #43200096 | 0 0 1 2 | 3 2 5 11
> ALL #119144 e4 | 0 5 4 | 2 28 16
>
> The average latency should be 0-1 for IRQ and 5-6 for thread, but is
> reported as 5 and 28, about 4 to 5 times more, due to the count
> overflowing when summed over all CPUs: 43200096 * 127 = 5486412192,
> however, 1191444898 (= 5486412192 mod MAX_INT) is reported instead, as
> seen on the last line of the output, and the averages are thus ~4.6
> times higher than they should be (5486412192 / 1191444898 = ~4.6).
>
> Fix the issue by changing {irq,thread,user}_count fields to unsigned
> long long, similarly to other fields in struct timerlat_top_cpu and to
> the count variable in timerlat_top_print_sum.
>
> Reported-by: Attila Fazekas <afazekas@redhat.com>
> Signed-off-by: Tomas Glozar <tglozar@redhat.com>
Thanks, I'm applying these, but could you or someone else create a test
directory in rtla and even rv that tests this code. I just examine it and
run some basic operations, but I have no idea if it is really working or not.
Having a utest directory or something would be really beneficial. That way,
I can at least run that test before I push it up to my tree.
-- Steve
^ permalink raw reply [flat|nested] 6+ messages in thread* Re: [PATCH 1/2] rtla/timerlat: Make timerlat_top_cpu->*_count unsigned long long
2024-10-11 17:23 ` Steven Rostedt
@ 2024-10-14 8:57 ` Tomas Glozar
0 siblings, 0 replies; 6+ messages in thread
From: Tomas Glozar @ 2024-10-14 8:57 UTC (permalink / raw)
To: Steven Rostedt
Cc: linux-trace-kernel, linux-kernel, jkacur, lgoncalv,
Attila Fazekas
pá 11. 10. 2024 v 19:23 odesílatel Steven Rostedt <rostedt@goodmis.org> napsal:
>
> Thanks, I'm applying these, but could you or someone else create a test
> directory in rtla and even rv that tests this code. I just examine it and
> run some basic operations, but I have no idea if it is really working or not.
>
> Having a utest directory or something would be really beneficial. That way,
> I can at least run that test before I push it up to my tree.
>
Yeah, we definitely need that, ideally to test expected behavior for
each common set of command line options. That would prevent unexpected
changes, like the recent defaulting to userspace threads requiring -k
to be used together with -U, otherwise, -U has no effect (because -u
is added by default). I'll look into that.
Tomas
^ permalink raw reply [flat|nested] 6+ messages in thread