[kvm-unit-tests PATCH 0/6] arm: Use stable test output lines

[kvm-unit-tests PATCH 0/6] arm: Use stable test output lines

[Andre Przywara]

When using kvm-unit-tests inside automated testing frameworks,
variable test naming becomes a problem. Some frameworks recognise tests
by their test output line and group the outputs from various runs for
statistical and reporting purposes. Having variable output like timer
values in there spoils this approach. Also the test name should be
somewhat self-explanatory, which is not true for every test.
Some examples highlighting the problem (TAP output from run-tests.sh -t):
ok 1 - selftest: setup: smp: nr_cpus = 2
ok 2 - selftest: setup: mem: size = 256 MB
ok 8 - selftest: smp: CPU(  1) mpidr=0080000001
ok 9 - selftest: smp: CPU(  2) mpidr=0080000002
ok 54 - gicv2: mmio: ITARGETSR: byte writes successful (0x1f => 0x01010001)
ok 55 - gicv2: mmio: all 3 CPUs have interrupts
ok 73 - invalid-function
ok 76 - cpu-on
ok 90 - ptimer-busy-loop: timer has expired (-8445)

This series aims to fix most of the problems, by making the actual test
report output line stable. I think this is best practises in the testing
world, at least when using TAP. We still retain the full information, by
moving every variable output into INFO: lines (which are still logged,
but typically filtered for automated processing).
The above lines now look like this:
ok 1 - selftest: setup: smp: number of CPUs matches expectation
ok 2 - selftest: setup: mem: memory size matches expectation
ok 8 - selftest: smp: MPIDR test on all CPUs
ok 49 - gicv2: mmio: ITARGETSR: byte writes successful
ok 50 - gicv2: mmio: all CPUs have interrupts
ok 68 - psci: invalid-function
ok 71 - psci: cpu-on
ok 85 - ptimer-busy-loop: timer has expired

Looks a bit more boring, but it's nicer for automated processing and
logging.

I am open for a discussion about the general approach, thus this is
dealing with ARM tests for now only.

Looking forward to any feedback!

Cheers,
Andre

Andre Przywara (6):
  arm: gic: check_acked: add test description
  arm: gic: Split variable output data from test name
  arm: timer: Split variable output data from test name
  arm: selftest: Split variable output data from test name
  arm: selftest: Make MPIDR output stable
  arm: Add missing test name prefix calls

 arm/gic.c      | 64 ++++++++++++++++++++++++++++++--------------------
 arm/pci-test.c |  2 ++
 arm/psci.c     |  2 ++
 arm/selftest.c | 23 ++++++++++++++----
 arm/timer.c    |  3 ++-
 5 files changed, 62 insertions(+), 32 deletions(-)

-- 
2.17.1

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

[Andre Przywara]

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);
 			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);
 	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

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

[Andrew Jones]

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.

>  			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

>  	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 

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

[Andre Przywara]

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 

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

[Andrew Jones]

On Fri, Sep 27, 2019 at 01:40:16PM +0100, Andre Przywara wrote:
> 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.

OK, with that argument we can leave the '++' off.

Thanks,
drew

[kvm-unit-tests PATCH 2/6] arm: gic: Split variable output data from test name

[Andre Przywara]

For some tests we mix variable diagnostic output with the test name,
which leads to variable test line, confusing some higher level
frameworks.

Split the output to always use the same test name for a certain test,
and put diagnostic output on a separate line using the INFO: tag.

Signed-off-by: Andre Przywara <andre.przywara@arm.com>
---
 arm/gic.c | 45 ++++++++++++++++++++++++++-------------------
 1 file changed, 26 insertions(+), 19 deletions(-)

