Message-Id: <20220718145150.3344778-1-mathieu.desnoyers@efficios.com>
Date:   Mon, 18 Jul 2022 10:51:50 -0400
From:   Mathieu Desnoyers <mathieu.desnoyers@...icios.com>
To:     James Morse <james.morse@....com>
Cc:     linux-kernel@...r.kernel.org,
        Mathieu Desnoyers <mathieu.desnoyers@...icios.com>,
        Catalin Marinas <catalin.marinas@....com>,
        Russell King <linux@...linux.org.uk>,
        "Mark Rutland" <mark.rutland@....com>,
        Will Deacon <will@...nel.org>,
        "Shawn Guo" <shawnguo@...nel.org>,
        "Sascha Hauer" <s.hauer@...gutronix.de>,
        Michael Jeanson <mjeanson@...icios.com>,
        linux-arm-kernel@...ts.infradead.org
Subject: [RFC PATCH] arm: i.MX6 Cortex-A9: Fix memory ordering inconsistency by disabling prefetch instructions

Observed issue
==============

On a Wandboard i.MX6 Quad Board revD1 (Cortex-A9 r2p10), spurious hangs
have been experienced in sys_futex in a few scenarios with liburcu
rwlock stress-tests [1]. The test run in a loop is:

for a in $(seq 1 100000); do echo $a; tests/benchmark/.libs/test_rwlock 2 2 1 || exit 1; done

This runs a 1 second test with 2 reader and 2 writer threads.

The hangs show up in the following scenarios:

- glibc nptl rwlock,
- glibc nptl pthread_join.

Another simpler test-case that reproduces the pthread join hang is as follows:

/*
 * Build with:
 *   gcc -O2 -pthread -o test-pthread-join test-pthread-join.c
 * Run in a loop:
 *   for a in $(seq 500000); do echo $a; ./test-pthread-join || exit 1; done
 */

void *testmemthread(void *arg)
{
        printf("thread id : %lu, pid %lu\n", pthread_self(), getpid());
        return ((void*)0);
}

int main()
{
        int err, i;
        pthread_t testmemid[NR_THREADS];
        void *tret;

        for (i = 0; i < NR_THREADS; i++) {
                err = pthread_create(&testmemid[i], NULL, testmemthread,
                        (void *)(long)i);
                if (err != 0)
                        exit(1);
        }
        for (i = 0; i < NR_THREADS; i++) {
                err = pthread_join(testmemid[i], &tret);
                if (err != 0)
                        exit(1);
        }
        return 0;
}

In all cases a FUTEX_WAIT is stuck waiting for a state change that can
be validated to be present in user memory by inspecting the hung process
with a debugger.

This can be reproduced with a Debian bullseye config-5.18.0-0.bpo.1-armmp
configuration. The config-5.18.0-0.bpo.1-armmp configuration applied to
a vanilla 5.18.2 kernel tree reproduces this issue when compiled with
gcc version 10.2.1 20210110 (Debian 10.2.1-6). The U-Boot version is
2021.01+dfsg-4.

Note that this either does not appear to reproduce or takes longer to
reproduce as soon as the configuration varies significantly enough to
change the kernel code generated for futex wait.

- It takes longer to hit the hang when running on a 5.18.2 kernel
  compiled with gcc version 7.5.0 (Ubuntu/Linaro 7.5.0-3ubuntu1~18.04).

- The issue is not reproduced with a kernel built from a
  imx_v6_v7_defconfig configuration with gcc 10.2.1.
  One important effect of this configuration change is that it targets
  __LINUX_ARM_ARCH__ = 6 rather than __LINUX_ARM_ARCH__ = 7.

Root Cause Analysis
===================

Instrumentation of the futex system call FUTEX_WAKE and FUTEX_WAIT code
with tracepoints, and tracing with LTTng [2] in "snapshot" flight
recorder mode allows a better understanding of what is going on when the
hang reproduces.

