2.6.19-rc2 and very unstable NTP

2.6.19-rc2 and very unstable NTP

[linux]

There have been a bunch of changes to timekeeping since 2.6.17, and I've
noticed that, with 2.6.19-rc2 + linuxpps, I'm getting some impressively
unstable oscillations in the local time.  +/- 350 us, when, given a
good quality local PPS source, it should be wiggling +/- a few us.
And the shape of the curves is not "wander" but "overcorrecting wildly".

It's sort of series of exponential decay curves, but each one overshoots
by 100%, and then before it fully flattens out, starts surging in the
other direction.   (Actually, the overshoot amplitudes fluctuate
erratically, too.)  As best I can render it in ASCII art:


*                      *                      *
                    *                      *
                  *                      *
                 *                      *
 *              *       *              *

               *                      *
  *                      *
--------------*----------------------*-----------
   *                      *

    *        *             *        *
     *                      *
      *                      *
        *                      *
           *                      *

600-700 us p-p, with 2200-2400 s per full cycle.

It looks like ajtimex() isn't doing what NTP is expecting,
leading to loop instability.


I'm going to git bisect this, although it's a bit time-consuming
waiting to see if things will settle own cleanly after each reboot.
And some of the patches have been anything but one-liners, so
that's not necessarily a direct pointer to the problem.

I know there have been a number of reports of ntp timekeeping
problems with 2.6.18.  Has there been any progress already?

(Local system: AMD64 uniprocessor, 2.6.19-rc2+linuxpps kernel,
NTP 4.2.2, Acutime 2000 GPS clock + PPS input.)

Re: 2.6.19-rc2 and very unstable NTP

[Roman Zippel]

Hi,

On Thu, 26 Oct 2006, linux@horizon.com wrote:

> There have been a bunch of changes to timekeeping since 2.6.17, and I've
> noticed that, with 2.6.19-rc2 + linuxpps,

Please specify "+ linuxpps".

bye, Roman

Re: 2.6.19-rc2 and very unstable NTP

[linux]

> Please specify "+ linuxpps".

http://gitweb.enneenne.com/?p=linuxpps;a=summary
http://wiki.enneenne.com/index.php/LinuxPPS_support

It's a PPS-input timestamping driver, touching drivers/serial/8250.c
and the like.  No contact with kernel timekeeping code, other than
calling it to obtain the timestamps.

I can send you NTP logs if you like; I just thought they were a bit
bulky for linux-kernel.

I don't think its use of netlink is entirely appropriate, but it works
well enough.

Re: 2.6.19-rc2 and very unstable NTP

[Roman Zippel]

Hi,

On Thu, 26 Oct 2006, linux@horizon.com wrote:

> > Please specify "+ linuxpps".
> 
> http://gitweb.enneenne.com/?p=linuxpps;a=summary
> http://wiki.enneenne.com/index.php/LinuxPPS_support
> 
> It's a PPS-input timestamping driver, touching drivers/serial/8250.c
> and the like.  No contact with kernel timekeeping code, other than
> calling it to obtain the timestamps.

Did you ask the author? It would really help to have more specific 
information here, e.g. what kernel interfaces are actually used in this 
configuration.

bye, Roman

Re: 2.6.19-rc2 and very unstable NTP

[linux]

First of all, nobody get too excited, yet.  I'm seeing an odd divergence
between the offset recorded in ntp's peerstats file (the log of the
measured time differences between each clock source) and the offset in
the loopstats file (the consensus value it uses to control the local
clock oscillator) that I need to investigate first.

> Did you ask the author? It would really help to have more specific 
> information here, e.g. what kernel interfaces are actually used in this 
> configuration.

Er... I thought I *was* asking the authors of the Linux kernel/time*
code.

If you're deeply suspiscious of a simple device driver, with publicly
available code, that adds timestamping to the handling of DCD changed
events from the serial ports, and exports those timestamps to user space,
I can remove it.  The Acutime 2000 can timestamp pulses sent to it
(via the RTS line), so I can get sub-microsecond time measurements anyway.

Having PPS as well was just a nice redundancy feature.

But here's the diffstat, with newly created files marked with a leading "+".
 drivers/Kconfig              |    2 +
 drivers/Makefile             |    1 +
+drivers/pps/Kconfig          |   43 ++++
+drivers/pps/Makefile         |    7 +
+drivers/pps/clients/Kconfig  |   23 ++
+drivers/pps/clients/Makefile |    6 +
+drivers/pps/clients/ktimer.c |  107 +++++++++
+drivers/pps/kapi.c           |  172 ++++++++++++++
+drivers/pps/pps.c            |  385 +++++++++++++++++++++++++++++++
+drivers/pps/procfs.c         |  180 +++++++++++++++
 drivers/serial/8250.c        |   85 +++++++-
 include/linux/netlink.h      |    2 +-
