[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <CALAqxLVj058mjS2tZSOJT0MZRSUyfa=o9OHiAUDr+ZGV5EfU+g@mail.gmail.com>
Date: Mon, 1 Jun 2015 13:32:26 -0700
From: John Stultz <john.stultz@...aro.org>
To: Daniel Bristot de Oliveira <bristot@...hat.com>
Cc: lkml <linux-kernel@...r.kernel.org>,
Prarit Bhargava <prarit@...hat.com>,
Richard Cochran <richardcochran@...il.com>,
Jan Kara <jack@...e.cz>, Jiri Bohac <jbohac@...e.cz>,
Thomas Gleixner <tglx@...utronix.de>,
Ingo Molnar <mingo@...hat.com>,
Shuah Khan <shuahkh@....samsung.com>
Subject: Re: [RFC][PATCH 0/4] Fixes for leapsecond expiring early ABS_TIME
CLOCK_REALTIME timers
On Mon, Jun 1, 2015 at 1:18 PM, Daniel Bristot de Oliveira
<bristot@...hat.com> wrote:
>
>
> Il 29/05/2015 17:24, John Stultz ha scritto:
>> Thus this patch series tries to address this isssue, including
>> extending the leap-a-day test to catch this problem, as well
>> as other relevant fixups I found while working on the code.
>>
>> This series has only had limited testing, so I wanted to send
>> it out for initial review and comment. Folks can grab this tree
>> via git for testing here:
>> https://git.linaro.org/people/john.stultz/linux.git dev/early-leap-timer
>
> John,
>
> I saw two failures while testing the patched kernel
> using the patched leap-a-day.
>
> On both cases the leap second was not inserted, and
> then the timer fired at the second edge (as expected?).
>
> Here is the output of both leap-a-day and dmesg for
> both errors:
>
> ===== Error 1 =====
> [root@...tro timers]# ./leap-a-day -s
> [...many lines...]
> Setting time to Wed Sep 9 20:59:50 2015
> Scheduling leap second for Wed Sep 9 21:00:00 2015
> Setting timer for Wed Sep 9 21:00:00 2015
> Wed Sep 9 20:59:57 2015 + 147 us (0) TIME_INS
> Wed Sep 9 20:59:57 2015 + 500352 us (0) TIME_INS
> Wed Sep 9 20:59:58 2015 + 558 us (0) TIME_INS
> Wed Sep 9 20:59:58 2015 + 500767 us (0) TIME_INS
> Wed Sep 9 20:59:59 2015 + 975 us (0) TIME_INS
> Wed Sep 9 20:59:59 2015 + 501181 us (0) TIME_INS
> Wed Sep 9 20:59:59 2015 + 1442 us (1) TIME_OOP
> Wed Sep 9 20:59:59 2015 + 501670 us (1) TIME_OOP
> Wed Sep 9 21:00:00 2015 + 110 us (1) TIME_WAIT - TIMER FIRED
> Wed Sep 9 21:00:00 2015 + 179 us (1) TIME_WAIT
> Wed Sep 9 21:00:00 2015 + 500340 us (1) TIME_WAIT
> Wed Sep 9 21:00:01 2015 + 548 us (1) TIME_WAIT
> Wed Sep 9 21:00:01 2015 + 500768 us (1) TIME_WAIT
> Wed Sep 9 21:00:02 2015 + 976 us (1) TIME_WAIT
> Leap complete
>
> Setting time to Thu Sep 10 20:59:50 2015
> Scheduling leap second for Thu Sep 10 21:00:00 2015
> Setting timer for Thu Sep 10 21:00:00 2015
> Thu Sep 10 20:59:57 2015 + 209 us (1) TIME_DEL
> Thu Sep 10 20:59:57 2015 + 500410 us (1) TIME_DEL
> Thu Sep 10 20:59:58 2015 + 646 us (1) TIME_DEL
> Thu Sep 10 20:59:58 2015 + 500881 us (1) TIME_DEL
> Thu Sep 10 21:00:00 2015 + 1182 us (0) TIME_WAIT - TIMER FIRED
> Thu Sep 10 21:00:00 2015 + 1283 us (0) TIME_WAIT
> Thu Sep 10 21:00:00 2015 + 501475 us (0) TIME_WAIT
> Thu Sep 10 21:00:01 2015 + 1654 us (0) TIME_WAIT
> Thu Sep 10 21:00:01 2015 + 501856 us (0) TIME_WAIT
> Thu Sep 10 21:00:02 2015 + 2032 us (0) TIME_WAIT
> Leap complete
>
> Setting time to Fri Sep 11 20:59:50 2015
> Scheduling leap second for Fri Sep 11 21:00:00 2015
> Setting timer for Fri Sep 11 21:00:00 2015
> Fri Sep 11 20:59:57 2015 + 139 us (0) TIME_INS
> Fri Sep 11 20:59:57 2015 + 500347 us (0) TIME_INS
> Fri Sep 11 20:59:58 2015 + 527 us (0) TIME_INS
> Fri Sep 11 20:59:58 2015 + 500751 us (0) TIME_INS
> Fri Sep 11 20:59:59 2015 + 987 us (0) TIME_INS
> Fri Sep 11 20:59:59 2015 + 501203 us (0) TIME_INS
> Fri Sep 11 21:00:00 2015 + 100 us (0) TIME_INS - TIMER FIRED
> Error: Incorrect NTP state?
> Fri Sep 11 21:00:00 2015 + 173 us (0) TIME_INS
> Fri Sep 11 21:00:00 2015 + 500353 us (0) TIME_OK
> Fri Sep 11 21:00:01 2015 + 583 us (0) TIME_OK
> Fri Sep 11 21:00:01 2015 + 500799 us (0) TIME_OK
> Fri Sep 11 21:00:02 2015 + 1021 us (0) TIME_OK
> Leap complete
> Errors observed
>
> [root@...tro timers]# dmesg | tail
> [ 1451.279313] Clock: deleting leap second 23:59:59 UTC
> [ 1464.296724] Clock: inserting leap second 23:59:60 UTC
> [ 1477.312373] Clock: deleting leap second 23:59:59 UTC
> [ 1490.329740] Clock: inserting leap second 23:59:60 UTC
> [ 1503.345402] Clock: deleting leap second 23:59:59 UTC
> [ 1516.362841] Clock: inserting leap second 23:59:60 UTC
> [ 1529.378466] Clock: deleting leap second 23:59:59 UTC
> [ 1542.395826] Clock: inserting leap second 23:59:60 UTC
> [ 1555.411551] Clock: deleting leap second 23:59:59 UTC
> [ 1697.998312] Adjusting tsc more than 11% (5677670 vs 7466007) <-- ???
> ---> did not insert the leap second <---
> ## did not insert the leap second
>
> ===== Error 2 =====
> [root@...tro timers]# ./leap-a-day -s
> [...many lines...]
> Setting time to Wed Aug 19 20:59:50 2015
> Scheduling leap second for Wed Aug 19 21:00:00 2015
> Setting timer for Wed Aug 19 21:00:00 2015
> Something cleared STA_INS/STA_DEL, setting it again.
> Wed Aug 19 20:59:57 2015 + 181 us (0) TIME_OK
> Wed Aug 19 20:59:57 2015 + 500357 us (0) TIME_INS
> Wed Aug 19 20:59:58 2015 + 559 us (0) TIME_INS
> Wed Aug 19 20:59:58 2015 + 500761 us (0) TIME_INS
> Wed Aug 19 20:59:59 2015 + 967 us (0) TIME_INS
> Wed Aug 19 20:59:59 2015 + 501177 us (0) TIME_INS
> Wed Aug 19 20:59:59 2015 + 1318 us (1) TIME_OOP
> Wed Aug 19 20:59:59 2015 + 501508 us (1) TIME_OOP
> Wed Aug 19 21:00:00 2015 + 99 us (1) TIME_WAIT - TIMER FIRED
> Wed Aug 19 21:00:00 2015 + 161 us (1) TIME_WAIT
> Wed Aug 19 21:00:00 2015 + 500320 us (1) TIME_WAIT
> Wed Aug 19 21:00:01 2015 + 523 us (1) TIME_WAIT
> Wed Aug 19 21:00:01 2015 + 500735 us (1) TIME_WAIT
> Wed Aug 19 21:00:02 2015 + 937 us (1) TIME_WAIT
> Leap complete
>
> Setting time to Thu Aug 20 20:59:50 2015
> Scheduling leap second for Thu Aug 20 21:00:00 2015
> Setting timer for Thu Aug 20 21:00:00 2015
> Thu Aug 20 20:59:57 2015 + 144 us (1) TIME_DEL
> Thu Aug 20 20:59:57 2015 + 500351 us (1) TIME_DEL
> Thu Aug 20 20:59:58 2015 + 552 us (1) TIME_DEL
> Thu Aug 20 20:59:58 2015 + 500752 us (1) TIME_DEL
> Thu Aug 20 21:00:00 2015 + 1021 us (0) TIME_WAIT - TIMER FIRED
> Thu Aug 20 21:00:00 2015 + 1096 us (0) TIME_WAIT
> Thu Aug 20 21:00:00 2015 + 501267 us (0) TIME_WAIT
> Thu Aug 20 21:00:01 2015 + 1470 us (0) TIME_WAIT
> Thu Aug 20 21:00:01 2015 + 501677 us (0) TIME_WAIT
> Thu Aug 20 21:00:02 2015 + 1886 us (0) TIME_WAIT
> Leap complete
>
> Setting time to Fri Aug 21 20:59:50 2015
> Scheduling leap second for Fri Aug 21 21:00:00 2015
> Setting timer for Fri Aug 21 21:00:00 2015
> Fri Aug 21 20:59:57 2015 + 153 us (0) TIME_INS
> Fri Aug 21 20:59:57 2015 + 500354 us (0) TIME_INS
> Fri Aug 21 20:59:58 2015 + 562 us (0) TIME_INS
> Fri Aug 21 20:59:58 2015 + 500815 us (0) TIME_INS
> Fri Aug 21 20:59:59 2015 + 1000 us (0) TIME_INS
> Fri Aug 21 20:59:59 2015 + 501207 us (0) TIME_INS
> Fri Aug 21 21:00:00 2015 + 109 us (0) TIME_INS - TIMER FIRED
> Error: Incorrect NTP state?
> Fri Aug 21 21:00:00 2015 + 173 us (0) TIME_INS
> Fri Aug 21 21:00:00 2015 + 500331 us (0) TIME_OK
> Fri Aug 21 21:00:01 2015 + 540 us (0) TIME_OK
> Fri Aug 21 21:00:01 2015 + 500791 us (0) TIME_OK
> Fri Aug 21 21:00:02 2015 + 1046 us (0) TIME_OK
> Leap complete
> Errors observed
>
> [root@...tro timers]# dmesg | tail
> [ 1283.857902] Clock: inserting leap second 23:59:60 UTC
> [ 1296.873600] Clock: deleting leap second 23:59:59 UTC
> [ 1309.891049] Clock: inserting leap second 23:59:60 UTC
> [ 1322.906709] Clock: deleting leap second 23:59:59 UTC
> [ 1335.924154] Clock: inserting leap second 23:59:60 UTC
> [ 1348.939824] Clock: deleting leap second 23:59:59 UTC
> [ 1361.957267] Clock: inserting leap second 23:59:60 UTC
> [ 1374.972919] Clock: deleting leap second 23:59:59 UTC
> [ 1387.989238] Clock: inserting leap second 23:59:60 UTC
> [ 1401.005877] Clock: deleting leap second 23:59:59 UTC
> ---> did not insert the leap second <---
>
> Both cases occurred in the same physical machine.
> AFAICS, it does not occur in the unpatched
> kernel/leap-a-day in the same machine.
Hrm. So did you happen to have ntpd running in the background during this test?
I know Prarit saw something very similar when he left ntpd running
during the test. I'd suspect it was due to ntpd changing the ntpd
state and possibly trying to stear the clock, however I've not seen
such behavior yet leaving ntpd running, and from your log it seems
like it would have to hit at a very specific window to trigger what
you're seeing.
thanks
-john
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
Powered by blists - more mailing lists