[PATCH] [RFC] Potential fix for leapsecond caused futex related load spikes

[PATCH] [RFC] Potential fix for leapsecond caused futex related load spikes

[John Stultz]

As widely reported on the internet today, some Linux systems after
the leapsecond was inserted are experiencing futex related load
spikes (usually connected to MySQL, Firefox, Thunderbird, Java, etc).

An apparent for this issue workaround is running:
$ date -s "`date`"

Credit: http://www.sheeri.com/content/mysql-and-leap-second-high-cpu-and-fix

I believe this issue is due to the leapsecond being added without
calling clock_was_set() to notify the hrtimer subsystem of the
change. (Although I've not yet chased all the way down to the
hrtimer code to validate exactly what's going on there).

The workaround functions as it forces a clock_was_set()
call from settimeofday().

This fix adds some extra logic to track when a leapsecond
is added from update_wall_time() and calls clock_was_set()
once the timekeeper.lock is released.

I've been able to reproduce the load spike using Thunderbird
when triggering a leap second and with this patch the issue
did not crop up.

NOTE: Some reports have been of a hard hang right at or before
the leapsecond. I've not been able to reproduce or diagnose
this, so this fix does not likely address the reported hard
hangs (unless they end up being connected to the futex/hrtimer
issue).

It had been a long day before I heard about this issue, so
my brain is a little mushy right now. Reviews and extra
testing would be greatly appreciated.

CC: stable@vger.kernel.org
CC: Thomas Gleixner <tglx@linutronix.de>
Reported-by: Jan Engelhardt <jengelh@inai.de>
Signed-off-by: John Stultz <johnstul@us.ibm.com>
---
 kernel/time/timekeeping.c |   11 +++++++++--
 1 file changed, 9 insertions(+), 2 deletions(-)

diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
index 6f46a00..e5da44f 100644
--- a/kernel/time/timekeeping.c
+++ b/kernel/time/timekeeping.c
@@ -942,7 +942,7 @@ static void timekeeping_adjust(s64 offset)
  *
  * Returns the unconsumed cycles.
  */
-static cycle_t logarithmic_accumulation(cycle_t offset, int shift)
+static cycle_t logarithmic_accumulation(cycle_t offset, int shift, int* clockset)
 {
 	u64 nsecps = (u64)NSEC_PER_SEC << timekeeper.shift;
 	u64 raw_nsecs;
@@ -963,6 +963,8 @@ static cycle_t logarithmic_accumulation(cycle_t offset, int shift)
 		leap = second_overflow(timekeeper.xtime.tv_sec);
 		timekeeper.xtime.tv_sec += leap;
 		timekeeper.wall_to_monotonic.tv_sec -= leap;
+		if (leap)
+			*clockset = 1;
 	}
 
 	/* Accumulate raw time */
@@ -994,6 +996,7 @@ static void update_wall_time(void)
 	struct clocksource *clock;
 	cycle_t offset;
 	int shift = 0, maxshift;
+	int clockset = 0;
 	unsigned long flags;
 
 	write_seqlock_irqsave(&timekeeper.lock, flags);
@@ -1026,7 +1029,7 @@ static void update_wall_time(void)
 	maxshift = (64 - (ilog2(ntp_tick_length())+1)) - 1;
 	shift = min(shift, maxshift);
 	while (offset >= timekeeper.cycle_interval) {
-		offset = logarithmic_accumulation(offset, shift);
+		offset = logarithmic_accumulation(offset, shift, &clockset);
 		if(offset < timekeeper.cycle_interval<<shift)
 			shift--;
 	}
@@ -1079,6 +1082,8 @@ static void update_wall_time(void)
 		leap = second_overflow(timekeeper.xtime.tv_sec);
 		timekeeper.xtime.tv_sec += leap;
 		timekeeper.wall_to_monotonic.tv_sec -= leap;
+		if (leap)
+			clockset = 1;
 	}
 
 	timekeeping_update(false);
@@ -1086,6 +1091,8 @@ static void update_wall_time(void)
 out:
 	write_sequnlock_irqrestore(&timekeeper.lock, flags);
 
+	if (clockset)
+		clock_was_set();
 }
 
 /**
-- 
1.7.9.5

Re: [PATCH] [RFC] Potential fix for leapsecond caused futex related load spikes

[John Stultz]

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

On 07/01/2012 02:36 AM, John Stultz wrote:
> As widely reported on the internet today, some Linux systems after
> the leapsecond was inserted are experiencing futex related load
> spikes (usually connected to MySQL, Firefox, Thunderbird, Java, etc).
>
> An apparent for this issue workaround is running:
> $ date -s "`date`"
>
> Credit: http://www.sheeri.com/content/mysql-and-leap-second-high-cpu-and-fix
>
> I believe this issue is due to the leapsecond being added without
> calling clock_was_set() to notify the hrtimer subsystem of the
> change. (Although I've not yet chased all the way down to the
> hrtimer code to validate exactly what's going on there).
>
> The workaround functions as it forces a clock_was_set()
> call from settimeofday().
>
> This fix adds some extra logic to track when a leapsecond
> is added from update_wall_time() and calls clock_was_set()
> once the timekeeper.lock is released.
>
> I've been able to reproduce the load spike using Thunderbird
> when triggering a leap second and with this patch the issue
> did not crop up.

Also, attached is the test case I've been using to trigger leapseconds, 
in case anyone else is interested in trying to either test this fix or 
help reproduce the reported hard hangs.

To build:
gcc leaptest.c -o leaptest -lrt

thanks
-john




[-- Attachment #2: leaptest.c --]
[-- Type: text/x-csrc, Size: 2076 bytes --]

/* Leap second test
 *              by: john stultz (johnstul@us.ibm.com)
 *              (C) Copyright IBM 2012
 *              Licensed under the GPL
 */