diff --git a/arm/gic.c b/arm/gic.c
index 6fd5e5e..66dcafe 100644
--- a/arm/gic.c
+++ b/arm/gic.c
@@ -353,8 +353,8 @@ static void test_typer_v2(uint32_t reg)
 {
 	int nr_gic_cpus = ((reg >> 5) & 0x7) + 1;
 
-	report("all %d CPUs have interrupts", nr_cpus == nr_gic_cpus,
-	       nr_gic_cpus);
+	report("all CPUs have interrupts", nr_cpus == nr_gic_cpus);
+	report_info("having %d CPUs", nr_gic_cpus);
 }
 
 #define BYTE(reg32, byte) (((reg32) >> ((byte) * 8)) & 0xff)
@@ -370,16 +370,21 @@ static void test_typer_v2(uint32_t reg)
 static void test_byte_access(void *base_addr, u32 pattern, u32 mask)
 {
 	u32 reg = readb(base_addr + 1);
+	bool res;
 
-	report("byte reads successful (0x%08x => 0x%02x)",
-	       reg == (BYTE(pattern, 1) & (mask >> 8)),
-	       pattern & mask, reg);
+	res = (reg == (BYTE(pattern, 1) & (mask >> 8)));
+	report("byte reads successful", res);
+	if (!res)
+		report_info("byte 1 of 0x%08x => 0x%02x", pattern & mask, reg);
 
 	pattern = REPLACE_BYTE(pattern, 2, 0x1f);
 	writeb(BYTE(pattern, 2), base_addr + 2);
 	reg = readl(base_addr);
-	report("byte writes successful (0x%02x => 0x%08x)",
-	       reg == (pattern & mask), BYTE(pattern, 2), reg);
+	res = (reg == (pattern & mask));
+	report("byte writes successful", res);
+	if (!res)
+		report_info("writing 0x%02x into bytes 2 => 0x%08x",
+			    BYTE(pattern, 2), reg);
 }
 
 static void test_priorities(int nr_irqs, void *priptr)
@@ -399,15 +404,16 @@ static void test_priorities(int nr_irqs, void *priptr)
 	pri_mask = readl(first_spi);
 
 	reg = ~pri_mask;
-	report("consistent priority masking (0x%08x)",
+	report("consistent priority masking",
 	       (((reg >> 16) == (reg & 0xffff)) &&
-	        ((reg & 0xff) == ((reg >> 8) & 0xff))), pri_mask);
+	        ((reg & 0xff) == ((reg >> 8) & 0xff))));
+	report_info("priority mask is 0x%08x", pri_mask);
 
 	reg = reg & 0xff;
 	for (pri_bits = 8; reg & 1; reg >>= 1, pri_bits--)
 		;
-	report("implements at least 4 priority bits (%d)",
-	       pri_bits >= 4, pri_bits);
+	report("implements at least 4 priority bits", pri_bits >= 4);
+	report_info("%d priority bits implemented", pri_bits);
 
 	pattern = 0;
 	writel(pattern, first_spi);
@@ -452,9 +458,9 @@ static void test_targets(int nr_irqs)
 	/* Check that bits for non implemented CPUs are RAZ/WI. */
 	if (nr_cpus < 8) {
 		writel(0xffffffff, targetsptr + GIC_FIRST_SPI);
-		report("bits for %d non-existent CPUs masked",
-		       !(readl(targetsptr + GIC_FIRST_SPI) & ~cpu_mask),
-		       8 - nr_cpus);
+		report("bits for non-existent CPUs masked",
+		       !(readl(targetsptr + GIC_FIRST_SPI) & ~cpu_mask));
+		report_info("%d non-existent CPUs", 8 - nr_cpus);
 	} else {
 		report_skip("CPU masking (all CPUs implemented)");
 	}
@@ -465,8 +471,10 @@ static void test_targets(int nr_irqs)
 	pattern = 0x0103020f;
 	writel(pattern, targetsptr + GIC_FIRST_SPI);
 	reg = readl(targetsptr + GIC_FIRST_SPI);
