[Bug Report] Multiple S390x KUNIT clk failures

[Nico Pache]

Hi,

We are seeing a number of the CLK kunit tests failing on S390x. This
has been occurring for some time now (as early as v6.1). We run these
tests as modules (without the UML wrappers), and have not seen these
failures on any other architectures.

The failing tests are:

clk-gate-hiword-test
------------------------------
# clk_gate_test_hiword_enable: EXPECTATION FAILED at
drivers/clk/clk-gate_test.c:322
Expected enable_val == (__u32)__builtin_bswap32((__u32)((
__u32)(__le32)(ctx->fake_reg))), but
enable_val == 33554944 (0x2000200)
(__u32)__builtin_bswap32((__u32)((
__u32)(__le32)(ctx->fake_reg))) == 0 (0x0)
not ok 1 clk_gate_test_hiword_enable
# clk_gate_test_hiword_disable: ASSERTION FAILED at
drivers/clk/clk-gate_test.c:339
Expected enable_val == (__u32)__builtin_bswap32((__u32)((
__u32)(__le32)(ctx->fake_reg))), but
enable_val == 33554944 (0x2000200)
(__u32)__builtin_bswap32((__u32)((
__u32)(__le32)(ctx->fake_reg))) == 0 (0x0)
not ok 2 clk_gate_test_hiword_disable


clk-gate-invert-test
------------------------------
# clk_gate_test_invert_enable: EXPECTATION FAILED at
drivers/clk/clk-gate_test.c:249
Expected enable_val == (__u32)__builtin_bswap32((__u32)((
__u32)(__le32)(ctx->fake_reg))), but
enable_val == 0 (0x0)
(__u32)__builtin_bswap32((__u32)((
__u32)(__le32)(ctx->fake_reg))) == 32768 (0x8000)
# clk_gate_test_invert_enable: EXPECTATION FAILED at
drivers/clk/clk-gate_test.c:250
Expected clk_hw_is_enabled(hw) to be true, but is false
not ok 1 clk_gate_test_invert_enable
# clk_gate_test_invert_disable: ASSERTION FAILED at
drivers/clk/clk-gate_test.c:266
Expected enable_val == (__u32)__builtin_bswap32((__u32)((
__u32)(__le32)(ctx->fake_reg))), but
enable_val == 0 (0x0)
(__u32)__builtin_bswap32((__u32)((
__u32)(__le32)(ctx->fake_reg))) == 32768 (0x8000)
not ok 2 clk_gate_test_invert_disable


clk-gate-is_enabled-test
------------------------------
ok 1 clk_gate_test_is_enabled
# clk_gate_test_is_disabled: ASSERTION FAILED at
drivers/clk/clk-gate_test.c:409
Expected clk_hw_is_enabled(hw) to be false, but is true
not ok 2 clk_gate_test_is_disabled
# clk_gate_test_is_enabled_inverted: ASSERTION FAILED at
drivers/clk/clk-gate_test.c:423
Expected hw is not error, but is: -17
not ok 3 clk_gate_test_is_enabled_inverted
# clk_gate_test_is_disabled_inverted: ASSERTION FAILED at
drivers/clk/clk-gate_test.c:438
Expected hw is not error, but is: -17
not ok 4 clk_gate_test_is_disabled_inverted


clk-gate-test
------------------------------
ok 1 clk_gate_test_parent_rate
# clk_gate_test_enable: EXPECTATION FAILED at
drivers/clk/clk-gate_test.c:169
Expected enable_val == (__u32)__builtin_bswap32((__u32)((
__u32)(__le32)(ctx->fake_reg))), but
enable_val == 32 (0x20)
(__u32)__builtin_bswap32((__u32)((
__u32)(__le32)(ctx->fake_reg))) == 0 (0x0)
not ok 2 clk_gate_test_enable
# clk_gate_test_disable: ASSERTION FAILED at drivers/clk/clk-gate_test.c:186
Expected enable_val == (__u32)__builtin_bswap32((__u32)((
__u32)(__le32)(ctx->fake_reg))), but
enable_val == 32 (0x20)
(__u32)__builtin_bswap32((__u32)((
__u32)(__le32)(ctx->fake_reg))) == 0 (0x0)
not ok 3 clk_gate_test_disable