+include/linux/pps.h          |   93 ++++++++
+include/linux/timepps.h      |  515 ++++++++++++++++++++++++++++++++++++++++++
 14 files changed, 1617 insertions(+), 4 deletions(-)

I *really* doubt it has any effect on the kernel timekeeping code.

Re: 2.6.19-rc2 and very unstable NTP

[Roman Zippel]

Hi,

On Thu, 26 Oct 2006, linux@horizon.com wrote:

> > Did you ask the author? It would really help to have more specific 
> > information here, e.g. what kernel interfaces are actually used in this 
> > configuration.
> 
> Er... I thought I *was* asking the authors of the Linux kernel/time*
> code.
> 
> If you're deeply suspiscious of a simple device driver, with publicly
> available code, that adds timestamping to the handling of DCD changed
> events from the serial ports, and exports those timestamps to user space,
> I can remove it.  The Acutime 2000 can timestamp pulses sent to it
> (via the RTS line), so I can get sub-microsecond time measurements anyway.

I don't have this hardware, so I can only guess and the less information I 
get the broader I have to guess. Sorry, but currently I don't have the 
time to go on such a broad hunt. Someone familiar with this code should a 
far easier time localizing the problem. It's not just kernel driver, there 
is also lot of code in user space which converts the data to time 
adjustments. There is also more than one way to adjust time, so I need 
more specific information about what is happening and what is expected to 
happen.

bye, Roman

Re: 2.6.19-rc2 and very unstable NTP

[john stultz]

On Thu, 2006-10-26 at 08:30 -0400, linux@horizon.com wrote:
> First of all, nobody get too excited, yet.  I'm seeing an odd divergence
> between the offset recorded in ntp's peerstats file (the log of the
> measured time differences between each clock source) and the offset in
> the loopstats file (the consensus value it uses to control the local
> clock oscillator) that I need to investigate first.

Ok, let us know if you find anything there.

> If you're deeply suspiscious of a simple device driver, with publicly
> available code, that adds timestamping to the handling of DCD changed
> events from the serial ports, and exports those timestamps to user space,
> I can remove it.  The Acutime 2000 can timestamp pulses sent to it
> (via the RTS line), so I can get sub-microsecond time measurements anyway.

One of the recent changes was removing the in-kernel PPS code. This was
done because there were no in-kernel users of the interface (the only
ones being I believe in a variant of this LinuxPPS patch). While from
the diffstat below it doesn't look like the patch affects the
timekeeping code, it would be good to first reproduce the issue without
the patch.


> Having PPS as well was just a nice redundancy feature.
> 
> But here's the diffstat, with newly created files marked with a leading "+".
>  drivers/Kconfig              |    2 +
>  drivers/Makefile             |    1 +
> +drivers/pps/Kconfig          |   43 ++++
> +drivers/pps/Makefile         |    7 +
> +drivers/pps/clients/Kconfig  |   23 ++
> +drivers/pps/clients/Makefile |    6 +
> +drivers/pps/clients/ktimer.c |  107 +++++++++
> +drivers/pps/kapi.c           |  172 ++++++++++++++
> +drivers/pps/pps.c            |  385 +++++++++++++++++++++++++++++++
> +drivers/pps/procfs.c         |  180 +++++++++++++++
>  drivers/serial/8250.c        |   85 +++++++-
>  include/linux/netlink.h      |    2 +-
> +include/linux/pps.h          |   93 ++++++++
> +include/linux/timepps.h      |  515 ++++++++++++++++++++++++++++++++++++++++++
>  14 files changed, 1617 insertions(+), 4 deletions(-)
> 
> I *really* doubt it has any effect on the kernel timekeeping code.


Could you also send me a copy of your full dmesg? 

thanks
-john

Re: 2.6.19-rc2 and very unstable NTP

[Roman Zippel]

Hi,

On Thu, 26 Oct 2006, john stultz wrote:

> One of the recent changes was removing the in-kernel PPS code. This was
> done because there were no in-kernel users of the interface (the only
> ones being I believe in a variant of this LinuxPPS patch). While from
> the diffstat below it doesn't look like the patch affects the
> timekeeping code, it would be good to first reproduce the issue without
> the patch.

The recent patch by Jim Houston explains the misbehaviour. It seems the 
ntp daemon uses ADJ_OFFSET_SINGLESHOT for time adjustments, which is 
rather coarse-grained. By adding proper PPS support one should be able to 
get a more stable clock, but it's better done by someone who has the 
hardware to test this.

bye, Roman

Re: 2.6.19-rc2 and very unstable NTP

[linux]

>> One of the recent changes was removing the in-kernel PPS code. This was
>> done because there were no in-kernel users of the interface (the only
>> ones being I believe in a variant of this LinuxPPS patch). While from
>> the diffstat below it doesn't look like the patch affects the
>> timekeeping code, it would be good to first reproduce the issue without
>> the patch.

