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

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

[Andre Przywara]

Hi,

a minor update addressing Drew's comments.
Changelog v1 ... v2:
- rewording IPI test names
- reordering number-of-CPUs reporting
- add Drew's Reviewed-by: tags

Cheers,
Andre.

-------------------------------------------
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!

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 v2 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..2ec4070 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: 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("IPI: directed", &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

[kvm-unit-tests PATCH v2 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 2ec4070..02d2928 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_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

[kvm-unit-tests PATCH v2 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>
Reviewed-by: Andrew Jones <drjones@redhat.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

[kvm-unit-tests PATCH v2 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>
Reviewed-by: Andrew Jones <drjones@redhat.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

[kvm-unit-tests PATCH v2 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>
Reviewed-by: Andrew Jones <drjones@redhat.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

[kvm-unit-tests PATCH v2 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>
Reviewed-by: Andrew Jones <drjones@redhat.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 02d2928..adb6aa4 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 v2 1/6] arm: gic: check_acked: add test description

[Andrew Jones]

On Fri, Oct 04, 2019 at 03:18:24PM +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(-)
>

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

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

[Andrew Jones]

On Fri, Oct 04, 2019 at 03:18:25PM +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(-)
>

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