Re: [LTP] [PATCH] timers: add a new test case leapsec_timer

Lingzhu Xiang
2012-07-06T09:46:34Z

On 07/08/2012 08:09 AM, Lingzhu Xiang wrote:
> A bug in the hrtimer subsystem caused all TIMER_ABSTIME CLOCK_REALTIME
> timers to expire one second early during and after leap seconds, thus
> such sub-second timers expire immediately, causing load spikes if used
> in fast loops. Calling clock_was_set() reverts this state. See [1].
>
> [1]: http://lwn.net/Articles/504658/.
>
> This patch is a regression test for the bug, based on the test case
> provided by John Stultz from the above link, and also tries to recover
> from inconsistency caused by reproduction of the bug.

A sample test run looks like this:

leapsec_timer 0 TINFO : test start at 2012-07-08
08:02:32.996771295 +0800
leapsec_timer 0 TINFO : now is 2012-07-08 08:02:32.996929883 +0800
leapsec_timer 0 TINFO : sleep till 2012-07-08 08:02:33.996929883 +0800
leapsec_timer 0 TINFO : now is 2012-07-08 08:02:33.996975957 +0800
leapsec_timer 0 TINFO : hrtimer early expiration is not detected.
leapsec_timer 0 TINFO : scheduling leap second 2012-07-09
08:00:00.000000000 +0800
leapsec_timer 0 TINFO : setting time to 2012-07-09
07:59:58.000000000 +0800
leapsec_timer 0 TINFO : 2012-07-09 07:59:58.000080000 +0800
adjtimex: clock synchronized
leapsec_timer 0 TINFO : 2012-07-09 07:59:58.000101000 +0800
adjtimex: clock synchronized
leapsec_timer 0 TINFO : 2012-07-09 07:59:58.000119000 +0800
adjtimex: insert leap second
leapsec_timer 0 TINFO : 2012-07-09 07:59:58.000138000 +0800
adjtimex: insert leap second
leapsec_timer 0 TINFO : 2012-07-09 07:59:58.500174000 +0800
adjtimex: insert leap second
leapsec_timer 0 TINFO : 2012-07-09 07:59:59.000246000 +0800
adjtimex: insert leap second
leapsec_timer 0 TINFO : 2012-07-09 07:59:59.500320000 +0800
adjtimex: insert leap second
leapsec_timer 0 TINFO : 2012-07-09 07:59:59.000368000 +0800
adjtimex: leap second in progress
leapsec_timer 0 TINFO : 2012-07-09 07:59:59.500403000 +0800
adjtimex: leap second in progress
leapsec_timer 0 TINFO : 2012-07-09 08:00:00.000432000 +0800
adjtimex: leap second has occurred
leapsec_timer 0 TINFO : 2012-07-09 08:00:00.500457000 +0800
adjtimex: leap second has occurred
leapsec_timer 0 TINFO : 2012-07-09 08:00:01.000475000 +0800
adjtimex: leap second has occurred
leapsec_timer 0 TINFO : 2012-07-09 08:00:01.500489000 +0800
adjtimex: leap second has occurred
leapsec_timer 0 TINFO : 2012-07-09 08:00:02.000506000 +0800
adjtimex: leap second has occurred
leapsec_timer 0 TINFO : now is 2012-07-09 08:00:02.500524432 +0800
leapsec_timer 0 TINFO : sleep till 2012-07-09 08:00:03.500524432 +0800
leapsec_timer 0 TINFO : now is 2012-07-09 08:00:02.500550236 +0800
leapsec_timer 1 TFAIL : hrtimer early expiration is detected.
leapsec_timer 0 TINFO : 2012-07-09 08:00:02.500561000 +0800
adjtimex: clock synchronized
leapsec_timer 0 TINFO : 2012-07-09 08:00:02.500568000 +0800
adjtimex: clock synchronized
leapsec_timer 0 TINFO : restoring time to 2012-07-08
08:02:37.497346606 +0800
leapsec_timer 0 TINFO : now is 2012-07-08 08:02:37.497351161 +0800
leapsec_timer 0 TINFO : sleep till 2012-07-08 08:02:38.497351161 +0800
leapsec_timer 0 TINFO : now is 2012-07-08 08:02:38.497391392 +0800
leapsec_timer 0 TINFO : hrtimer early expiration is not detected.

As can be observed, the first timer before the leap second and third timer
after resetting time state worked as expected (early expiration not
detected),
but the second timer after the leap second before resetting time state
returned unexpectedly early. Thus the above bug was reproduced.

Note that this test case might cause kernel freeze. Running with -c 5 will
highly increase the likelihood of that.