Several tst-robust* tests time out with recent Linux kernel

[Stefan Liebler]

On 17.11.23 02:22, Edgecombe, Rick P wrote:
> A bit more info...
> 
> The error returned to userspace is originating from:
> https://github.com/torvalds/linux/blob/master/kernel/futex/pi.c#L295
> 
> 'uval' is often zero in that error case, but sometimes just a
> mismatching value like: uval=0x567, task_pid_vnr()=0x564
> 
> 
> Depending on the number of CPUs the VM is running on it reproduces or
> not. When it does reproduce, the newly added path here is taken:
> https://github.com/torvalds/linux/blob/master/kernel/futex/pi.c#L1185
> The path is taken a lot during the test, sometimes >400 times before
> the above linked error is generated during the syscall. When it doesn't
> reproduce, I never saw that new path taken.
> 
> More print statements make the reproduction less reliable, so it does
> seem to have a race in the mix at least somewhat. Otherwise, I haven't
> tried to understand what is going on here with all this highwire
> locking.
> 
> Hope it helps.
Hi,

I've also observed fails in glibc testcase nptl/tst-robust8pi with:
mutex_timedlock of 66 in thread 7 failed with 22
=> pthread_mutex_timedlock returns 22=EINVAL

I've saw it on s390x. There I've used kernel with
commit 120d99901eb288f1d21db3976df4ba347b28f9c7
s390/vfio-ap: do not reset queue removed from host config

But I also saw it on a x86_64 kvm-guest with Fedora 39 and
copr-repository with vanilla kernel:
Linux fedora 6.7.0-0.rc8.20240107gt52b1853b.366.vanilla.fc39.x86_64 #1
SMP PREEMPT_DYNAMIC Sun Jan  7 06:17:30 UTC 2024 x86_64 GNU/Linux

And reported it to libc-alpha ("FAILING nptl/tst-robust8pi"
https://sourceware.org/pipermail/libc-alpha/2024-January/154150.html)
where Florian Weimer pointed me to this thread.

I've reduced the test (see attachement) and now have only one process
with three threads. I only use one mutex with attributes like the
original testcase: PTHREAD_MUTEX_ROBUST_NP, PTHREAD_PROCESS_SHARED,
PTHREAD_PRIO_INHERIT.
Every thread is doing a loop with pthread_mutex_timedlock(abstime={0,0})
and if locked, pthread_mutex_unlock.

I've added some uprobes before and after the futex-syscall in
__futex_lock_pi64(in pthread_mutex_timedlock) and futex_unlock_pi(in
pthread_mutex_unlock). For me __ASSUME_FUTEX_LOCK_PI2 is not available,
but __ASSUME_TIME64_SYSCALLS is defined.

For me it looks like this (simplified ubprobes-trace):
<thread> <timestamp>: <probe>
t1 4309589.419744: before syscall in __futex_lock_pi64

t3 4309589.419745: before syscall in futex_unlock_pi
t2 4309589.419745: before syscall in __futex_lock_pi64

t3 4309589.419747: after syscall in futex_unlock_pi
t2 4309589.419747: after syscall in __futex_lock_pi64 ret=-22=EINVAL

t1 4309589.419748: after syscall in __futex_lock_pi64 ret=-110=ETIMEDOUT

Can you please have a look again?

Bye,
Stefan Liebler
-------------- next part --------------
A non-text attachment was scrubbed...
Name: tst-robust8pi-20240118.c
Type: text/x-csrc
Size: 4161 bytes
Desc: not available
URL: <https://sourceware.org/pipermail/libc-alpha/attachments/20240119/9cd124a5/attachment-0001.bin>