-	report("register content preserved (%08x => %08x)",
-	       reg == (pattern & cpu_mask), pattern & cpu_mask, reg);
+	report("register content preserved", reg == (pattern & cpu_mask));
+	if (reg != (pattern & cpu_mask))
+		report_info("writing %08x reads back as %08x",
+			    pattern & cpu_mask, reg);
 
 	/* The TARGETS registers are byte accessible. */
 	test_byte_access(targetsptr + GIC_FIRST_SPI, pattern, cpu_mask);
@@ -505,9 +513,8 @@ static void gic_test_mmio(void)
 	       test_readonly_32(gic_dist_base + GICD_IIDR, false));
 
 	reg = readl(idreg);
-	report("ICPIDR2 is read-only (0x%08x)",
-	       test_readonly_32(idreg, false),
-	       reg);
+	report("ICPIDR2 is read-only", test_readonly_32(idreg, false));
+	report_info("value of ICPIDR2: 0x%08x", reg);
 
 	test_priorities(nr_irqs, gic_dist_base + GICD_IPRIORITYR);
 
-- 
2.17.1

Re: [kvm-unit-tests PATCH 2/6] arm: gic: Split variable output data from test name

[Andrew Jones]

On Fri, Sep 27, 2019 at 11:42:23AM +0100, Andre Przywara wrote:
> For some tests we mix variable diagnostic output with the test name,
> which leads to variable test line, confusing some higher level
> frameworks.
> 
> Split the output to always use the same test name for a certain test,
> and put diagnostic output on a separate line using the INFO: tag.
> 
> Signed-off-by: Andre Przywara <andre.przywara@arm.com>
> ---
>  arm/gic.c | 45 ++++++++++++++++++++++++++-------------------
>  1 file changed, 26 insertions(+), 19 deletions(-)
> 
> diff --git a/arm/gic.c b/arm/gic.c
> index 6fd5e5e..66dcafe 100644
> --- a/arm/gic.c
> +++ b/arm/gic.c
> @@ -353,8 +353,8 @@ static void test_typer_v2(uint32_t reg)
>  {
>  	int nr_gic_cpus = ((reg >> 5) & 0x7) + 1;
>  
> -	report("all %d CPUs have interrupts", nr_cpus == nr_gic_cpus,
> -	       nr_gic_cpus);
> +	report("all CPUs have interrupts", nr_cpus == nr_gic_cpus);
> +	report_info("having %d CPUs", nr_gic_cpus);

Maybe slightly better:

 report_info("nr_cpus=%d", nr_cpus);
 report("all CPUs have interrupts", nr_cpus == nr_gic_cpus);

>  }
>  
>  #define BYTE(reg32, byte) (((reg32) >> ((byte) * 8)) & 0xff)
> @@ -370,16 +370,21 @@ static void test_typer_v2(uint32_t reg)
>  static void test_byte_access(void *base_addr, u32 pattern, u32 mask)
>  {
>  	u32 reg = readb(base_addr + 1);
> +	bool res;
>  
> -	report("byte reads successful (0x%08x => 0x%02x)",
> -	       reg == (BYTE(pattern, 1) & (mask >> 8)),
> -	       pattern & mask, reg);
> +	res = (reg == (BYTE(pattern, 1) & (mask >> 8)));
> +	report("byte reads successful", res);
> +	if (!res)
> +		report_info("byte 1 of 0x%08x => 0x%02x", pattern & mask, reg);
>  
>  	pattern = REPLACE_BYTE(pattern, 2, 0x1f);
>  	writeb(BYTE(pattern, 2), base_addr + 2);
>  	reg = readl(base_addr);
> -	report("byte writes successful (0x%02x => 0x%08x)",
> -	       reg == (pattern & mask), BYTE(pattern, 2), reg);
> +	res = (reg == (pattern & mask));
> +	report("byte writes successful", res);
> +	if (!res)
> +		report_info("writing 0x%02x into bytes 2 => 0x%08x",
> +			    BYTE(pattern, 2), reg);
>  }
>  
>  static void test_priorities(int nr_irqs, void *priptr)
> @@ -399,15 +404,16 @@ static void test_priorities(int nr_irqs, void *priptr)
>  	pri_mask = readl(first_spi);
>  
>  	reg = ~pri_mask;
> -	report("consistent priority masking (0x%08x)",
> +	report("consistent priority masking",
>  	       (((reg >> 16) == (reg & 0xffff)) &&
> -	        ((reg & 0xff) == ((reg >> 8) & 0xff))), pri_mask);
> +	        ((reg & 0xff) == ((reg >> 8) & 0xff))));
> +	report_info("priority mask is 0x%08x", pri_mask);
>  
>  	reg = reg & 0xff;
>  	for (pri_bits = 8; reg & 1; reg >>= 1, pri_bits--)
>  		;
> -	report("implements at least 4 priority bits (%d)",
> -	       pri_bits >= 4, pri_bits);
> +	report("implements at least 4 priority bits", pri_bits >= 4);
> +	report_info("%d priority bits implemented", pri_bits);
>  
>  	pattern = 0;
>  	writel(pattern, first_spi);
> @@ -452,9 +458,9 @@ static void test_targets(int nr_irqs)
>  	/* Check that bits for non implemented CPUs are RAZ/WI. */
>  	if (nr_cpus < 8) {
>  		writel(0xffffffff, targetsptr + GIC_FIRST_SPI);
> -		report("bits for %d non-existent CPUs masked",
> -		       !(readl(targetsptr + GIC_FIRST_SPI) & ~cpu_mask),
> -		       8 - nr_cpus);
> +		report("bits for non-existent CPUs masked",
> +		       !(readl(targetsptr + GIC_FIRST_SPI) & ~cpu_mask));
> +		report_info("%d non-existent CPUs", 8 - nr_cpus);
>  	} else {
>  		report_skip("CPU masking (all CPUs implemented)");
>  	}
> @@ -465,8 +471,10 @@ static void test_targets(int nr_irqs)
>  	pattern = 0x0103020f;
>  	writel(pattern, targetsptr + GIC_FIRST_SPI);
>  	reg = readl(targetsptr + GIC_FIRST_SPI);
> -	report("register content preserved (%08x => %08x)",
> -	       reg == (pattern & cpu_mask), pattern & cpu_mask, reg);
> +	report("register content preserved", reg == (pattern & cpu_mask));
> +	if (reg != (pattern & cpu_mask))
> +		report_info("writing %08x reads back as %08x",
> +			    pattern & cpu_mask, reg);
>  
>  	/* The TARGETS registers are byte accessible. */
>  	test_byte_access(targetsptr + GIC_FIRST_SPI, pattern, cpu_mask);
> @@ -505,9 +513,8 @@ static void gic_test_mmio(void)
>  	       test_readonly_32(gic_dist_base + GICD_IIDR, false));
>  
>  	reg = readl(idreg);
> -	report("ICPIDR2 is read-only (0x%08x)",
> -	       test_readonly_32(idreg, false),
> -	       reg);
> +	report("ICPIDR2 is read-only", test_readonly_32(idreg, false));
> +	report_info("value of ICPIDR2: 0x%08x", reg);
>  
>  	test_priorities(nr_irqs, gic_dist_base + GICD_IPRIORITYR);
>  
> -- 
> 2.17.1
>

