futex timeout not working? (bisected)

futex timeout not working? (bisected)

[Heiko Carstens]

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

Re: futex timeout not working? (bisected)

[Thomas Gleixner]

Heiko,

On Thu, 15 Oct 2015, Heiko Carstens wrote:
>   /* 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 you actually hand in a pointer to 'ts' then the program works as
expected even with the commit in question applied.

Thanks,

	tglx

Re: futex timeout not working? (bisected)

[Heiko Carstens]

On Fri, Oct 16, 2015 at 12:21:51PM +0200, Thomas Gleixner wrote:
> Heiko,
> 
> On Thu, 15 Oct 2015, Heiko Carstens wrote:
> >   /* 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 you actually hand in a pointer to 'ts' then the program works as
> expected even with the commit in question applied.

Yes, sorry about that! I was just about to write that this should have
been &ts on x86. Since x86 seems to pass also structures >8 bytes by
value.

However on s390 it is passed by reference. So even it I change ts to &ts,
it will hang as I described.

So you are saying this works on x86 and it must be some s390 specific bug?

Re: futex timeout not working? (bisected)

[Thomas Gleixner]

On Fri, 16 Oct 2015, Heiko Carstens wrote:
> On Fri, Oct 16, 2015 at 12:21:51PM +0200, Thomas Gleixner wrote:
> > Heiko,
> > 
> > On Thu, 15 Oct 2015, Heiko Carstens wrote:
> > >   /* 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 you actually hand in a pointer to 'ts' then the program works as
> > expected even with the commit in question applied.
> 
> Yes, sorry about that! I was just about to write that this should have
> been &ts on x86. Since x86 seems to pass also structures >8 bytes by
> value.
> 
> However on s390 it is passed by reference. So even it I change ts to &ts,
> it will hang as I described.
> 
> So you are saying this works on x86 and it must be some s390 specific bug?
 
time ./f
futex-syscall returned with an error:: Connection timed out
ret = -1

real  0m0.501s
user  0m0.000s
sys   0m0.000s

Thanks,

	tglx

Re: futex timeout not working? (bisected)

[Heiko Carstens]

On Fri, Oct 16, 2015 at 12:33:51PM +0200, Thomas Gleixner wrote:
> On Fri, 16 Oct 2015, Heiko Carstens wrote:
> > So you are saying this works on x86 and it must be some s390 specific bug?
> 
> time ./f
> futex-syscall returned with an error:: Connection timed out
> ret = -1
> 
> real  0m0.501s
> user  0m0.000s
> sys   0m0.000s

Too bad. And I thought I could blame somebody else ;)
Sorry for the noise. Will need to dig in our code.

Re: futex timeout not working? (bisected)

[Thomas Gleixner]

On Fri, 16 Oct 2015, Heiko Carstens wrote:
> On Fri, Oct 16, 2015 at 12:21:51PM +0200, Thomas Gleixner wrote:
> > Heiko,
> > 
> > On Thu, 15 Oct 2015, Heiko Carstens wrote:
> > >   /* 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 you actually hand in a pointer to 'ts' then the program works as
> > expected even with the commit in question applied.
> 
> Yes, sorry about that! I was just about to write that this should have
> been &ts on x86. Since x86 seems to pass also structures >8 bytes by
> value.
> 
> However on s390 it is passed by reference. So even it I change ts to &ts,
> it will hang as I described.
> 
> So you are saying this works on x86 and it must be some s390 specific bug?

Looks like. I have no idea why that would break on s390. Did you try
to revert the commit on top of tree?

Thanks,

	tglx

Re: futex timeout not working? (bisected)

[Heiko Carstens]

On Fri, Oct 16, 2015 at 12:35:23PM +0200, Thomas Gleixner wrote:
> On Fri, 16 Oct 2015, Heiko Carstens wrote:
> > On Fri, Oct 16, 2015 at 12:21:51PM +0200, Thomas Gleixner wrote:
> > > Heiko,
> > > 
> > > On Thu, 15 Oct 2015, Heiko Carstens wrote:
> > > >   /* 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 you actually hand in a pointer to 'ts' then the program works as
> > > expected even with the commit in question applied.
> > 
> > Yes, sorry about that! I was just about to write that this should have
> > been &ts on x86. Since x86 seems to pass also structures >8 bytes by
> > value.
> > 
> > However on s390 it is passed by reference. So even it I change ts to &ts,
> > it will hang as I described.
> > 
> > So you are saying this works on x86 and it must be some s390 specific bug?
> 
> Looks like. I have no idea why that would break on s390. Did you try
> to revert the commit on top of tree?

Reverting the patch isn't easy due to all the dependencies the code has in
the meantime. However the following code snippet does logically revert the
patch and it works again:

diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
index 3739ac6aa473..c97dd1cc9bd5 100644
--- a/kernel/time/timekeeping.c
+++ b/kernel/time/timekeeping.c
@@ -1953,12 +1953,10 @@ ktime_t ktime_get_update_offsets_now(unsigned int *cwsseq, ktime_t *offs_real,
 		nsecs = timekeeping_get_ns(&tk->tkr_mono);
 		base = ktime_add_ns(base, nsecs);
 
-		if (*cwsseq != tk->clock_was_set_seq) {
-			*cwsseq = tk->clock_was_set_seq;
-			*offs_real = tk->offs_real;
-			*offs_boot = tk->offs_boot;
-			*offs_tai = tk->offs_tai;
-		}
+		*cwsseq = tk->clock_was_set_seq;
+		*offs_real = tk->offs_real;
+		*offs_boot = tk->offs_boot;
+		*offs_tai = tk->offs_tai;
 
 		/* Handle leapsecond insertion adjustments */
 		if (unlikely(base.tv64 >= tk->next_leap_ktime.tv64))

