futex timeout not working? (bisected)

[Heiko Carstens <heiko.carstens@de.ibm.com>]

Hi Thomas,

I received a bug report from Stefan Liebler that certain futex timeouts
do not work anymore at least on s390 (see test case below).

I did a quick bisect which ended at this commit:

868a3e915f7f5eba8f8cb4f7da2276760807c51c is the first bad commit
commit 868a3e915f7f5eba8f8cb4f7da2276760807c51c
Author: Thomas Gleixner <tglx@linutronix.de>
Date:   Tue Apr 14 21:08:37 2015 +0000

    hrtimer: Make offset update smarter
    
    On every tick/hrtimer interrupt we update the offset variables of the
    clock bases. That's silly because these offsets change very seldom.
    
    Add a sequence counter to the time keeping code which keeps track of
    the offset updates (clock_was_set()). Have a sequence cache in the
    hrtimer cpu bases to evaluate whether the offsets must be updated or
    not. This allows us later to avoid pointless cacheline pollution.
    
    Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
    Reviewed-by: Preeti U Murthy <preeti@linux.vnet.ibm.com>
    Acked-by: Peter Zijlstra <peterz@infradead.org>
    Cc: Viresh Kumar <viresh.kumar@linaro.org>
    Cc: Marcelo Tosatti <mtosatti@redhat.com>
    Cc: Frederic Weisbecker <fweisbec@gmail.com>
    Cc: John Stultz <john.stultz@linaro.org>
    Link: http://lkml.kernel.org/r/20150414203501.132820245@linutronix.de
    Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
    Cc: John Stultz <john.stultz@linaro.org>

Before that commit the testcase below failed after 0.5s, like expected. With
that commit the timer doesn't seem to expire. See also /proc/timer_list which
I added below when running kernel version 4.3.0-rc5.

Do you have an idea what's wrong here?

Thanks,
Heiko

Test program:

//CFLAGS=
//LDFLAGS=
#define _GNU_SOURCE
#include <stdio.h>
#include <stdlib.h>
#include <linux/futex.h>
#include <sys/time.h>
#include <unistd.h>
#include <sys/syscall.h>

int
main (void)
{
  int futex_word = 0;
#define FUTEX_PRIVATE 0
  int op = FUTEX_WAIT_BITSET | FUTEX_CLOCK_REALTIME | FUTEX_PRIVATE;
  int expected = 0;
  struct timespec ts;
  struct timeval tv;
  int ret;

  if (gettimeofday (&tv, NULL) != 0)
    {
      puts ("gettimeofday failed");
      return 1;
    }

  TIMEVAL_TO_TIMESPEC (&tv, &ts);

  /* We wait for half a second.  */
  ts.tv_nsec += 500000000;
  if (ts.tv_nsec >= 1000000000)
    {
      ++ts.tv_sec;
      ts.tv_nsec -= 1000000000;
    }

  ret = syscall (__NR_futex, &futex_word, op, expected, ts, NULL, FUTEX_BITSET_MATCH_ANY);
  if (ret == -1)
    {
      perror ("futex-syscall returned with an error:");
    }
  printf ("ret = %d\n", ret);
  return EXIT_SUCCESS;
}


Output of /proc/timer_list (a.out is the process in question).

Timer List Version: v0.8
HRTIMER_MAX_CLOCK_BASES: 4
now at 5669154446189 nsecs

cpu: 0
 clock 0:
  .base:       000000003e784b40
  .index:      0
  .resolution: 1 nsecs
  .get_time:   ktime_get
  .offset:     0 nsecs