Otherwise looks good to me

Thanks,
drew 

[kvm-unit-tests PATCH 3/6] arm: timer: Split variable output data from test name

[Andre Przywara]

For some tests we mix variable diagnostic output with the test name,
which leads to variable test line, confusing some higher level
frameworks.

Split the output to always use the same test name for a certain test,
and put diagnostic output on a separate line using the INFO: tag.

Signed-off-by: Andre Przywara <andre.przywara@arm.com>
---
 arm/timer.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/arm/timer.c b/arm/timer.c
index f2f6019..0b808d5 100644
--- a/arm/timer.c
+++ b/arm/timer.c
@@ -249,7 +249,8 @@ static void test_timer(struct timer_info *info)
 	local_irq_enable();
 	left = info->read_tval();
 	report("interrupt received after TVAL/WFI", info->irq_received);
-	report("timer has expired (%d)", left < 0, left);
+	report("timer has expired", left < 0);
+	report_info("TVAL is %d ticks", left);
 }
 
 static void test_vtimer(void)
-- 
2.17.1

Re: [kvm-unit-tests PATCH 3/6] arm: timer: Split variable output data from test name

[Andrew Jones]

On Fri, Sep 27, 2019 at 11:42:24AM +0100, Andre Przywara wrote:
> For some tests we mix variable diagnostic output with the test name,
> which leads to variable test line, confusing some higher level
> frameworks.
> 
> Split the output to always use the same test name for a certain test,
> and put diagnostic output on a separate line using the INFO: tag.
> 
> Signed-off-by: Andre Przywara <andre.przywara@arm.com>
> ---
>  arm/timer.c | 3 ++-
>  1 file changed, 2 insertions(+), 1 deletion(-)
> 
> diff --git a/arm/timer.c b/arm/timer.c
> index f2f6019..0b808d5 100644
> --- a/arm/timer.c
> +++ b/arm/timer.c
> @@ -249,7 +249,8 @@ static void test_timer(struct timer_info *info)
>  	local_irq_enable();
>  	left = info->read_tval();
>  	report("interrupt received after TVAL/WFI", info->irq_received);
> -	report("timer has expired (%d)", left < 0, left);
> +	report("timer has expired", left < 0);
> +	report_info("TVAL is %d ticks", left);
>  }
>  
>  static void test_vtimer(void)
> -- 
> 2.17.1
>

