Re: [kvm-unit-tests PATCH 1/6] arm: gic: check_acked: add test description

[Andre Przywara <andre.przywara@arm.com>]

On Fri, 27 Sep 2019 14:18:45 +0200
Andrew Jones <drjones@redhat.com> wrote:

Hi,

> On Fri, Sep 27, 2019 at 11:42:22AM +0100, Andre Przywara wrote:
> > At the moment the check_acked() IRQ helper function just prints a
> > generic "Completed" or "Timed out" message, without given a more
> > detailed test description.
> > 
> > To be able to tell the different IRQ tests apart, and also to allow
> > re-using it more easily, add a "description" parameter string,
> > which is prefixing the output line. This gives more information on what
> > exactly was tested.
> > 
> > This also splits the variable output part of the line (duration of IRQ
> > delivery) into a separate INFO: line, to not confuse testing frameworks.
> > 
> > Signed-off-by: Andre Przywara <andre.przywara@arm.com>
> > ---
> >  arm/gic.c | 17 ++++++++++-------
> >  1 file changed, 10 insertions(+), 7 deletions(-)
> > 
> > diff --git a/arm/gic.c b/arm/gic.c
> > index ed5642e..6fd5e5e 100644
> > --- a/arm/gic.c
> > +++ b/arm/gic.c
> > @@ -60,7 +60,7 @@ static void stats_reset(void)
> >  	smp_wmb();
> >  }
> >  
> > -static void check_acked(cpumask_t *mask)
> > +static void check_acked(const char *testname, cpumask_t *mask)
> >  {
> >  	int missing = 0, extra = 0, unexpected = 0;
> >  	int nr_pass, cpu, i;
> > @@ -88,7 +88,9 @@ static void check_acked(cpumask_t *mask)
> >  			}
> >  		}
> >  		if (nr_pass == nr_cpus) {
> > -			report("Completed in %d ms", !bad, ++i * 100);
> > +			report("%s", !bad, testname);
> > +			if (i)
> > +				report_info("took more than %d ms", i * 100);  
> 
> Any reason for dropping the '++'? Without it we don't account for the last
> 100 ms.

Actually we expect the interrupt to either fire immediately, or to not fire at all (timeout). So the previous message of "Completed in 100 ms" was somewhat misleading, because this was just due to the mdelay(100) above, and the IRQ was most probably delivered before this delay loop even started.

I had "took less than ++i *100 ms" before (and can revert to that if you like), but then figured that filtering for the most common case (immediate delivery) is more useful.

> 
> >  			return;
> >  		}
> >  	}
> > @@ -105,8 +107,9 @@ static void check_acked(cpumask_t *mask)
> >  		}
> >  	}
> >  
> > -	report("Timed-out (5s). ACKS: missing=%d extra=%d unexpected=%d",
> > -	       false, missing, extra, unexpected);
> > +	report("%s", false, testname);
> > +	report_info("Timed-out (5s). ACKS: missing=%d extra=%d unexpected=%d",
> > +		    missing, extra, unexpected);
> >  }
> >  
> >  static void check_spurious(void)
> > @@ -185,7 +188,7 @@ static void ipi_test_self(void)
> >  	cpumask_clear(&mask);
> >  	cpumask_set_cpu(smp_processor_id(), &mask);
> >  	gic->ipi.send_self();
> > -	check_acked(&mask);
> > +	check_acked("IPI to self", &mask);  
> 
> Could even do "IPI: self"
>               "IPI: directed"
>               "IPI: broadcast"
> 
> to improve parsibility

Indeed.

Thanks for having a look!

Cheers,
Andre.



> 
> >  	report_prefix_pop();
> >  }
> >  
> > @@ -200,7 +203,7 @@ static void ipi_test_smp(void)
> >  	for (i = smp_processor_id() & 1; i < nr_cpus; i += 2)
> >  		cpumask_clear_cpu(i, &mask);
> >  	gic_ipi_send_mask(IPI_IRQ, &mask);
> > -	check_acked(&mask);
> > +	check_acked("directed IPI", &mask);
> >  	report_prefix_pop();
> >  
> >  	report_prefix_push("broadcast");
> > @@ -208,7 +211,7 @@ static void ipi_test_smp(void)
> >  	cpumask_copy(&mask, &cpu_present_mask);
> >  	cpumask_clear_cpu(smp_processor_id(), &mask);
> >  	gic->ipi.send_broadcast();
> > -	check_acked(&mask);
> > +	check_acked("IPI broadcast", &mask);
> >  	report_prefix_pop();
> >  }
> >  
> > -- 
> > 2.17.1
> >  
> 
> Thanks,
> drew