active timers:
 #0: <000000003e784fc8>, tick_sched_timer, S:01, tick_nohz_restart, swapper/0/0
 # expires at 5669155904652-5669155904652 nsecs [in 1458463 to 1458463 nsecs]
 #1: <0000000039b4ef00>, timerfd_tmrproc, S:01, do_timerfd_settime, systemd-logind/355
 # expires at 5670131137000-5670131137000 nsecs [in 976690811 to 976690811 nsecs]
 #2: <0000000039b9ba28>, hrtimer_wakeup, S:01, schedule_hrtimeout_range_clock.part.6, gmain/371
 # expires at 5672000040022-5672004036021 nsecs [in 2845593833 to 2849589832 nsecs]
 #3: <0000000039b43a28>, hrtimer_wakeup, S:01, schedule_hrtimeout_range_clock.part.6, rpcbind/353
 # expires at 5679106011014-5679136011013 nsecs [in 9951564825 to 9981564824 nsecs]
 #4: <000000003b6d7e60>, hrtimer_wakeup, S:01, do_nanosleep, crond/360
 # expires at 5679505850152-5679505900152 nsecs [in 10351403963 to 10351453963 nsecs]
 #5: <000000003c0c3400>, timerfd_tmrproc, S:01, do_timerfd_settime, systemd-journal/123
 # expires at 5679631137000-5679631137000 nsecs [in 10476690811 to 10476690811 nsecs]
 #6: <000000003c0a9600>, timerfd_tmrproc, S:01, do_timerfd_settime, systemd-network/354
 # expires at 5680131137000-5680131137000 nsecs [in 10976690811 to 10976690811 nsecs]
 #7: <000000003c0c0200>, timerfd_tmrproc, S:01, do_timerfd_settime, systemd-journal/123
 # expires at 5690131137000-5690131137000 nsecs [in 20976690811 to 20976690811 nsecs]
 #8: <000000003c089100>, timerfd_tmrproc, S:01, do_timerfd_settime, systemd/1
 # expires at 5690381137000-5690381137000 nsecs [in 21226690811 to 21226690811 nsecs]
 #9: <0000000039d2be60>, hrtimer_wakeup, S:01, do_nanosleep, sleep/23893
 # expires at 5703965950486-5703966000486 nsecs [in 34811504297 to 34811554297 nsecs]
 #10: <0000000038b8fa28>, hrtimer_wakeup, S:01, schedule_hrtimeout_range_clock.part.6, NetworkManager/338
 # expires at 5704000462109-5704060386108 nsecs [in 34846015920 to 34905939919 nsecs]
 #11: <0000000039f37e60>, hrtimer_wakeup, S:01, do_nanosleep, atd/361
 # expires at 7203318466583-7203318516583 nsecs [in 1534164020394 to 1534164070394 nsecs]
 clock 1:
  .base:       000000003e784b80
  .index:      1
  .resolution: 1 nsecs
  .get_time:   ktime_get_real
  .offset:     0 nsecs
active timers:
 #0: <0000000039113ca8>, hrtimer_wakeup, S:01, futex_wait_queue_me, a.out/23871
 # expires at 1444905100055495000-1444905100055545000 nsecs [in 1444899430901048811 to 1444899430901098811 nsecs]
 #1: <00000000359ee800>, timerfd_tmrproc, S:01, do_timerfd_settime, systemd/1522
 # expires at 9223372036854775807-9223372036854775807 nsecs [in 9223366367700329618 to 9223366367700329618 nsecs]
 #2: <000000003d3bb600>, timerfd_tmrproc, S:01, do_timerfd_settime, systemd/1
 # expires at 9223372036854775807-9223372036854775807 nsecs [in 9223366367700329618 to 9223366367700329618 nsecs]
 clock 2:
  .base:       000000003e784bc0
  .index:      2
  .resolution: 1 nsecs
  .get_time:   ktime_get_boottime
  .offset:     0 nsecs
active timers:
 clock 3:
  .base:       000000003e784c00
  .index:      3
  .resolution: 1 nsecs
  .get_time:   ktime_get_clocktai
  .offset:     0 nsecs
active timers:
  .expires_next   : 5669155904652 nsecs
  .hres_active    : 1
  .nr_events      : 16206
  .nr_retries     : 8
  .nr_hangs       : 0
  .max_hang_time  : 0
  .nohz_mode      : 2
  .last_tick      : 5669085904652 nsecs
  .tick_stopped   : 0
  .idle_jiffies   : 4295504200
  .idle_calls     : 30731
  .idle_sleeps    : 9923
  .idle_entrytime : 5669153708785 nsecs
  .idle_waketime  : 5669153708785 nsecs
  .idle_exittime  : 5669153722880 nsecs
  .idle_sleeptime : 5647204783130 nsecs
  .iowait_sleeptime: 1444642837 nsecs
  .last_jiffies   : 4295504200
  .next_timer     : 5669205904652
  .idle_expires   : 5669205904652 nsecs
jiffies: 4295504207

Tick Device: mode:     1
Per CPU device: 0
Clock Event Device: comparator
 max_delta_ns:   9223372036854775807
 min_delta_ns:   1
 mult:           16777
 shift:          12
 mode:           3
 next_event:     5669155904652 nsecs
 set_next_event: s390_next_event
 event_handler:  hrtimer_interrupt
 retries:        6