Reviewed-by: Andrew Jones <drjones@redhat.com>

[kvm-unit-tests PATCH 4/6] arm: selftest: Split variable output data from test name

[Andre Przywara]

For some tests we mix variable diagnostic output with the test name,
which leads to variable test line, confusing some higher level
frameworks.

Split the output to always use the same test name for a certain test,
and put diagnostic output on a separate line using the INFO: tag.

Signed-off-by: Andre Przywara <andre.przywara@arm.com>
---
 arm/selftest.c | 9 ++++++---
 1 file changed, 6 insertions(+), 3 deletions(-)

diff --git a/arm/selftest.c b/arm/selftest.c
index 28a17f7..a0c1ab8 100644
--- a/arm/selftest.c
+++ b/arm/selftest.c
@@ -43,13 +43,16 @@ static void check_setup(int argc, char **argv)
 			phys_addr_t memsize = PHYS_END - PHYS_OFFSET;
 			phys_addr_t expected = ((phys_addr_t)val)*1024*1024;
 
-			report("size = %" PRIu64 " MB", memsize == expected,
-							memsize/1024/1024);
+			report("memory size matches expectation",
+			       memsize == expected);
+			report_info("found %" PRIu64 " MB", memsize/1024/1024);
 			++nr_tests;
 
 		} else if (strcmp(argv[i], "smp") == 0) {
 
-			report("nr_cpus = %d", nr_cpus == (int)val, nr_cpus);
+			report("number of CPUs matches expectation",
+			       nr_cpus == (int)val);
+			report_info("found %d CPUs", nr_cpus);
 			++nr_tests;
 		}
 
-- 
2.17.1

Re: [kvm-unit-tests PATCH 4/6] arm: selftest: Split variable output data from test name

[Andrew Jones]

