[PATCH 1/2] rtla/timerlat: Make timerlat_top_cpu->*_count unsigned long long

[PATCH 1/2] rtla/timerlat: Make timerlat_top_cpu->*_count unsigned long long

[tglozar]

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

[PATCH 2/2] rtla/timerlat: Make timerlat_hist_cpu->*_count unsigned long long

[tglozar]

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

Re: [PATCH 1/2] rtla/timerlat: Make timerlat_top_cpu->*_count unsigned long long

[John Kacur]

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>

Re: [PATCH 2/2] rtla/timerlat: Make timerlat_hist_cpu->*_count unsigned long long

[John Kacur]

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>

Re: [PATCH 1/2] rtla/timerlat: Make timerlat_top_cpu->*_count unsigned long long

[Steven Rostedt]

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

Re: [PATCH 1/2] rtla/timerlat: Make timerlat_top_cpu->*_count unsigned long long

[Tomas Glozar]

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