| Message ID | 20190927104227.253466-2-andre.przywara@arm.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
| Series | arm: Use stable test output lines | expand |
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
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
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
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(); }
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(-)