futex timeout not working? (bisected)

From: Heiko Carstens
Date: Thu Oct 15 2015 - 06:44:45 EST

Next message: Mark Rutland: "Re: [PATCHv3 08/11] arm64: Check for selected granule support"
Previous message: Loan: "Loan Offer"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

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@xxxxxxxxxxxxx>
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@xxxxxxxxxxxxx>
Reviewed-by: Preeti U Murthy <preeti@xxxxxxxxxxxxxxxxxx>
Acked-by: Peter Zijlstra <peterz@xxxxxxxxxxxxx>
Cc: Viresh Kumar <viresh.kumar@xxxxxxxxxx>
Cc: Marcelo Tosatti <mtosatti@xxxxxxxxxx>
Cc: Frederic Weisbecker <fweisbec@xxxxxxxxx>
Cc: John Stultz <john.stultz@xxxxxxxxxx>
Link: http://lkml.kernel.org/r/20150414203501.132820245@xxxxxxxxxxxxx
Signed-off-by: Thomas Gleixner <tglx@xxxxxxxxxxxxx>
Cc: John Stultz <john.stultz@xxxxxxxxxx>

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

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

Next message: Mark Rutland: "Re: [PATCHv3 08/11] arm64: Check for selected granule support"
Previous message: Loan: "Loan Offer"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]