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

[Stefan Liebler <stli@linux.ibm.com>]

[-- Attachment #1: Type: text/plain, Size: 2794 bytes --]

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

[-- Attachment #2: tst-robust8pi-20240118.c --]
[-- Type: text/x-csrc, Size: 4161 bytes --]

//CFLAGS=-pthread
//LDFLAGS=-lpthread
#include <stdio.h>
#include <stdlib.h>
#include <pthread.h>
#include <assert.h>
#include <errno.h>
#include <unistd.h>

#define NUM_THREADS 3
#define THREAD_FUNC thr_func
#define USE_BARRIER 1
#ifndef ROUNDS
# define ROUNDS 100000000
#endif

typedef struct thr_info
{
  int nr;
  pthread_t thread;
} __attribute__ ((aligned (256))) thr_info_t;

#define THR_INIT()				\
  thr_info_t *thr = (thr_info_t *) arg;

#define THR_PRINTF(fmt, ...)			\
  printf ("#%d: " fmt, thr->nr, __VA_ARGS__)

#define THR_PUTS(msg)				\
  printf ("#%d: " msg "\n", thr->nr)

#if USE_BARRIER != 0
static pthread_barrier_t thrs_barrier;
#endif

static pthread_mutex_t mtx;
static const struct timespec before = { 0, 0 };

/* ###################################################################
   thread func
   ###############################################################  */

static void *
thr_func (void *arg)
{
  THR_INIT ();
  int state = 0;
  int fct;

#if 0
  /* 3 threads, 1xfct=0=pthread_mutex_lock, 2xfct=1=pthread_mutex_timedlock: EINVAL.  */
  fct = (thr->nr + 1) % 2;
#elif 0
  /* 3 threads, 2xfct=0=pthread_mutex_lock, 1xfct=1=pthread_mutex_timedlock: no fails.  */
  fct = (thr->nr) % 2;
#elif 1
  /* >3 threads, fct=1=only pthread_mutex_timedlock: EINVAL.  */
  fct = 1;
#endif

  int round = 0;
  THR_PRINTF ("started: fct=%d\n", fct);
#if USE_BARRIER != 0
  pthread_barrier_wait (&thrs_barrier);
#endif
  while (1)
    {

      if (state == 0)
	{
	  round ++;
	  int e;

	  switch (fct)
	    {
	    case 0:
	      e = pthread_mutex_lock (&mtx);
	      if (e != 0)
		{
		  THR_PRINTF ("mutex_lock failed with %d (round=%d)\n", e, round);
		  exit (1);
		}
	      state = 1;
	      break;
	    case 1:
	      e = pthread_mutex_timedlock (&mtx, &before);
	      if (e != 0 && e != ETIMEDOUT)
		{
		  THR_PRINTF ("mutex_timedlock failed with %d (round=%d)\n", e, round);
		  exit (1);
		}
	      break;
	    default:
	      e = pthread_mutex_trylock (&mtx);
	      if (e != 0 && e != EBUSY)
		{
		  THR_PRINTF ("mutex_trylock failed with %d (round=%d)\n", e, round);
		  exit (1);
		}
	      break;
	    }

	  if (e == EOWNERDEAD)
	    pthread_mutex_consistent (&mtx);

	  if (e == 0 || e == EOWNERDEAD)
	    state = 1;
	}
      else
	{
	  int e = pthread_mutex_unlock (&mtx);
	  if (e != 0)
	    {
	      THR_PRINTF ("mutex_unlock of failed with %d (round=%d)\n", e, round);
	      exit (1);
	    }
	  state = 0;
	}

      if (round >= ROUNDS)
	{
	  THR_PRINTF ("REACHED round %d. => exit\n", ROUNDS);
	  if (state != 0)
	    {
	      int e = pthread_mutex_unlock (&mtx);
	      if (e != 0)
		{
		  THR_PRINTF ("mutex_unlock@exit of failed with %d (round=%d)\n", e, round);
		  exit (1);
		}
	    }
	  break;
	}
    }

  return NULL;
}

int
main (void)
{
  int i;
  printf ("main: start %d threads.\n", NUM_THREADS);

#if USE_BARRIER != 0
  pthread_barrier_init (&thrs_barrier, NULL, NUM_THREADS + 1);
#endif

  pthread_mutexattr_t ma;
  if (pthread_mutexattr_init (&ma) != 0)
    {
      puts ("mutexattr_init failed");
      return 0;
    }
  if (pthread_mutexattr_setrobust (&ma, PTHREAD_MUTEX_ROBUST_NP) != 0)
    {
      puts ("mutexattr_setrobust failed");
      return 1;
    }
  if (pthread_mutexattr_setpshared (&ma, PTHREAD_PROCESS_SHARED) != 0)
    {
      puts ("mutexattr_setpshared failed");
      return 1;
    }
  if (pthread_mutexattr_setprotocol (&ma, PTHREAD_PRIO_INHERIT) != 0)
    {
      puts ("pthread_mutexattr_setprotocol failed");
      return 1;
    }

  if (pthread_mutex_init (&mtx, &ma) != 0)
    {
      puts ("pthread_mutex_init failed");
      return 1;
    }

  thr_info_t thrs[NUM_THREADS];
  for (i = 0; i < NUM_THREADS; i++)
    {
      thrs[i].nr = i;
      assert (pthread_create (&(thrs[i].thread), NULL, THREAD_FUNC, &(thrs[i]))
	      == 0);;
    }

#if USE_BARRIER != 0
  /* All threads start work after this barrier.  */
  pthread_barrier_wait (&thrs_barrier);
#endif

  for (i = 0; i < NUM_THREADS; i++)
    {
      pthread_join (thrs[i].thread, NULL);
    }

#if USE_BARRIER != 0
  pthread_barrier_destroy (&thrs_barrier);
#endif

  printf ("main: end.\n");
  return EXIT_SUCCESS;
}