Hi,
On Wed, Mar 15, 2023 at 12:07:20PM +0100, Eric Auger wrote:
> The pmu-chain-promotion test is composed of several subtests.
> In case of failures, the current logs are really dificult to
> analyze since they look very similar and sometimes duplicated
> for each subtest. Add prefixes for each subtest and introduce
> a macro that prints the registers we are mostly interested in,
> namerly the 2 first counters and the overflow counter.
One possible typo below.
Ran pmu-chain-promotion with and without this patch applied, the
improvement is very noticeable, it makes it very easy to match the debug
message with the subtest being run:
Reviewed-by: Alexandru Elisei <alexandru.elisei@xxxxxxx>
>
> Signed-off-by: Eric Auger <eric.auger@xxxxxxxxxx>
> ---
> arm/pmu.c | 63 ++++++++++++++++++++++++++++---------------------------
> 1 file changed, 32 insertions(+), 31 deletions(-)
>
> diff --git a/arm/pmu.c b/arm/pmu.c
> index f6e95012..dad7d4b4 100644
> --- a/arm/pmu.c
> +++ b/arm/pmu.c
> @@ -715,6 +715,11 @@ static void test_chained_sw_incr(bool unused)
> report_info("overflow=0x%lx, #0=0x%lx #1=0x%lx", read_sysreg(pmovsclr_el0),
> read_regn_el0(pmevcntr, 0), read_regn_el0(pmevcntr, 1));
> }
> +#define PRINT_REGS(__s) \
> + report_info("%s #1=0x%lx #0=0x%lx overflow=0x%lx", __s, \
> + read_regn_el0(pmevcntr, 1), \
> + read_regn_el0(pmevcntr, 0), \
> + read_sysreg(pmovsclr_el0))
>
> static void test_chain_promotion(bool unused)
> {
> @@ -725,6 +730,7 @@ static void test_chain_promotion(bool unused)
> return;
>
> /* Only enable CHAIN counter */
> + report_prefix_push("subtest1");
> pmu_reset();
> write_regn_el0(pmevtyper, 0, MEM_ACCESS | PMEVTYPER_EXCLUDE_EL0);
> write_regn_el0(pmevtyper, 1, CHAIN | PMEVTYPER_EXCLUDE_EL0);
> @@ -732,83 +738,81 @@ static void test_chain_promotion(bool unused)
> isb();
>
> mem_access_loop(addr, 20, pmu.pmcr_ro | PMU_PMCR_E);
> + PRINT_REGS("post");
> report(!read_regn_el0(pmevcntr, 0),
> "chain counter not counting if even counter is disabled");
> + report_prefix_pop();
>
> /* Only enable even counter */
> + report_prefix_push("subtest2");
> pmu_reset();
> write_regn_el0(pmevcntr, 0, PRE_OVERFLOW_32);
> write_sysreg_s(0x1, PMCNTENSET_EL0);
> isb();
>
> mem_access_loop(addr, 20, pmu.pmcr_ro | PMU_PMCR_E);
> + PRINT_REGS("post");
> report(!read_regn_el0(pmevcntr, 1) && (read_sysreg(pmovsclr_el0) == 0x1),
> "odd counter did not increment on overflow if disabled");
> - report_info("MEM_ACCESS counter #0 has value 0x%lx",
> - read_regn_el0(pmevcntr, 0));
> - report_info("CHAIN counter #1 has value 0x%lx",
> - read_regn_el0(pmevcntr, 1));
> - report_info("overflow counter 0x%lx", read_sysreg(pmovsclr_el0));
> + report_prefix_pop();
>
> /* start at 0xFFFFFFDC, +20 with CHAIN enabled, +20 with CHAIN disabled */
> + report_prefix_push("subtest3");
> pmu_reset();
> write_sysreg_s(0x3, PMCNTENSET_EL0);
> write_regn_el0(pmevcntr, 0, PRE_OVERFLOW2_32);
> isb();
> + PRINT_REGS("init");
>
> mem_access_loop(addr, 20, pmu.pmcr_ro | PMU_PMCR_E);
> - report_info("MEM_ACCESS counter #0 has value 0x%lx",
> - read_regn_el0(pmevcntr, 0));
> + PRINT_REGS("After 1st loop");
>
> /* disable the CHAIN event */
> write_sysreg_s(0x2, PMCNTENCLR_EL0);
> mem_access_loop(addr, 20, pmu.pmcr_ro | PMU_PMCR_E);
> - report_info("MEM_ACCESS counter #0 has value 0x%lx",
> - read_regn_el0(pmevcntr, 0));
> + PRINT_REGS("After 2d loop");
Hmm.. was that supposed to be "after 2**n**d loop" (matches the "after 1st
loop" message)? A few more instances below.
Thanks,
Alex
> report(read_sysreg(pmovsclr_el0) == 0x1,
> "should have triggered an overflow on #0");
> report(!read_regn_el0(pmevcntr, 1),
> "CHAIN counter #1 shouldn't have incremented");
> + report_prefix_pop();
>
> /* start at 0xFFFFFFDC, +20 with CHAIN disabled, +20 with CHAIN enabled */
>
> + report_prefix_push("subtest4");
> pmu_reset();
> write_sysreg_s(0x1, PMCNTENSET_EL0);
> write_regn_el0(pmevcntr, 0, PRE_OVERFLOW2_32);
> isb();
> - report_info("counter #0 = 0x%lx, counter #1 = 0x%lx overflow=0x%lx",
> - read_regn_el0(pmevcntr, 0), read_regn_el0(pmevcntr, 1),
> - read_sysreg(pmovsclr_el0));
> + PRINT_REGS("init");
>
> mem_access_loop(addr, 20, pmu.pmcr_ro | PMU_PMCR_E);
> - report_info("MEM_ACCESS counter #0 has value 0x%lx",
> - read_regn_el0(pmevcntr, 0));
> + PRINT_REGS("After 1st loop");
>
> /* enable the CHAIN event */
> write_sysreg_s(0x3, PMCNTENSET_EL0);
> isb();
> mem_access_loop(addr, 20, pmu.pmcr_ro | PMU_PMCR_E);
> - report_info("MEM_ACCESS counter #0 has value 0x%lx",
> - read_regn_el0(pmevcntr, 0));
> +
> + PRINT_REGS("After 2d loop");
>
> report((read_regn_el0(pmevcntr, 1) == 1) &&
> (read_sysreg(pmovsclr_el0) == 0x1),
> "CHAIN counter enabled: CHAIN counter was incremented and overflow");
> -
> - report_info("CHAIN counter #1 = 0x%lx, overflow=0x%lx",
> - read_regn_el0(pmevcntr, 1), read_sysreg(pmovsclr_el0));
> + report_prefix_pop();
>
> /* start as MEM_ACCESS/CPU_CYCLES and move to CHAIN/MEM_ACCESS */
> + report_prefix_push("subtest5");
> pmu_reset();
> write_regn_el0(pmevtyper, 0, MEM_ACCESS | PMEVTYPER_EXCLUDE_EL0);
> write_regn_el0(pmevtyper, 1, CPU_CYCLES | PMEVTYPER_EXCLUDE_EL0);
> write_sysreg_s(0x3, PMCNTENSET_EL0);
> write_regn_el0(pmevcntr, 0, PRE_OVERFLOW2_32);
> isb();
> + PRINT_REGS("init");
>
> mem_access_loop(addr, 20, pmu.pmcr_ro | PMU_PMCR_E);
> - report_info("MEM_ACCESS counter #0 has value 0x%lx",
> - read_regn_el0(pmevcntr, 0));
> + PRINT_REGS("After 1st loop");
>
> /* 0 becomes CHAINED */
> write_sysreg_s(0x0, PMCNTENSET_EL0);
> @@ -817,37 +821,34 @@ static void test_chain_promotion(bool unused)
> write_regn_el0(pmevcntr, 1, 0x0);
>
> mem_access_loop(addr, 20, pmu.pmcr_ro | PMU_PMCR_E);
> - report_info("MEM_ACCESS counter #0 has value 0x%lx",
> - read_regn_el0(pmevcntr, 0));
> + PRINT_REGS("After 2d loop");
>
> report((read_regn_el0(pmevcntr, 1) == 1) &&
> (read_sysreg(pmovsclr_el0) == 0x1),
> "32b->64b: CHAIN counter incremented and overflow");
> -
> - report_info("CHAIN counter #1 = 0x%lx, overflow=0x%lx",
> - read_regn_el0(pmevcntr, 1), read_sysreg(pmovsclr_el0));
> + report_prefix_pop();
>
> /* start as CHAIN/MEM_ACCESS and move to MEM_ACCESS/CPU_CYCLES */
> + report_prefix_push("subtest6");
> pmu_reset();
> write_regn_el0(pmevtyper, 0, MEM_ACCESS | PMEVTYPER_EXCLUDE_EL0);
> write_regn_el0(pmevtyper, 1, CHAIN | PMEVTYPER_EXCLUDE_EL0);
> write_regn_el0(pmevcntr, 0, PRE_OVERFLOW2_32);
> write_sysreg_s(0x3, PMCNTENSET_EL0);
> + PRINT_REGS("init");
>
> mem_access_loop(addr, 20, pmu.pmcr_ro | PMU_PMCR_E);
> - report_info("counter #0=0x%lx, counter #1=0x%lx",
> - read_regn_el0(pmevcntr, 0), read_regn_el0(pmevcntr, 1));
> + PRINT_REGS("After 1st loop");
>
> write_sysreg_s(0x0, PMCNTENSET_EL0);
> write_regn_el0(pmevtyper, 1, CPU_CYCLES | PMEVTYPER_EXCLUDE_EL0);
> write_sysreg_s(0x3, PMCNTENSET_EL0);
>
> mem_access_loop(addr, 20, pmu.pmcr_ro | PMU_PMCR_E);
> + PRINT_REGS("After 2d loop");
> report(read_sysreg(pmovsclr_el0) == 1,
> "overflow is expected on counter 0");
> - report_info("counter #0=0x%lx, counter #1=0x%lx overflow=0x%lx",
> - read_regn_el0(pmevcntr, 0), read_regn_el0(pmevcntr, 1),
> - read_sysreg(pmovsclr_el0));
> + report_prefix_pop();
> }
>
> static bool expect_interrupts(uint32_t bitmap)
> --
> 2.38.1
>