[Stephen Boyd]

Quoting Nico Pache (2024-05-13 18:08:40)

> Hi,
>
> We are seeing a number of the CLK kunit tests failing on S390x. This
> has been occurring for some time now (as early as v6.1). We run these
> tests as modules (without the UML wrappers), and have not seen these
> failures on any other architectures.

Do you have commit 75357829cc8e ("clk: Fix clk gate kunit test on
big-endian CPUs"). What is the kernel version?

[Nico Pache]

Hi Stephen,

Yes, we have that commit. This is failing on fedora-ark, so it's
constantly updated to match upstream, and the earliest recorded
instance of it failing in our environment is v6.1.

Cheers,
-- Nico

[Stephen Boyd]

Quoting Nico Pache (2024-05-14 00:14:24)

> Hi Stephen,
>
> Yes, we have that commit. This is failing on fedora-ark, so it's
> constantly updated to match upstream, and the earliest recorded
> instance of it failing in our environment is v6.1.
>

Please don't top post. I'm unable to run s390 kunit tests in qemu. They
seem to crash before finishing.

./tools/testing/kunit/kunit.py run --kunitconfig=lib/kunit --arch=s390 --cross_compile=/path/to/s390-linux-

[14:55:10] Starting KUnit Kernel (1/1)...
[14:55:10] ============================================================
Running tests with:
$ qemu-system-s390x -nodefaults -m 1024 -kernel .kunit/arch/s390/boot/bzImage -append 'kunit.enable=1 console=ttyS0 kunit_shutdown=reboot' -no-reboot -nographic -serial stdio -machine s390-ccw-virtio -cpu qemu
[14:55:11] ============================= =============================
[14:55:11] ================= example_init (1 subtest) =================
[14:55:11] [PASSED] example_init_test
[14:55:11] ================== [PASSED] example_init ===================
[14:55:11] ============================= =============================
[14:55:11] ============= kunit_executor_test (8 subtests) =============
[14:55:11] [PASSED] parse_filter_test
[14:55:11] [PASSED] filter_suites_test
[14:55:11] [PASSED] filter_suites_test_glob_test
[14:55:11] [PASSED] filter_suites_to_empty_test
[14:55:11] [PASSED] parse_filter_attr_test
[14:55:11] [PASSED] filter_attr_test
[14:55:11] [PASSED] filter_attr_empty_test
[14:55:11] [PASSED] filter_attr_skip_test
[14:55:11] [ERROR] Test: kunit_executor_test: Expected test number 1 but found 2
[14:55:11] =============== [PASSED] kunit_executor_test ===============
[14:55:11] ============================= =============================
[14:55:11] ============ kunit-try-catch-test (2 subtests) =============
[14:55:11] [PASSED] kunit_test_try_catch_successful_try_no_catch
[14:55:11] [PASSED] kunit_test_try_catch_unsuccessful_try_does_catch
[14:55:11] [ERROR] Test: kunit-try-catch-test: Expected test number 1 but found 3
[14:55:11] ============== [PASSED] kunit-try-catch-test ===============
[14:55:11] ============================= =============================
[14:55:11] ============ kunit-resource-test (12 subtests) =============
[14:55:11] [PASSED] kunit_resource_test_init_resources
[14:55:11] [PASSED] kunit_resource_test_alloc_resource
[14:55:11] [PASSED] kunit_resource_test_destroy_resource
[14:55:11] [PASSED] kunit_resource_test_remove_resource
[14:55:11] [PASSED] kunit_resource_test_cleanup_resources
[14:55:11] [PASSED] kunit_resource_test_proper_free_ordering
[14:55:11] [PASSED] kunit_resource_test_static
[14:55:11] [PASSED] kunit_resource_test_named
[14:55:11] [PASSED] kunit_resource_test_action
[14:55:11] [PASSED] kunit_resource_test_remove_action
[14:55:11] [PASSED] kunit_resource_test_release_action
[14:55:11] [PASSED] kunit_resource_test_action_ordering
[14:55:11] [ERROR] Test: kunit-resource-test: Expected test number 1 but found 4
[14:55:11] =============== [PASSED] kunit-resource-test ===============
[14:55:11] ============================= =============================
[14:55:11] =============== kunit-log-test (2 subtests) ================
[14:55:11] [PASSED] kunit_log_test
[14:55:11] [SKIPPED] kunit_log_newline_test
[14:55:11] [ERROR] Test: kunit-log-test: Expected test number 1 but found 5
[14:55:11] ================= [PASSED] kunit-log-test ==================
[14:55:11] ============================= =============================
[14:55:11] ================ kunit_status (2 subtests) =================
[14:55:11] [PASSED] kunit_status_set_failure_test
[14:55:11] [PASSED] kunit_status_mark_skipped_test
[14:55:11] [ERROR] Test: kunit_status: Expected test number 1 but found 6
[14:55:11] ================== [PASSED] kunit_status ===================
[14:55:11] ============================= =============================
[14:55:11] ================ kunit_current (2 subtests) ================
[14:55:11] [PASSED] kunit_current_test
[14:55:11] [PASSED] kunit_current_fail_test
[14:55:11] [ERROR] Test: kunit_current: Expected test number 1 but found 7
[14:55:11] ================== [PASSED] kunit_current ==================
[14:55:11] ============================= =============================
[14:55:11] ================ kunit_device (3 subtests) =================
[14:55:11] [PASSED] kunit_device_test
[14:55:11] [PASSED] kunit_device_cleanup_test
[14:55:11] [PASSED] kunit_device_driver_test
[14:55:11] [ERROR] Test: kunit_device: Expected test number 1 but found 8
[14:55:11] ================== [PASSED] kunit_device ===================
[14:55:11] ============================= =============================
[14:55:11] ============= string-stream-test (12 subtests) =============
[14:55:11] [PASSED] string_stream_managed_init_test
[14:55:11] [PASSED] string_stream_unmanaged_init_test
[14:55:11] [PASSED] string_stream_managed_free_test
[14:55:11] [PASSED] string_stream_resource_free_test
[14:55:11] [PASSED] string_stream_line_add_test
[14:55:11] [PASSED] string_stream_variable_length_line_test
[14:55:11] [PASSED] string_stream_append_test
[14:55:11] [PASSED] string_stream_append_auto_newline_test
[14:55:11] [PASSED] string_stream_append_empty_string_test
[14:55:11] [PASSED] string_stream_no_auto_newline_test
[14:55:11] [PASSED] string_stream_auto_newline_test
[14:55:11] [PASSED] string_stream_performance_test
[14:55:11] [ERROR] Test: string-stream-test: Expected test number 1 but found 9
[14:55:11] =============== [PASSED] string-stream-test ================
[14:55:11] ============================= =============================
[14:55:11] =================== example (9 subtests) ===================
[14:55:11] [PASSED] example_simple_test
[14:55:11] [SKIPPED] example_skip_test
[14:55:11] [ERROR] Test: example: missing expected subtest!
[14:55:11]
[14:55:11] # example_mark_skipped_test: initializing
[14:55:11]
[14:55:11] # example_mark_skipped_test: You should see a line below.
[14:55:11] [CRASHED]
[14:55:11] [ERROR] Test: example: missing expected subtest!
[14:55:11] [CRASHED]
[14:55:11] [ERROR] Test: example: missing expected subtest!
[14:55:11] [CRASHED]
[14:55:11] [ERROR] Test: example: missing expected subtest!
[14:55:11] [CRASHED]
[14:55:11] [ERROR] Test: example: missing expected subtest!
[14:55:11] [CRASHED]
[14:55:11] [ERROR] Test: example: missing expected subtest!
[14:55:11] [CRASHED]
[14:55:11] [ERROR] Test: example: missing expected subtest!
[14:55:11] [CRASHED]
[14:55:11] [ERROR] Test: example: missing subtest result line!
[14:55:11]
[14:55:11] # module: kunit_example_test
[14:55:11] ==================== [CRASHED] example =====================
[14:55:11]
[14:55:11] # example: initializing suite
[14:55:11]
[14:55:11] ======================== [CRASHED] ========================
[14:55:11]
[14:55:11] ======================== [CRASHED] ========================
[14:55:11]
[14:55:11] ======================== [CRASHED] ========================
[14:55:11]
[14:55:11] ======================== [CRASHED] ========================
[14:55:11]
[14:55:11] ======================== [CRASHED] ========================
[14:55:11]
[14:55:11] ======================== [CRASHED] ========================
[14:55:11]
[14:55:11] ======================== [CRASHED] ========================
[14:55:11]
[14:55:11] ======================== [CRASHED] ========================
[14:55:11]
[14:55:11] ======================== [CRASHED] ========================
[14:55:11]
[14:55:11] ======================== [CRASHED] ========================
[14:55:11] [ERROR] Test: main: missing expected subtest!
[14:55:11] [CRASHED]
[14:55:11] [ERROR] Test: main: missing expected subtest!
[14:55:11] [CRASHED]
[14:55:11] [ERROR] Test: main: missing expected subtest!
[14:55:11] [CRASHED]
[14:55:11] [ERROR] Test: main: missing expected subtest!
[14:55:11] [CRASHED]
[14:55:11] [ERROR] Test: main: missing expected subtest!
[14:55:11] [CRASHED]
[14:55:11] [ERROR] Test: main: missing expected subtest!
[14:55:11] [CRASHED]
[14:55:11] [ERROR] Test: main: missing expected subtest!
[14:55:11] [CRASHED]
[14:55:11] [ERROR] Test: main: missing expected subtest!
[14:55:11] [CRASHED]
[14:55:11] [ERROR] Test: main: missing expected subtest!
[14:55:11] [CRASHED]
[14:55:11] ============================================================
[14:55:11] Testing complete. Ran 62 tests: passed: 44, crashed: 16, skipped: 2, errors: 25
The kernel seems to have crashed; you can decode the stack traces with:
$ scripts/decode_stacktrace.sh .kunit/vmlinux .kunit < .kunit/test.log | tee .kunit/decoded.log | ./tools/testing/kunit/kunit.py parse
[14:55:11] Elapsed time: 16.240s total, 1.476s configuring, 14.294s building, 0.469s running

I wonder if something with my local environment is causing troubles.

[Donald Zickus]

Hi Stephen,

On Tue, May 14, 2024 at 6:04 PM Stephen Boyd <sb...@kernel.org> wrote:

Quoting Nico Pache (2024-05-14 00:14:24)
> Hi Stephen,
>
> Yes, we have that commit. This is failing on fedora-ark, so it's
> constantly updated to match upstream, and the earliest recorded
> instance of it failing in our environment is v6.1.
>

Please don't top post. I'm unable to run s390 kunit tests in qemu. They
seem to crash before finishing.

I am working with Nico on moving this forward.  What can we do to help resolve this?

Cheers,

Don

[Donald Zickus]

(trying again without the html part that gmail likes to add. Apologies)

[Audra Mitchell]

On Tue, May 28, 2024 at 02:49:56PM -0400, Donald Zickus wrote:
> (trying again without the html part that gmail likes to add. Apologies)
>
> On Tue, May 28, 2024 at 2:45 PM Donald Zickus <dzi...@redhat.com> wrote:
> >
> > Hi Stephen,
> >
> > On Tue, May 14, 2024 at 6:04 PM Stephen Boyd <sb...@kernel.org> wrote:
> >>
> >> Quoting Nico Pache (2024-05-14 00:14:24)
> >> > Hi Stephen,
> >> >
> >> > Yes, we have that commit. This is failing on fedora-ark, so it's
> >> > constantly updated to match upstream, and the earliest recorded
> >> > instance of it failing in our environment is v6.1.
> >> >
> >>
> >> Please don't top post. I'm unable to run s390 kunit tests in qemu. They
> >> seem to crash before finishing.
> >
> >
> > I am working with Nico on moving this forward. What can we do to help resolve this?

Hello all,

I spent some time last week or so working on debugging these failures and I
believe I have found the problem. I reached out to Malk Salter for advice on
the best way to move forward with a fix on Friday the 17th, but he was on
PTO for the last week. I was waiting for his reply before I replied to this
thread.

Also as a side note, I also ran into the same issue as Stephen with running
the kunit tests on s390 QEMU. I did not pursue resolving that issue and
instead just compiled the test as a module.

For clarity, this is what I sent to Mark and were I believe the failure is
occurring:

The tests create a pretend clk-gate and use a "fake_reg" to emulate
the expected behavior of the clk_gate->reg. I added some debug
statements to the driver and noticed that the reg changes after
initialization to -1. I also noticed that we call this to read the
data in the clk-gate->reg:

static inline u32 clk_gate_readl(struct clk_gate *gate)
{
if (gate->flags & CLK_GATE_BIG_ENDIAN)
return ioread32be(gate->reg);

return readl(gate->reg);
}

However, it does not look like ioread32be is defined for s390, so
instead the compiler uses read1 (which becomes zpci_load). I checked
this by dumping the assembler of the compiled kunit clk-gate_test:

/root/linux/drivers/clk/clk-gate.c: 29
0x13214c9c6 <clk_gate_is_enabled+38>: tm 33(%r2),4
0x13214c9ca <clk_gate_is_enabled+42>: jne 0x13214ca82
<clk_gate_is_enabled+226>
/root/linux/./arch/s390/include/asm/pci_io.h: 64
0x13214c9ce <clk_gate_is_enabled+46>: lghi %r4,4
0x13214c9d2 <clk_gate_is_enabled+50>: la %r2,160(%r15)
0x13214c9d6 <clk_gate_is_enabled+54>: brasl %r14,0x131bbc3f0 <zpci_load>
0x13214c9dc <clk_gate_is_enabled+60>: cije %r2,0,0x13214ca78
<clk_gate_is_enabled+216>

Following up on this, I noticed that if the zpci_load is not
successful, we will return a -1:

static inline RETTYPE zpci_read_##RETTYPE(const volatile void __iomem
*addr) \
{
\
u64 data;
\
int rc;
\

\
rc = zpci_load(&data, addr, LENGTH);
\
if (rc)
\
data = -1ULL;
\
return (RETTYPE) data;
\
}


