Re: [PATCH v2 4/5] lib/cpumask_kunit: log mask contents

[Sander Vanheule]

Hi Maíra,

On Sun, 2022-08-21 at 11:02 -0300, Maíra Canal wrote:
> 
> 
> On 8/21/22 10:13, Sander Vanheule wrote:
> > On Sat, 2022-08-20 at 14:46 -0700, Yury Norov wrote:
> > > On Sat, Aug 20, 2022 at 05:03:12PM +0200, Sander Vanheule wrote:
> > > > For extra context, log the contents of the masks under test.  This
> > > > should help with finding out why a certain test fails.
> > > > 
> > > > Link:
> > > > https://lore.kernel.org/lkml/CABVgOSkPXBc-PWk1zBZRQ_Tt+Sz1ruFHBj3ixojymZF=Vi4tpQ@xxxxxxxxxxxxxx/
> > > > Suggested-by: David Gow <davidgow@xxxxxxxxxx>
> > > > Signed-off-by: Sander Vanheule <sander@xxxxxxxxxxxxx>
> > > > Reviewed-by: David Gow <davidgow@xxxxxxxxxx>
> > > > ---
> > > >  lib/cpumask_kunit.c | 10 ++++++++++
> > > >  1 file changed, 10 insertions(+)
> > > > 
> > > > diff --git a/lib/cpumask_kunit.c b/lib/cpumask_kunit.c
> > > > index 4d353614d853..0f8059a5e93b 100644
> > > > --- a/lib/cpumask_kunit.c
> > > > +++ b/lib/cpumask_kunit.c
> > > > @@ -51,6 +51,10 @@
> > > >  static cpumask_t mask_empty;
> > > >  static cpumask_t mask_all;
> > > >  
> > > > +#define STR_MASK(m)                    #m
> > > > +#define TEST_CPUMASK_PRINT(test, mask) \
> > > > +       kunit_info(test, "%s = '%*pbl'\n", STR_MASK(mask),
> > > > nr_cpumask_bits,
> > > > cpumask_bits(mask))
> > > > +
> > > >  static void test_cpumask_weight(struct kunit *test)
> > > >  {
> > > >         KUNIT_EXPECT_TRUE(test, cpumask_empty(&mask_empty));
> > > > @@ -103,6 +107,9 @@ static void test_cpumask_iterators_builtin(struct
> > > > kunit
> > > > *test)
> > > >         /* Ensure the dynamic masks are stable while running the tests
> > > > */
> > > >         cpu_hotplug_disable();
> > > >  
> > > > +       TEST_CPUMASK_PRINT(test, cpu_online_mask);
> > > > +       TEST_CPUMASK_PRINT(test, cpu_present_mask);
> > > > +
> > > >         EXPECT_FOR_EACH_CPU_BUILTIN_EQ(test, online);
> > > >         EXPECT_FOR_EACH_CPU_BUILTIN_EQ(test, present);
> > > >  
> > > > @@ -114,6 +121,9 @@ static int test_cpumask_init(struct kunit *test)
> > > >         cpumask_clear(&mask_empty);
> > > >         cpumask_setall(&mask_all);
> > > >  
> > > > +       TEST_CPUMASK_PRINT(test, &mask_all);
> > > > +       TEST_CPUMASK_PRINT(test, cpu_possible_mask);
> > > > +
> > > 
> > > It sort of breaks the rule of silence. Can you make this print conditional
> > > on a test failure? If everything is OK, who wants to look into details? 
> > 
> > I will change the macros to the _MSG versions, and log the mask there.
> > 
> > I implemented this with kunit_info() as David proposed. AFAICT I can't call 
> > kunit_info() only when the test fails, because the EXPECT_ macros don't
> > return
> > any result.
> 
> Maybe you can use KUNIT_EXPECT_EQ_MSG to print a more detailed error and
> avoid printing the info when the test doesn't fail.

Yes, this is what I currently have for use with the _MSG() variants of the
macros:

+#define MASK_MSG(m)                    \
+       "%s contains %sCPUs %*pbl", #m, (cpumask_weight(m) ? "" : "no "), nr_cpumask_bits, cpumask_bits(m)
+

For example, with (bogus) KUNIT_EXPECT_TRUE_MSG(test, ..., MASK_MSG(mask)) this
becomes (trimmed):

$ ./tools/testing/kunit/kunit.py run  --build_dir=build-um cpumask
[...]
[18:15:33] # test_cpumask_weight: EXPECTATION FAILED at lib/cpumask_kunit.c:60
[18:15:33] Expected cpumask_empty(((struct cpumask *)(1 ? (cpu_all_bits) : (void *)sizeof(__check_is_bitmap(cpu_all_bits))))) to be true, but is false
[18:15:33] 
[18:15:33] cpu_all_mask contains CPUs 0
[18:15:33] # test_cpumask_weight: EXPECTATION FAILED at lib/cpumask_kunit.c:61
[18:15:33] Expected cpumask_full(&mask_empty) to be true, but is false
[18:15:33] 
[18:15:33] &mask_empty contains no CPUs
[18:15:33] not ok 1 - test_cpumask_weight
[18:15:33] [FAILED] test_cpumask_weight
[...]

Or on a real system:
[    1.246805]     # test_cpumask_weight: EXPECTATION FAILED at lib/cpumask_kunit.c:59
[    1.246805]     Expected cpumask_empty(((struct cpumask *)(1 ? (cpu_all_bits) : (void *)sizeof(__check_is_bitmap(cpu_all_bits))))) to be true, but is false
[    1.246805] 
[    1.246805] cpu_all_mask contains CPUs 0-1
[    1.249756]     not ok 1 - test_cpumask_weight

I will send an updated series tomorrow, in case David or others have more more comments.

Best,
Sander