#include <stdio.h>
#include <time.h>
#include <sys/time.h>
#include <sys/timex.h>


#define CALLS_PER_LOOP 64
#define NSEC_PER_SEC 1000000000ULL

/* returns 1 if a <= b, 0 otherwise */
static inline int in_order(struct timespec a, struct timespec b)
{
	if(a.tv_sec < b.tv_sec)
		return 1;
	if(a.tv_sec > b.tv_sec)
		return 0;
	if(a.tv_nsec > b.tv_nsec)
		return 0;
	return 1;
}


int  main(void)
{
	struct timeval tv;
	struct timex tx;
	struct timespec list[CALLS_PER_LOOP];
	int i, inconsistent;
	int clock_type = CLOCK_REALTIME;
	long now, then;

	/* Get the current time */
	gettimeofday(&tv, NULL);

	/* Calculate the next leap second */
	tv.tv_sec += 86400 - tv.tv_sec % 86400;

	/* Set the time to be 10 seconds from that time */
	tv.tv_sec -= 10;
	settimeofday(&tv, NULL);

	/* Set the leap second insert flag */
	tx.modes = ADJ_STATUS;
	tx.status = STA_INS;
	adjtimex(&tx);

	clock_gettime(clock_type, &list[0]);
	now = then = list[0].tv_sec;
	while(now - then < 30){
		inconsistent = 0;

		/* Fill list */
		for(i=0; i < CALLS_PER_LOOP; i++)
			clock_gettime(clock_type, &list[i]);

		/* Check for inconsistencies */
		for(i=0; i < CALLS_PER_LOOP-1; i++)
			if(!in_order(list[i],list[i+1]))
				inconsistent = i;

		/* display inconsistency */
		if(inconsistent){
			unsigned long long delta;
			for(i=0; i < CALLS_PER_LOOP; i++){
				if(i == inconsistent)
					printf("--------------------\n");
				printf("%lu:%lu\n",list[i].tv_sec,
							list[i].tv_nsec);
				if(i == inconsistent + 1 )
					printf("--------------------\n");
			}
			delta = list[inconsistent].tv_sec*NSEC_PER_SEC;
			delta += list[inconsistent].tv_nsec;
			delta -= list[inconsistent+1].tv_sec*NSEC_PER_SEC;
			delta -= list[inconsistent+1].tv_nsec;
			printf("Delta: %llu ns\n", delta);
			fflush(0);
			break;
		}
		now = list[0].tv_sec;
	}

	/* clear TIME_WAIT */
	tx.modes = ADJ_STATUS;
	tx.status = 0;
	adjtimex(&tx);

	return 0;
}

Re: [PATCH] [RFC] Potential fix for leapsecond caused futex related load spikes

[Jan Ceuleers]

On 07/01/2012 11:36 AM, John Stultz wrote:
> I believe this issue is due to the leapsecond being added without
> calling clock_was_set() to notify the hrtimer subsystem of the
> change. (Although I've not yet chased all the way down to the
> hrtimer code to validate exactly what's going on there).

For the benefit of -stable:

Am I right in thinking that, if the analysis is confirmed, this was
caused by the following commit:

commit 746976a301ac9c9aa10d7d42454f8d6cdad8ff2b
Author: Thomas Gleixner <tglx@linutronix.de>
Date:   Tue Jul 3 20:05:20 2007 +0200

NTP: remove clock_was_set() call to prevent deadlock

The clock_was_set() call in seconds_overflow() which happens only when
leap seconds are inserted / deleted is wrong in two aspects:

1. it results in a call to on_each_cpu() with interrupts disabled
2. it is potential deadlock source vs. call_lock in smp_call_function()

The only possible side effect of the removal might be, that an absolute
CLOCK_REALTIME timer fires 1 second too late, in the rare case of leap
second deletion and an absolute CLOCK_REALTIME timer which expires in
the affected time frame. It will never fire too early.

This was probably observed by the reporter of a June 30th -> July 1st
hang: http://lkml.org/lkml/2007/7/3/103

A similar problem was observed by Dave Jones, who provided a screen shot
with a lockdep back trace, which allowed to analyse the problem.

Sob: Thomas Gleixner <tglx@linutronix.de>
Ab: Ingo Molnar <mingo@elte.hu>
Sob: Linus Torvalds <torvalds@linux-foundation.org>