> The recent patch by Jim Houston explains the misbehaviour. It seems the 
> ntp daemon uses ADJ_OFFSET_SINGLESHOT for time adjustments, which is 
> rather coarse-grained. By adding proper PPS support one should be able to 
> get a more stable clock, but it's better done by someone who has the 
> hardware to test this.

Actually, I saw that, applied it, rebooted, and immediately reproduced
the problem.  So while clearly a bug, it doesn't appear to be the cause.

And given that, in the course of my experiments, I managed to reproduce
the problem with 2.6.17+linuxpps and 2.6.19-rc3 with the ntp.c patch,
but managed to make it go away with 2.6.19-rc3+linuxpps with the pps
source marked "noselect" (which results in identical kernel activity,
but doesn't actually use the returned timestamp for anything), I'm
looking pretty hard at ntpd right now.

My apologies for the false alarm.


In case anyone cares...

NTP measures the time offset between the local clock and a number of
configured time sources, or peers.  Then it uses an impressively elaborate
scheme for choosing a single system offset from those contributions.
This system offset is the input to the clock discipline control loop.

The basic NTP misbahavior is that the offsets reported in the peerstats
file are diverging from the offsets in the loopstats file.  The loopstats
offsets trace a nice exponential decay toward zero, but the peerstats
proceed at a different rate, overshooting badly, until something notices
and there's a big correction, and things swing the other way.

Trying to draw it in ASCII art, the o points are from peerstats, and
the x points are from loopstats, and the *s are where they coincide:

*                     *                     *
                   o                     o   
 x               o     x               o     
                o                     o      
 ox            o       ox            o       
   x                     x
     x        o            x        o        
__o____ x_x_____________o____ x_x____________
             o     x x             o     x x 
   o            x        o            x      
              x                     x
    o       ox            o       ox         
     o                     o                 
      o     x               o     x          
        o                     o              
           *                     *           

Amplitude about +/- 300 us, half-period about 1100-1200 s, but
rather chaotic.

There are only three peers, which all agree very tightly (GPS input,
PPS input, and a LAN peer which has a GPS clock itself), so I don't see
how a properly functioning ntpd can somehow choose among the three and
get the wrong number like this.  Regardless of what adjtimex() does.

Re: 2.6.19-rc2 and very unstable NTP

[Roman Zippel]

Hi,

On Fri, 27 Oct 2006, linux@horizon.com wrote:

> And given that, in the course of my experiments, I managed to reproduce
> the problem with 2.6.17+linuxpps and 2.6.19-rc3 with the ntp.c patch,
> but managed to make it go away with 2.6.19-rc3+linuxpps with the pps
> source marked "noselect" (which results in identical kernel activity,
> but doesn't actually use the returned timestamp for anything), I'm
> looking pretty hard at ntpd right now.

To analyze the kernel behaviour I would at least need the information fed 
to the kernel, e.g. by tracing the ntp daemon via "TZ=utc strace -f -tt 
-e trace=adjtimex -o ntpd.trace ..." and the ntp peer logs of same time 
period. Kernel boot messages and config might help as well.

bye, Roman

Re: 2.6.19-rc2 and very unstable NTP

[linux]

> To analyze the kernel behaviour I would at least need the information fed 
> to the kernel, e.g. by tracing the ntp daemon via "TZ=utc strace -f -tt 
> -e trace=adjtimex -o ntpd.trace ..." and the ntp peer logs of same time 
> period. Kernel boot messages and config might help as well.

Actually, I just found it!  It's kind of a combination bug.

I had hacked NTP_MINPOLL to 2 in the ntpd source, and was using that
value on the pps source.  But ntpd would copy that value, minus 4,
into ntv.constant (and set ADJ_TIMECONST), and adjtimex() would complain
and return EINVAL.

It wouldn't accept the passed-in values, but would still fill in the
structure with the current values.

But ntpd didn't notice or log this error, and would log the *returned*
consstant.  Which was oddly dissociated from the expected one.

The failure to check the return code is an ntpd bug.


Now, in the kernel, I wonder what the allowed range should properly be.

I notice that on the input side, you have
	time_constant = min(txc->constant + 4, (long)MAXTC);
but on the output side, it's
	txc->constant      = time_constant;

This is clearly inconsistent and wrong, but which side should be fixed
is an interesting question I haven't got an answer to yet.

For now, I've just hacked the kernel to allow values of time_constant
down to 0 (txc->constant >= -4), as nothing will break with that
value.  (The only complicated one is ntp.c:296, and SHIFT_PLL is 4,
while SHIFT_NSEC is 12, so it all works.)

(Also, is MAXTC high enough for ntpv4?  I think it's in "-4" space,
so it should be time_constant = min(txc->constant, (long)MAXTC) + 4;)


That was an interesting piece of debugging... I was all over the map
before finding it.  And your suggestion of "strace -e adjtimex" was
indeed exactly what found it in the end.

So thanks!