On Fri, Sep 27, 2019 at 11:42:25AM +0100, Andre Przywara wrote:
> For some tests we mix variable diagnostic output with the test name,
> which leads to variable test line, confusing some higher level
> frameworks.
> 
> Split the output to always use the same test name for a certain test,
> and put diagnostic output on a separate line using the INFO: tag.
> 
> Signed-off-by: Andre Przywara <andre.przywara@arm.com>
> ---
>  arm/selftest.c | 9 ++++++---
>  1 file changed, 6 insertions(+), 3 deletions(-)
> 
> diff --git a/arm/selftest.c b/arm/selftest.c
> index 28a17f7..a0c1ab8 100644
> --- a/arm/selftest.c
> +++ b/arm/selftest.c
> @@ -43,13 +43,16 @@ static void check_setup(int argc, char **argv)
>  			phys_addr_t memsize = PHYS_END - PHYS_OFFSET;
>  			phys_addr_t expected = ((phys_addr_t)val)*1024*1024;
>  
> -			report("size = %" PRIu64 " MB", memsize == expected,
> -							memsize/1024/1024);
> +			report("memory size matches expectation",
> +			       memsize == expected);
> +			report_info("found %" PRIu64 " MB", memsize/1024/1024);
>  			++nr_tests;
>  
>  		} else if (strcmp(argv[i], "smp") == 0) {
>  
> -			report("nr_cpus = %d", nr_cpus == (int)val, nr_cpus);
> +			report("number of CPUs matches expectation",
> +			       nr_cpus == (int)val);
> +			report_info("found %d CPUs", nr_cpus);
>  			++nr_tests;
>  		}
>  
> -- 
> 2.17.1
>

Reviewed-by: Andrew Jones <drjones@redhat.com>

[kvm-unit-tests PATCH 5/6] arm: selftest: Make MPIDR output stable

[Andre Przywara]

At the moment the smp selftest outputs one line for each vCPU, with the
CPU number and its MPIDR printed in the same test result line.
For automated test frameworks this has the problem of including variable
output in the test name, also the number of tests varies, depending on the
number of vCPUs.

Fix this by only generating a single line of output for the SMP test,
which summarises the result. We use two cpumasks, to let each vCPU report
its result and completion of the test (code stolen from the GIC test).

For informational purposes we keep the one line per CPU, but prefix it
with an INFO: tag, so that frameworks can ignore it.

Signed-off-by: Andre Przywara <andre.przywara@arm.com>
---
 arm/selftest.c | 14 ++++++++++++--
 1 file changed, 12 insertions(+), 2 deletions(-)

diff --git a/arm/selftest.c b/arm/selftest.c
index a0c1ab8..e9dc5c0 100644
--- a/arm/selftest.c
+++ b/arm/selftest.c
@@ -17,6 +17,8 @@
 #include <asm/smp.h>
 #include <asm/barrier.h>
 
+static cpumask_t ready, valid;
+
 static void __user_psci_system_off(void)
 {
 	psci_system_off();
@@ -341,8 +343,11 @@ static void cpu_report(void *data __unused)
 	uint64_t mpidr = get_mpidr();
 	int cpu = smp_processor_id();
 
-	report("CPU(%3d) mpidr=%010" PRIx64,
-		mpidr_to_cpu(mpidr) == cpu, cpu, mpidr);
+	if (mpidr_to_cpu(mpidr) == cpu)
+		cpumask_set_cpu(smp_processor_id(), &valid);
+	smp_wmb();		/* Paired with rmb in main(). */
+	cpumask_set_cpu(smp_processor_id(), &ready);
+	report_info("CPU%3d: MPIDR=%010" PRIx64, cpu, mpidr);
 }
 
 int main(int argc, char **argv)
@@ -371,6 +376,11 @@ int main(int argc, char **argv)
 
 		report("PSCI version", psci_check());
 		on_cpus(cpu_report, NULL);