First, a bit of context about sys_futex: it relies on a Dekker [3]
two-variables memory barrier scenario:

 * CPU 0                                 CPU 1
 * val = *futex;
 * sys_futex(WAIT, futex, val);
 *   futex_wait(futex, val);
 *
 *   waiters++; (a)
 *   smp_mb(); (A) <-- paired with -.
 *                                  |
 *   lock(hash_bucket(futex));      |
 *                                  |
 *   uval = *futex;                 |
 *                                  |        *futex = newval;
 *                                  |        sys_futex(WAKE, futex);
 *                                  |          futex_wake(futex);
 *                                  |
 *                                  `--------> smp_mb(); (B)
 *   if (uval == val)
 *     queue();
 *     unlock(hash_bucket(futex));
 *     schedule();                         if (waiters)
 *                                           lock(hash_bucket(futex));
 *   else                                    wake_waiters(futex);
 *     waiters--; (b)                        unlock(hash_bucket(futex));
 *
 * Where (A) orders the waiters increment and the futex value read through
 * atomic operations (see futex_hb_waiters_inc) and where (B) orders the write
 * to futex and the waiters read (see futex_hb_waiters_pending()).
 *
 * This yields the following case (where X:=waiters, Y:=futex):
 *
 *      X = Y = 0
 *
 *      w[X]=1          w[Y]=1
 *      MB              MB
 *      r[Y]=y          r[X]=x
 *
 * Which guarantees that x==0 && y==0 is impossible; which translates back into
 * the guarantee that we cannot both miss the futex variable change and the
 * enqueue.

When reproducing the hang, we observe the following in the userspace
stacks and in the execution trace:

  (gdb) thread apply all bt

  Thread 5 (Thread 0xb5693450 (LWP 2404) "test_rwlock"):
  #0  __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
  #1  0xb6fa105c in futex_abstimed_wait (private=0, abstime=0x0, clockid=0, expected=3, futex_word=<optimized out>) at ../sysdeps/nptl/futex-internal.h:287
  #2  __pthread_rwlock_wrlock_full (abstime=0x0, clockid=0, rwlock=0x4420d8 <lock>) at pthread_rwlock_common.c:731
  #3  __GI___pthread_rwlock_wrlock (rwlock=rwlock@...ry=0x4420d8 <lock>) at pthread_rwlock_wrlock.c:27
  #4  0x00430fe0 in thr_writer (_count=0x96e1d0) at test_rwlock.c:205
  #5  0xb6f9c98e in start_thread (arg=0x4d5aa9ac) at pthread_create.c:477
  #6  0xb6f37bec in ?? () at ../sysdeps/unix/sysv/linux/arm/clone.S:73 from /lib/arm-linux-gnueabihf/libc.so.6
  Backtrace stopped: previous frame identical to this frame (corrupt stack?)

  Thread 4 (Thread 0xb5e94450 (LWP 2403) "test_rwlock"):
  #0  __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
  #1  0xb6fa0ea4 in futex_abstimed_wait (private=0, abstime=0x0, clockid=0, expected=2, futex_word=<optimized out>) at ../sysdeps/nptl/futex-internal.h:287
  #2  __pthread_rwlock_wrlock_full (abstime=0x0, clockid=0, rwlock=0x4420d8 <lock>) at pthread_rwlock_common.c:830
  #3  __GI___pthread_rwlock_wrlock (rwlock=rwlock@...ry=0x4420d8 <lock>) at pthread_rwlock_wrlock.c:27
  #4  0x00430fe0 in thr_writer (_count=0x96e1c8) at test_rwlock.c:205
  #5  0xb6f9c98e in start_thread (arg=0x4d5aa9ac) at pthread_create.c:477
  #6  0xb6f37bec in ?? () at ../sysdeps/unix/sysv/linux/arm/clone.S:73 from /lib/arm-linux-gnueabihf/libc.so.6
  Backtrace stopped: previous frame identical to this frame (corrupt stack?)

  Thread 3 (Thread 0xb6695450 (LWP 2402) "test_rwlock"):
  #0  __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
  #1  0xb6fa07be in futex_abstimed_wait (private=<optimized out>, abstime=0x0, clockid=0, expected=3, futex_word=<optimized out>) at ../sysdeps/nptl/futex-internal.h:287
  #2  __pthread_rwlock_rdlock_full (abstime=0x0, clockid=0, rwlock=0x4420d8 <lock>) at pthread_rwlock_common.c:460
  #3  __GI___pthread_rwlock_rdlock (rwlock=rwlock@...ry=0x4420d8 <lock>) at pthread_rwlock_rdlock.c:27
  #4  0x004311ba in thr_reader (_count=0x96e1b8) at test_rwlock.c:157
  #5  0xb6f9c98e in start_thread (arg=0x4d5aa9ac) at pthread_create.c:477
  #6  0xb6f37bec in ?? () at ../sysdeps/unix/sysv/linux/arm/clone.S:73 from /lib/arm-linux-gnueabihf/libc.so.6
  Backtrace stopped: previous frame identical to this frame (corrupt stack?)

  Thread 2 (Thread 0xb6e96450 (LWP 2401) "test_rwlock"):
  #0  __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
  #1  0xb6fa07be in futex_abstimed_wait (private=<optimized out>, abstime=0x0, clockid=0, expected=3, futex_word=<optimized out>) at ../sysdeps/nptl/futex-internal.h:287
  #2  __pthread_rwlock_rdlock_full (abstime=0x0, clockid=0, rwlock=0x4420d8 <lock>) at pthread_rwlock_common.c:460
  #3  __GI___pthread_rwlock_rdlock (rwlock=rwlock@...ry=0x4420d8 <lock>) at pthread_rwlock_rdlock.c:27
  #4  0x004311ba in thr_reader (_count=0x96e1b0) at test_rwlock.c:157
  #5  0xb6f9c98e in start_thread (arg=0x4d5aa9ac) at pthread_create.c:477
  #6  0xb6f37bec in ?? () at ../sysdeps/unix/sysv/linux/arm/clone.S:73 from /lib/arm-linux-gnueabihf/libc.so.6
  Backtrace stopped: previous frame identical to this frame (corrupt stack?)

  Thread 1 (Thread 0xb6fe3d60 (LWP 2400) "test_rwlock"):
  #0  __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
  #1  0xb6f9dafc in __pthread_clockjoin_ex (threadid=3068748880, thread_return=thread_return@...ry=0xbeb80a8c, clockid=clockid@...ry=0, abstime=abstime@...ry=0x0, block=block@...ry=true) at pthread_join_common.c:145
  #2  0xb6f9d8ec in __pthread_join (threadid=<optimized out>, thread_return=thread_return@...ry=0xbeb80a8c) at pthread_join.c:24
  #3  0x00430b20 in main (argc=<optimized out>, argv=0xbeb80c14) at test_rwlock.c:367

  (gdb) print *rwlock
  $1 = {__data = {__readers = 19, __writers = 0, __wrphase_futex = 3, __writers_futex = 3, __pad3 = 0, __pad4 = 0, __flags = 0 '\000',
      __shared = 0 '\000', __pad1 = 0 '\000', __pad2 = 0 '\000', __cur_writer = 0},
    __size = "\023\000\000\000\000\000\000\000\003\000\000\000\003", '\000' <repeats 18 times>, __align = 19}

Thread 4 (tid=2403) should either have been awakened when the
__wrphase_futex state changed from 2 to 3, or should have observed a
__wrphase_futex==3 and thus never have blocked.

Here is the relevant instrumentation. Note that the instrumentation
added aims at minimizing the impact on the fast-path timings to make
sure the issue can be reproduced under tracing. Indeed, adding too much
instrumentation either hides the problem or makes it take much longer to
reproduce.

futex_wait_end:              At each location where the function futex_wait_setup() returns.
futex_wait_get_value_locked: Conditional if uval != val so the timing of the fast-path is not changed too much.
futex_wait_get_user:         After futex_wait_setup issues get_user() (slow path for page faults).
futex_wake_end:              At each location where the function futex_wake() returns.

Let's look at the relevant portion of the trace just before the hang:

[...]
        [16:27:34.437683527] (+0.000004666) futex_wait_end: { cpu_id = 2 }, { tid = 2403, pid = 2400 }, { uaddr = 0x4420E0, val = 2, ret = 0, msg = "" }
        [16:27:34.437700528] (+0.000017001) futex_wait_end: { cpu_id = 0 }, { tid = 2402, pid = 2400 }, { uaddr = 0x4420E0, val = 3, ret = 0, msg = "" }
        [16:27:34.437703195] (+0.000002667) futex_wake_end: { cpu_id = 1 }, { tid = 2401, pid = 2400 }, { uaddr = 0x4420E0, ret = 1, msg = "" }
        [16:27:34.437704862] (+0.000001667) futex_wait_end: { cpu_id = 3 }, { tid = 2404, pid = 2400 }, { uaddr = 0x4420E4, val = 3, ret = 0, msg = "" }
        [16:27:34.437708195] (+0.000003333) futex_wait_end: { cpu_id = 1 }, { tid = 2401, pid = 2400 }, { uaddr = 0x4420E0, val = 3, ret = 0, msg = "" }
        [16:27:34.437735863] (+0.000027668) futex_wake_end: { cpu_id = 2 }, { tid = 2403, pid = 2400 }, { uaddr = 0x4420E0, ret = 2, msg = "" }
        [16:27:34.437741863] (+0.000006000) futex_wake_end: { cpu_id = 2 }, { tid = 2403, pid = 2400 }, { uaddr = 0x4420E4, ret = 1, msg = "" }
        [16:27:34.437745863] (+0.000004000) futex_wait_end: { cpu_id = 2 }, { tid = 2403, pid = 2400 }, { uaddr = 0x4420E0, val = 2, ret = 0, msg = "" }
        [16:27:34.437762531] (+0.000016668) futex_wait_end: { cpu_id = 1 }, { tid = 2401, pid = 2400 }, { uaddr = 0x4420E0, val = 3, ret = 0, msg = "" }
        [16:27:34.437765531] (+0.000003000) futex_wake_end: { cpu_id = 0 }, { tid = 2402, pid = 2400 }, { uaddr = 0x4420E0, ret = 1, msg = "" }
        [16:27:34.437767864] (+0.000002333) futex_wait_end: { cpu_id = 3 }, { tid = 2404, pid = 2400 }, { uaddr = 0x4420E4, val = 3, ret = 0, msg = "" }
        [16:27:34.437770198] (+0.000002334) futex_wait_end: { cpu_id = 0 }, { tid = 2402, pid = 2400 }, { uaddr = 0x4420E0, val = 3, ret = 0, msg = "" }
        [16:27:34.437797865] (+0.000027667) futex_wake_end: { cpu_id = 2 }, { tid = 2403, pid = 2400 }, { uaddr = 0x4420E0, ret = 2, msg = "" }
        [16:27:34.437803866] (+0.000006001) futex_wake_end: { cpu_id = 2 }, { tid = 2403, pid = 2400 }, { uaddr = 0x4420E4, ret = 1, msg = "" }
        [16:27:34.437807866] (+0.000004000) futex_wait_end: { cpu_id = 2 }, { tid = 2403, pid = 2400 }, { uaddr = 0x4420E0, val = 2, ret = 0, msg = "" }
        [16:27:34.437824866] (+0.000017000) futex_wait_end: { cpu_id = 0 }, { tid = 2402, pid = 2400 }, { uaddr = 0x4420E0, val = 3, ret = 0, msg = "" }
        [16:27:34.437826866] (+0.000002000) futex_wake_end: { cpu_id = 1 }, { tid = 2401, pid = 2400 }, { uaddr = 0x4420E0, ret = 1, msg = "" }
        [16:27:34.437830200] (+0.000003334) futex_wait_end: { cpu_id = 3 }, { tid = 2404, pid = 2400 }, { uaddr = 0x4420E4, val = 3, ret = 0, msg = "" }
        [16:27:34.437831533] (+0.000001333) futex_wait_end: { cpu_id = 1 }, { tid = 2401, pid = 2400 }, { uaddr = 0x4420E0, val = 3, ret = 0, msg = "" }
        [16:27:34.437852868] (+0.000021335) futex_wake_end: { cpu_id = 2 }, { tid = 2403, pid = 2400 }, { uaddr = 0x4420E0, ret = 2, msg = "" }
        [16:27:34.437858534] (+0.000005666) futex_wake_end: { cpu_id = 2 }, { tid = 2403, pid = 2400 }, { uaddr = 0x4420E4, ret = 1, msg = "" }
(b)     [16:27:34.437862868] (+0.000004334) futex_wait_end: { cpu_id = 2 }, { tid = 2403, pid = 2400 }, { uaddr = 0x4420E0, val = 2, ret = 0, msg = "" }
(a)     [16:27:34.437879202] (+0.000016334) futex_wake_end: { cpu_id = 0 }, { tid = 2402, pid = 2400 }, { uaddr = 0x4420E0, ret = 0, msg = "!futex_hb_waiters_pending" }
        [16:27:34.437879535] (+0.000000333) futex_wait_end: { cpu_id = 1 }, { tid = 2401, pid = 2400 }, { uaddr = 0x4420E0, val = 3, ret = 0, msg = "" }
        [16:27:34.437884535] (+0.000005000) futex_wait_end: { cpu_id = 0 }, { tid = 2402, pid = 2400 }, { uaddr = 0x4420E0, val = 3, ret = 0, msg = "" }
        [16:27:34.437884535] (+0.000000000) futex_wait_end: { cpu_id = 3 }, { tid = 2404, pid = 2400 }, { uaddr = 0x4420E4, val = 3, ret = 0, msg = "" }
        [16:27:35.241824878] (+0.803940343) futex_wait_end: { cpu_id = 2 }, { tid = 2400, pid = 2400 }, { uaddr = 0xB6E964B8, val = 2401, ret = 0, msg = "" }

At (a), tid=2402 observes waiters_pending==0, and therefore skips
awakening any other threads on futex uaddr=0x4420E0.

However, at (b), tid=2403 returns from futex_wait_setup() on futex
uaddr=0x4420E0 with ret=0, which will cause it to block. It was called
with a val=2 as input argument. Considering that no
futex_wait_get_value_locked is traced, this means the observed uval
loaded by futex_get_value_locked() matches the expected val (==2).

Considering that tid=2402 observes waiters_pending==0, we have the
following ordering:

Waker                  Waiter
tid=2402               tid=2403
-------------------------------
*futex=3
dmb
                       load *futex
                       sys_futex
load waiters_pending
  (observe 0)
                         atomic_inc waiters_pending
                         dmb
                         load *futex
                           (observe 2, impossible!)

The fact that the waiter thread observes the futex=2 when the waker
observed waiters_pending=0 is a contradiction of the Dekker 2-variables
memory barrier scenario.

Looking more specifically at the operations involved in the loads and
stores of the futex and waiters_pending variables, we notice two things:

1) atomic_inc has a prefetchw() (PLDW) instruction, which is compiled
   out for __LINUX_ARM_ARCH__ = 6, which could explain why imx_v6_v7_defconfig
   does not reproduce the hang.

2) the waiter thread has a pattern of load *futex; dmb; load *futex,
   which are two loads of the same variable. I have attempted to modify
   the get_user used for the second load to replace LDR by LDREX in
   case some variation of errata 761319 would be at play here, but
   the hang persists.

Solution
========

The hang does not reproduce with the code that implements the arm
prefetchw() static inline function commented out.

Note that it is not the same as commenting out the entire arch-specific
prefetchw implementation (leaving ARCH_HAS_PREFETCHW undefined), which
then relies on the __builtin_prefetch() builtin.

Known Drawbacks
===============

Removing prefetch instructions can affect the performance of some
microbenchmarks, especially for streaming use-cases.

Unfortunately, the Cortex-A9 does not appear to have a documented
Coprocessor Access Control Register bit for disabling the PLD and PLDW
instructions, which prevents fixing it at boot-time from U-Boot.
Removing the prefetch instruction from the kernel code does not fix
similar issues that may arise in user-space.

Request for Feedback
====================

This fix targets all i.MX configurations, but it is likely too broad (or
too narrow). It would be great if people with access to different
Freescale i.MX test boards, and test boards from other vendors, could try
to reproduce the issue to figure out what would be the right scope for
this fix.

It would also be great if people with knowledge of the ARM CPU internals
could help understanding whether this fix really fixes an issue between
prefetch and memory barriers, or just happens to hide the issue. It
would be good to understand whether this issue only affects PLDW or if
it also affects the PLD instruction.

Link: https://liburcu.org [1]
Link: https://lttng.org [2]
Link: https://lwn.net/Articles/573436/ [3]
Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@...icios.com>
Cc: James Morse <james.morse@....com>
Cc: Catalin Marinas <catalin.marinas@....com>
Cc: Russell King <linux@...linux.org.uk>
Cc: "Mark Rutland" <mark.rutland@....com>
Cc: Will Deacon <will@...nel.org>
Cc: "Shawn Guo" <shawnguo@...nel.org>
Cc: "Sascha Hauer" <s.hauer@...gutronix.de>
Cc: Michael Jeanson <mjeanson@...icios.com>
Cc: linux-arm-kernel@...ts.infradead.org
---
 arch/arm/Kconfig                 | 3 +++
 arch/arm/include/asm/processor.h | 2 ++
 arch/arm/mach-imx/Kconfig        | 1 +
 3 files changed, 6 insertions(+)

diff --git a/arch/arm/Kconfig b/arch/arm/Kconfig
index 2e8091e2d8a8..ffcc0363e171 100644
--- a/arch/arm/Kconfig
+++ b/arch/arm/Kconfig
@@ -239,6 +239,9 @@ config GENERIC_ISA_DMA
 config FIQ
 	bool
 
+config ARM_DISABLE_PREFETCHW
+	bool
+
 config ARCH_MTD_XIP
 	bool
 
diff --git a/arch/arm/include/asm/processor.h b/arch/arm/include/asm/processor.h
index bdc35c0e8dfb..8a3e0c566d1f 100644
--- a/arch/arm/include/asm/processor.h
+++ b/arch/arm/include/asm/processor.h
@@ -121,6 +121,7 @@ static inline void prefetch(const void *ptr)
 #define ARCH_HAS_PREFETCHW
 static inline void prefetchw(const void *ptr)
 {
+#if !defined(CONFIG_ARM_DISABLE_PREFETCHW)
 	__asm__ __volatile__(
 		".arch_extension	mp\n"
 		__ALT_SMP_ASM(
@@ -128,6 +129,7 @@ static inline void prefetchw(const void *ptr)
 			"pld\t%a0"
 		)
 		:: "p" (ptr));
+#endif
 }
 #endif
 #endif
diff --git a/arch/arm/mach-imx/Kconfig b/arch/arm/mach-imx/Kconfig
index c5a59158722b..1bbc6d63b6ec 100644
--- a/arch/arm/mach-imx/Kconfig
+++ b/arch/arm/mach-imx/Kconfig
@@ -10,6 +10,7 @@ menuconfig ARCH_MXC
 	select PM_OPP if PM
 	select SOC_BUS
 	select SRAM
+	select ARM_DISABLE_PREFETCHW
 	help
 	  Support for Freescale MXC/iMX-based family of processors
 
-- 
2.30.2

Powered by blists - more mailing lists