Re: futex timeout not working? (bisected)

[Heiko Carstens]

On Fri, Oct 16, 2015 at 12:54:51PM +0200, Heiko Carstens wrote:
> > > So you are saying this works on x86 and it must be some s390 specific bug?
> > 
> > Looks like. I have no idea why that would break on s390. Did you try
> > to revert the commit on top of tree?
> 
> Reverting the patch isn't easy due to all the dependencies the code has in
> the meantime. However the following code snippet does logically revert the
> patch and it works again:
> 
> diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
> index 3739ac6aa473..c97dd1cc9bd5 100644
> --- a/kernel/time/timekeeping.c
> +++ b/kernel/time/timekeeping.c
> @@ -1953,12 +1953,10 @@ ktime_t ktime_get_update_offsets_now(unsigned int *cwsseq, ktime_t *offs_real,
>  		nsecs = timekeeping_get_ns(&tk->tkr_mono);
>  		base = ktime_add_ns(base, nsecs);
>  
> -		if (*cwsseq != tk->clock_was_set_seq) {
> -			*cwsseq = tk->clock_was_set_seq;
> -			*offs_real = tk->offs_real;
> -			*offs_boot = tk->offs_boot;
> -			*offs_tai = tk->offs_tai;
> -		}
> +		*cwsseq = tk->clock_was_set_seq;
> +		*offs_real = tk->offs_real;
> +		*offs_boot = tk->offs_boot;
> +		*offs_tai = tk->offs_tai;

Adding the patch below also "fixes" this. Right now I don't see why this
could architecture specific. Hmm.

diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
index 3739ac6aa473..75771b15647c 100644
--- a/kernel/time/timekeeping.c
+++ b/kernel/time/timekeeping.c
@@ -1835,7 +1835,7 @@ void update_wall_time(void)
 	 * memcpy under the tk_core.seq against one before we start
 	 * updating.
 	 */
-	timekeeping_update(tk, clock_set);
+	timekeeping_update(tk, clock_set | TK_CLOCK_WAS_SET);
 	memcpy(real_tk, tk, sizeof(*tk));
 	/* The memcpy must come last. Do not put anything here! */
 	write_seqcount_end(&tk_core.seq);

Re: futex timeout not working? (bisected)

[Thomas Gleixner]

On Fri, 16 Oct 2015, Heiko Carstens wrote:

> On Fri, Oct 16, 2015 at 12:54:51PM +0200, Heiko Carstens wrote:
> > > > So you are saying this works on x86 and it must be some s390 specific bug?
> > > 
> > > Looks like. I have no idea why that would break on s390. Did you try
> > > to revert the commit on top of tree?
> > 
> > Reverting the patch isn't easy due to all the dependencies the code has in
> > the meantime. However the following code snippet does logically revert the
> > patch and it works again:
> > 
> > diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
> > index 3739ac6aa473..c97dd1cc9bd5 100644
> > --- a/kernel/time/timekeeping.c
> > +++ b/kernel/time/timekeeping.c
> > @@ -1953,12 +1953,10 @@ ktime_t ktime_get_update_offsets_now(unsigned int *cwsseq, ktime_t *offs_real,
> >  		nsecs = timekeeping_get_ns(&tk->tkr_mono);
> >  		base = ktime_add_ns(base, nsecs);
> >  
> > -		if (*cwsseq != tk->clock_was_set_seq) {
> > -			*cwsseq = tk->clock_was_set_seq;
> > -			*offs_real = tk->offs_real;
> > -			*offs_boot = tk->offs_boot;
> > -			*offs_tai = tk->offs_tai;
> > -		}
> > +		*cwsseq = tk->clock_was_set_seq;
> > +		*offs_real = tk->offs_real;
> > +		*offs_boot = tk->offs_boot;
> > +		*offs_tai = tk->offs_tai;
> 
> Adding the patch below also "fixes" this. Right now I don't see why this
> could architecture specific. Hmm.
> 
> diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
> index 3739ac6aa473..75771b15647c 100644
> --- a/kernel/time/timekeeping.c
> +++ b/kernel/time/timekeeping.c
> @@ -1835,7 +1835,7 @@ void update_wall_time(void)
>  	 * memcpy under the tk_core.seq against one before we start
>  	 * updating.
>  	 */
> -	timekeeping_update(tk, clock_set);
> +	timekeeping_update(tk, clock_set | TK_CLOCK_WAS_SET);
>  	memcpy(real_tk, tk, sizeof(*tk));
>  	/* The memcpy must come last. Do not put anything here! */
>  	write_seqcount_end(&tk_core.seq);

Well, the latter is incrementing the sequence count on every wall time
update.

The question is why the hrtimer code is not seeing that the clock was
set at some point during boot.

Lemme dig into that.

Thanks,

	tglx

Re: futex timeout not working? (bisected)

[Thomas Gleixner]

Heiko,

On Fri, 16 Oct 2015, Thomas Gleixner wrote:
> On Fri, 16 Oct 2015, Heiko Carstens wrote:
> > Adding the patch below also "fixes" this. Right now I don't see why this
> > could architecture specific. Hmm.
> > 
> > diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
> > index 3739ac6aa473..75771b15647c 100644
> > --- a/kernel/time/timekeeping.c
> > +++ b/kernel/time/timekeeping.c
> > @@ -1835,7 +1835,7 @@ void update_wall_time(void)
> >  	 * memcpy under the tk_core.seq against one before we start
> >  	 * updating.
> >  	 */
> > -	timekeeping_update(tk, clock_set);
> > +	timekeeping_update(tk, clock_set | TK_CLOCK_WAS_SET);
> >  	memcpy(real_tk, tk, sizeof(*tk));
> >  	/* The memcpy must come last. Do not put anything here! */
> >  	write_seqcount_end(&tk_core.seq);
> 
> Well, the latter is incrementing the sequence count on every wall time
> update.
> 
> The question is why the hrtimer code is not seeing that the clock was
> set at some point during boot.
> 
> Lemme dig into that.

The only point I found which does not update the sequence count is
timekeeping_init().

Does the patch below fix your issue?

Thanks,

	tglx

8<--------------------

diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
index 3739ac6aa473..44d2cc0436f4 100644
--- a/kernel/time/timekeeping.c
+++ b/kernel/time/timekeeping.c
@@ -1251,7 +1251,7 @@ void __init timekeeping_init(void)
 	set_normalized_timespec64(&tmp, -boot.tv_sec, -boot.tv_nsec);
 	tk_set_wall_to_mono(tk, tmp);
 
-	timekeeping_update(tk, TK_MIRROR);
+	timekeeping_update(tk, TK_MIRROR | TK_CLOCK_WAS_SET);
 
 	write_seqcount_end(&tk_core.seq);
 	raw_spin_unlock_irqrestore(&timekeeper_lock, flags);

Re: futex timeout not working? (bisected)

[Heiko Carstens]

On Fri, Oct 16, 2015 at 02:45:37PM +0200, Thomas Gleixner wrote:
> The only point I found which does not update the sequence count is
> timekeeping_init().
> 
> Does the patch below fix your issue?
> 

Yes, it does. Thanks for looking into this and fixing it!


> 8<--------------------
> 
> diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
> index 3739ac6aa473..44d2cc0436f4 100644
> --- a/kernel/time/timekeeping.c
> +++ b/kernel/time/timekeeping.c
> @@ -1251,7 +1251,7 @@ void __init timekeeping_init(void)
>  	set_normalized_timespec64(&tmp, -boot.tv_sec, -boot.tv_nsec);
>  	tk_set_wall_to_mono(tk, tmp);
> 
> -	timekeeping_update(tk, TK_MIRROR);
> +	timekeeping_update(tk, TK_MIRROR | TK_CLOCK_WAS_SET);
> 
>  	write_seqcount_end(&tk_core.seq);
>  	raw_spin_unlock_irqrestore(&timekeeper_lock, flags);
>