+		while (!cpumask_full(&ready))
+			cpu_relax();
+		smp_rmb();		/* Paired with wmb in cpu_report(). */
+		report("MPIDR test on all CPUs", cpumask_full(&valid));
+		report_info("%d CPUs reported back", nr_cpus);
 
 	} else {
 		printf("Unknown subtest\n");
-- 
2.17.1

Re: [kvm-unit-tests PATCH 5/6] arm: selftest: Make MPIDR output stable

[Andrew Jones]

On Fri, Sep 27, 2019 at 11:42:26AM +0100, Andre Przywara wrote:
> At the moment the smp selftest outputs one line for each vCPU, with the
> CPU number and its MPIDR printed in the same test result line.
> For automated test frameworks this has the problem of including variable
> output in the test name, also the number of tests varies, depending on the
> number of vCPUs.
> 
> Fix this by only generating a single line of output for the SMP test,
> which summarises the result. We use two cpumasks, to let each vCPU report
> its result and completion of the test (code stolen from the GIC test).
> 
> For informational purposes we keep the one line per CPU, but prefix it
> with an INFO: tag, so that frameworks can ignore it.
> 
> Signed-off-by: Andre Przywara <andre.przywara@arm.com>
> ---
>  arm/selftest.c | 14 ++++++++++++--
>  1 file changed, 12 insertions(+), 2 deletions(-)
> 
> diff --git a/arm/selftest.c b/arm/selftest.c
> index a0c1ab8..e9dc5c0 100644
> --- a/arm/selftest.c
> +++ b/arm/selftest.c
> @@ -17,6 +17,8 @@
>  #include <asm/smp.h>
>  #include <asm/barrier.h>
>  
> +static cpumask_t ready, valid;
> +
>  static void __user_psci_system_off(void)
>  {
>  	psci_system_off();
> @@ -341,8 +343,11 @@ static void cpu_report(void *data __unused)
>  	uint64_t mpidr = get_mpidr();
>  	int cpu = smp_processor_id();
>  
> -	report("CPU(%3d) mpidr=%010" PRIx64,
> -		mpidr_to_cpu(mpidr) == cpu, cpu, mpidr);
> +	if (mpidr_to_cpu(mpidr) == cpu)
> +		cpumask_set_cpu(smp_processor_id(), &valid);
> +	smp_wmb();		/* Paired with rmb in main(). */
> +	cpumask_set_cpu(smp_processor_id(), &ready);
> +	report_info("CPU%3d: MPIDR=%010" PRIx64, cpu, mpidr);
>  }
>  
>  int main(int argc, char **argv)
> @@ -371,6 +376,11 @@ int main(int argc, char **argv)
>  
>  		report("PSCI version", psci_check());
>  		on_cpus(cpu_report, NULL);
> +		while (!cpumask_full(&ready))
> +			cpu_relax();
> +		smp_rmb();		/* Paired with wmb in cpu_report(). */
> +		report("MPIDR test on all CPUs", cpumask_full(&valid));
> +		report_info("%d CPUs reported back", nr_cpus);
>  
>  	} else {
>  		printf("Unknown subtest\n");
> -- 
> 2.17.1
>

Reviewed-by: Andrew Jones <drjones@redhat.com>

[kvm-unit-tests PATCH 6/6] arm: Add missing test name prefix calls

[Andre Przywara]

When running the unit tests in TAP mode (./run_tests.sh -t), every single
test result is printed. This works fine for most tests which use the
reporting prefix feature to indicate the actual test name.
However psci and pci were missing those names, so the reporting left
people scratching their head what was actually tested:
...
ok 74 - invalid-function
ok 75 - affinity-info-on
ok 76 - affinity-info-off
ok 77 - cpu-on

Push a "psci" prefix before running those tests to make those report
lines more descriptive.
While at it, do the same for pci, even though it is less ambigious there.
Also the GIC ITARGETSR test was missing a report_prefix_pop().

Signed-off-by: Andre Przywara <andre.przywara@arm.com>
---
 arm/gic.c      | 2 ++
 arm/pci-test.c | 2 ++
 arm/psci.c     | 2 ++
 3 files changed, 6 insertions(+)

diff --git a/arm/gic.c b/arm/gic.c
index 66dcafe..ebb6ea2 100644
--- a/arm/gic.c
+++ b/arm/gic.c
@@ -480,6 +480,8 @@ static void test_targets(int nr_irqs)
 	test_byte_access(targetsptr + GIC_FIRST_SPI, pattern, cpu_mask);
 
 	writel(orig_targets, targetsptr + GIC_FIRST_SPI);
+
+	report_prefix_pop();
 }
 
 static void gic_test_mmio(void)
