| Message ID | 20241011121015.2868751-1-tglozar@redhat.com (mailing list archive) |
|---|---|
| State | Queued |
| Headers | show |
| Series | [1/2] rtla/timerlat: Make timerlat_top_cpu->*_count unsigned long long | expand |
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>
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
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
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);