All this to say, I'm not sure the best way to resolve this problem. We
need to patch clk_gate_readl() but I am not sure the best way to go
about doing this for big_endian systems.

Any recommedations on the best way to resolve this problem is welcomed!

Thanks in advance!

-- Audra Mitchell

[msa...@redhat.com]

It is defined. arch/s390/include/asm/io.h defines:

#define __raw_readl zpci_read_u32

and then includes include/asm-generic/io.h which has:

static inline u32 readl(const volatile void __iomem *addr)
{
u32 val;

log_read_mmio(32, addr, _THIS_IP_, _RET_IP_);
__io_br();
val = __le32_to_cpu((__le32 __force)__raw_readl(addr));
__io_ar(val);
log_post_read_mmio(val, 32, addr, _THIS_IP_, _RET_IP_);
return val;
}
...
static inline u32 ioread32be(const volatile void __iomem *addr)
{
return swab32(readl(addr));
}

which should do the right thing (s390 being BE and readl() is for 32-bit LE reads).

But I don't know the s390 compiler or ISA, so I'm not sure where the zpci_load
is coming from.

[Stephen Boyd]

Quoting msa...@redhat.com (2024-05-28 15:53:48)

So the problem is that the zpci_read_u32() fails and returns -1?

This test isn't the best because it uses fakes iomem and architectures
may not like that. We really need to implement something in KUnit core
to allocate a fake iomem region and then plumb that through all the
architectures so that the iomem functions like readl, writel, etc. go a
different direction when the pointer is for the fake region.

Probably the best thing to do in the short term here is to prevent this
test from running on S390 via Kconfig.

[Audra Mitchell]

Hey Stephen, thanks a bunch for looking at this. I do not have a lot of
experience with s390 to vote one way or another for how best to approach
resolving this problem.

By the way zpci_load is coming from here:

readl calls __raw_readl
s390 defines raw_readl as zpci_read_u32:

#define __raw_readl zpci_read_u32

And zpci_read is defined here, which then calls zpci_load:

#define zpci_read(LENGTH, RETTYPE) \

static inline RETTYPE zpci_read_##RETTYPE(const volatile void __iomem *addr) \
{ \
u64 data; \
int rc; \
\
rc = zpci_load(&data, addr, LENGTH); \
if (rc) \
data = -1ULL; \
return (RETTYPE) data; \
}

Thanks again!