diff --git a/arm/pci-test.c b/arm/pci-test.c
index cf128ac..7c3836e 100644
--- a/arm/pci-test.c
+++ b/arm/pci-test.c
@@ -19,6 +19,8 @@ int main(void)
 		return report_summary();
 	}
 
+	report_prefix_push("pci");
+
 	pci_print();
 
 	ret = pci_testdev();
diff --git a/arm/psci.c b/arm/psci.c
index 5cb4d5c..536c9b7 100644
--- a/arm/psci.c
+++ b/arm/psci.c
@@ -126,6 +126,8 @@ int main(void)
 {
 	int ver = psci_invoke(PSCI_0_2_FN_PSCI_VERSION, 0, 0, 0);
 
+	report_prefix_push("psci");
+
 	if (nr_cpus < 2) {
 		report_skip("At least 2 cpus required");
 		goto done;
-- 
2.17.1

Re: [kvm-unit-tests PATCH 6/6] arm: Add missing test name prefix calls

[Andrew Jones]

On Fri, Sep 27, 2019 at 11:42:27AM +0100, Andre Przywara wrote:
> When running the unit tests in TAP mode (./run_tests.sh -t), every single
> test result is printed. This works fine for most tests which use the
> reporting prefix feature to indicate the actual test name.
> However psci and pci were missing those names, so the reporting left
> people scratching their head what was actually tested:
> ...
> ok 74 - invalid-function
> ok 75 - affinity-info-on
> ok 76 - affinity-info-off
> ok 77 - cpu-on
> 
> Push a "psci" prefix before running those tests to make those report
> lines more descriptive.
> While at it, do the same for pci, even though it is less ambigious there.
> Also the GIC ITARGETSR test was missing a report_prefix_pop().
> 
> Signed-off-by: Andre Przywara <andre.przywara@arm.com>
> ---
>  arm/gic.c      | 2 ++
>  arm/pci-test.c | 2 ++
>  arm/psci.c     | 2 ++
>  3 files changed, 6 insertions(+)
> 
> diff --git a/arm/gic.c b/arm/gic.c
> index 66dcafe..ebb6ea2 100644
> --- a/arm/gic.c
> +++ b/arm/gic.c
> @@ -480,6 +480,8 @@ static void test_targets(int nr_irqs)
>  	test_byte_access(targetsptr + GIC_FIRST_SPI, pattern, cpu_mask);
>  
>  	writel(orig_targets, targetsptr + GIC_FIRST_SPI);
> +
> +	report_prefix_pop();
>  }
>  
>  static void gic_test_mmio(void)
> diff --git a/arm/pci-test.c b/arm/pci-test.c
> index cf128ac..7c3836e 100644
> --- a/arm/pci-test.c
> +++ b/arm/pci-test.c
> @@ -19,6 +19,8 @@ int main(void)
>  		return report_summary();
>  	}
>  
> +	report_prefix_push("pci");
> +
>  	pci_print();
>  
>  	ret = pci_testdev();
> diff --git a/arm/psci.c b/arm/psci.c
> index 5cb4d5c..536c9b7 100644
> --- a/arm/psci.c
> +++ b/arm/psci.c
> @@ -126,6 +126,8 @@ int main(void)
>  {
>  	int ver = psci_invoke(PSCI_0_2_FN_PSCI_VERSION, 0, 0, 0);
>  
> +	report_prefix_push("psci");
> +
>  	if (nr_cpus < 2) {
>  		report_skip("At least 2 cpus required");
>  		goto done;
> -- 
> 2.17.1
>

Reviewed-by: Andrew Jones <drjones@redhat.com>