lkml.org 
[lkml]   [2022]   [Sep]   [15]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
Patch in this message
/
Date
SubjectRe: [RFC PATCH] arm: i.MX6 Cortex-A9: Fix memory ordering inconsistency by disabling prefetch instructions
From
On 2022-07-18 10:51, Mathieu Desnoyers wrote:
> 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:

I had a good discussion with Mark Rutland about this in the hallway
track at LPC2022. I'll write down the follow up testing steps we
identified here so we don't forget.

A first goal that Mark has is of course to try to reproduce on another
Cortex-A9 test board himself.

Another thing he wishes to validate is whether the issue is caused
specifically by the PLDW, or if it can be reproduced when replacing PLDW
with simple loads and stores.

He came up with a change to test: whether turning the prefetchw() (PLDW)
into a load instruction makes the problem disappear or not.

Following that discussion, I also thought of an other thing to try:

struct futex_hash_bucket {
atomic_t waiters;
-> add a dummy integer field here on the same cache line as the
waiters count
spinlock_t lock;
struct plist_head chain;
} ____cacheline_aligned_in_smp;

and store to the dummy integer field rather than using PLDW on waiters.
AFAIU this should bring the cache line locally with intent to write as
well. So it would basically be using false-sharing for the purpose of
prefetching the cache line.

Hopefully we'll be able to proceed with those tests when this round of
conference is over.

Thanks,

Mathieu


>
> 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@entry=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@entry=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@entry=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@entry=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@entry=0xbeb80a8c, clockid=clockid@entry=0, abstime=abstime@entry=0x0, block=block@entry=true) at pthread_join_common.c:145
> #2 0xb6f9d8ec in __pthread_join (threadid=<optimized out>, thread_return=thread_return@entry=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@efficios.com>
> Cc: James Morse <james.morse@arm.com>
> Cc: Catalin Marinas <catalin.marinas@arm.com>
> Cc: Russell King <linux@armlinux.org.uk>
> Cc: "Mark Rutland" <mark.rutland@arm.com>
> Cc: Will Deacon <will@kernel.org>
> Cc: "Shawn Guo" <shawnguo@kernel.org>
> Cc: "Sascha Hauer" <s.hauer@pengutronix.de>
> Cc: Michael Jeanson <mjeanson@efficios.com>
> Cc: linux-arm-kernel@lists.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
>


--
Mathieu Desnoyers
EfficiOS Inc.
https://www.efficios.com

\
 
 \ /
  Last update: 2022-09-15 11:09    [W:0.078 / U:1.192 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site