Re[2]: NTPsec reports excessive jitter from GPSD/KPPS SHM

[Nick Burkitt]

Hi Gary.

Yes, I modified my driver to tell KPPS about the new "clear" interrupt. That's why KPPS now reports clear events. The code is below, for what it's worth.

The machines (I have five of them) have all been getting NTP time from Internet sources for the better part of a year, so their system clocks' drifts should be well characterized by now. 

NTPsec command line: 

/usr/local/sbin/ntpd -g -N -u ntp:ntp

While the ntpmon snapshot I included showed SHM(1) being used, sometimes ntpd likes SHM(1), and sometimes it doesn't. Right now it's giving SHM(1) the silent treatment. In a while, it might have a change of heart.

     remote           refid      st t when poll reach   delay   offset   jitter
 SHM(0)          .GPS.            0 l   29   64  377   0.0000  49.6561   2.9519
xSHM(1)          .PPS.            0 l   28   64  377   0.0000 -27.0924   7.5853

Yep, there it goes:

     remote           refid      st t when poll reach   delay   offset   jitter
 SHM(0)          .GPS.            0 l   50   64  377   0.0000  30.2184  16.2243
*SHM(1)          .PPS.            0 l   48   64  377   0.0000 -40.9404  13.4211

Here's a few minutes worth.

                               offset   jitter

01:36:37: UTC: 2020: *SHM(1) -10.7633   1.8668
01:36:42: UTC: 2020: *SHM(1) -11.3509   1.3202
01:37:47: UTC: 2020: *SHM(1) -11.8400   1.5121
01:38:46: UTC: 2020: *SHM(1) -11.8400   1.5121
01:39:51: UTC: 2020: *SHM(1) -11.9605   1.6094
01:40:50: UTC: 2020: *SHM(1) -12.5353   2.0366
01:41:49: UTC: 2020: xSHM(1) -14.5243   3.4161
01:42:00: UTC: 2020: xSHM(1) -17.0590   5.2023
01:42:59: UTC: 2020: *SHM(1) -17.0590   5.2023
01:43:04: UTC: 2020: *SHM(1) -29.6526  16.9138
01:44:09: UTC: 2020: *SHM(1) -28.8646  14.6121
01:45:13: UTC: 2020: *SHM(1) -26.2311  10.9424
01:46:18: UTC: 2020: *SHM(1) -22.3639   7.6043

01:49:40: UTC: 2020: *SHM(1) -17.7667   7.2290
01:50:41: UTC: 2020: *SHM(1) -16.1794   8.5299
01:51:41: UTC: 2020: *SHM(1) -14.6885   8.0622
01:52:42: UTC: 2020: *SHM(1) -14.0576   6.5393
01:53:42: UTC: 2020: *SHM(1) -14.0576   6.5393
01:54:42: UTC: 2020: *SHM(1) -12.7403   5.7526
01:55:43: UTC: 2020: *SHM(1) -12.1726   4.9322
01:56:43: UTC: 2020: *SHM(1)  -9.8137   5.8895
01:57:44: UTC: 2020: *SHM(1) -10.5865   4.1311
01:58:44: UTC: 2020: *SHM(1) -10.3007   3.3317
01:59:45: UTC: 2020: *SHM(1) -11.5909   1.8194
02:00:45: UTC: 2020: *SHM(1) -10.3201   1.8974
02:01:45: UTC: 2020: *SHM(1)  -6.2886   4.8932
02:02:46: UTC: 2020: *SHM(1) -11.0618   1.9716

02:10:54: UTC: 2020: *SHM(1) -48.9056  29.8773
02:11:55: UTC: 2020: *SHM(1) -37.3060  18.7964
02:12:55: UTC: 2020: *SHM(1) -32.7262  15.0994
02:13:56: UTC: 2020: xSHM(1) -32.7262  15.0994
02:14:56: UTC: 2020: *SHM(1) -29.6662  13.6276
02:15:56: UTC: 2020: *SHM(1) -32.0791  10.4186
02:16:57: UTC: 2020: *SHM(1) -28.4634  12.6528
02:17:57: UTC: 2020: *SHM(1) -23.3575  16.1535
02:18:58: UTC: 2020: *SHM(1) -21.5258  13.9039
02:19:58: UTC: 2020: *SHM(1) -21.3243   9.4552

Here's a snapshot of ntpmon from a another copy of the device that's been running for three days. This is using the assert-only KPPS driver, of course.

     remote           refid      st t when poll reach   delay   offset   jitter
 SHM(0)          .GPS.            0 l   59   64  377   0.0000  -2.3327   0.0396
xSHM(1)          .PPS.            0 l   21   64  377   0.0000 -133.573   3.4322

Revised KPPS driver code:

static irqreturn_t core100_pps_assert_handler( int irq, void* data )

{
    struct core100_pdev_drvdata* p_pdev_info = ( struct core100_pdev_drvdata* ) data;
    struct pps_event_time ts;
    pps_get_ts( &ts );
    pps_event( p_pdev_info->pps_source, &ts, PPS_CAPTUREASSERT, NULL );
    return IRQ_HANDLED;
}

static irqreturn_t core100_pps_clear_handler( int irq, void* data )
{
    struct core100_pdev_drvdata* p_pdev_info = ( struct core100_pdev_drvdata* ) data;
    struct pps_event_time ts;
    pps_get_ts( &ts );
    pps_event( p_pdev_info->pps_source, &ts, PPS_CAPTURECLEAR, NULL );
    return IRQ_HANDLED;
}

static int core100_register_pps( struct core100_pdev_drvdata* p_pdev_info )
{
    static struct pps_source_info core100_pps_info = {
        .name = "core100",
        .path = "",
        .mode = PPS_CAPTUREASSERT | PPS_OFFSETASSERT | PPS_CAPTURECLEAR | PPS_OFFSETCLEAR | PPS_ECHOASSERT | PPS_ECHOCLEAR | PPS_CANWAIT | PPS_TSFMT_TSPEC,
        .owner = THIS_MODULE,
    };
    int rv;

    rv = platform_get_irq( p_pdev_info->pdev, 0 );
    if ( ( rv < 0 ) && ( rv != -EPROBE_DEFER ) )
    {
        printk( KERN_ERR KBUILD_MODNAME ": %s(%s): platform_get_irq(%d) failed\n", __func__, p_pdev_info->name, 0 );
        return rv;
    }
    p_pdev_info->pps_assert_irq = rv;

    rv = platform_get_irq( p_pdev_info->pdev, 1 );
    if ( ( rv < 0 ) && ( rv != -EPROBE_DEFER ) )
    {
        printk( KERN_ERR KBUILD_MODNAME ": %s(%s): platform_get_irq(%d) failed\n", __func__, p_pdev_info->name, 1 );
        return rv;
    }
    p_pdev_info->pps_clear_irq = rv;

    p_pdev_info->pps_source = pps_register_source( &core100_pps_info, PPS_CAPTUREASSERT | PPS_OFFSETASSERT | PPS_CAPTURECLEAR | PPS_OFFSETCLEAR );
    if ( NULL == p_pdev_info->pps_source )
    {
        printk( KERN_ERR KBUILD_MODNAME ": %s(%s): pps_register_source() failed\n", __func__, p_pdev_info->name );
        return -ENOMEM;
    }
    rv = devm_request_irq( &p_pdev_info->pdev->dev, p_pdev_info->pps_assert_irq, core100_pps_assert_handler, IRQF_TRIGGER_RISING | IRQF_TIMER, p_pdev_info->name, p_pdev_info );
    if ( rv )
    {
        printk( KERN_ERR KBUILD_MODNAME ": %s(%s): devm_request_irq(%d) failed: %d\n", __func__, p_pdev_info->name, p_pdev_info->pps_clear_irq, rv );
        return rv;
    }
    rv = devm_request_irq( &p_pdev_info->pdev->dev, p_pdev_info->pps_clear_irq, core100_pps_clear_handler, IRQF_TRIGGER_RISING | IRQF_TIMER, p_pdev_info->name, p_pdev_info );
    if ( rv )
    {
        printk( KERN_ERR KBUILD_MODNAME ": %s(%s): devm_request_irq(%d) failed: %d\n", __func__, p_pdev_info->name, p_pdev_info->pps_clear_irq, rv );
        return rv;
    }
    return rv;
}

-Nick

------ Original Message ------

From: "Gary E. Miller" <address@hidden>

To: address@hidden

Sent: 3/5/2020 4:47:10 PM

Subject: Re: NTPsec reports excessive jitter from GPSD/KPPS SHM

Yo Nick!

 

On Fri, 06 Mar 2020 00:23:53 +0000

"Nick Burkitt" <address@hidden> wrote:

 

Yes, the u-blox PPS is 100 ms wide. We use the rising edge for other

purposes, so I've implemented a second interrupt for the falling edge

(Zynq GIC interrupts are rising edge/high level only). Now I'm

capturing both assert and clear. It doesn't seem to have made any

difference, though.

 

Really? It should have moved the offset of SHM(1) by 100 millisec!

Unless (see below).

 

Since you are not using the gpsd code for KPPS it is hard to know

what is going on. Did you change your code as well as adding clear?

Your code was only looking at assert.

 

root@MPM-4006:~# ppstest /dev/pps0

source 0 - assert 1583451764.950840664, sequence: 1111 - clear

1583451764.050612818, sequence: 1110

 

Yup, there is the 100 msec pulse width. It does appear that the assert

is the correct KPPS edge to use. And your system clock is right in the

middle. So looking at assert was the right thing as you had been doing.

 

Since you are not using the gpsd KPPS code, and you did not supply any

changes you made to your KPPS code, unclear, so far, what it happening.

 

=========================================================================

Here's cgps:

 

That did not survive email well. Also, your attempt to obfusacte your

lat/long failed: lat: 37.318070, Lon: -121.783261, AltHAE: 25.57

 

Looks like: 3222 Scotch Heather Ct, San Jose, CA 95148

 

All I needed was: 3D FIX.

 

Here's ntpmon:

 

remote refid st t when poll reach delay

offset jitter

SHM(0) .GPS. 0 l 17 64 377 0ns

48.263ms 14.602ms

*SHM(1) .PPS. 0 l 15 64 377 0ns

-26.60ms 16.084ms

 

Huh? Sure looks like SHM(1) is being used. Note the asterisk in column

one? No problem here. How long did you wait? It can take hours for

ntpd to pull your system clock into sync.

 

I should note that the numbers that NTPsec uses for offset and jitter

wander all over the map, from a low of ~2 ms to 50 or even > 100 ms.

 

NTPsec does not use offset or jitter, it calcualtes them.

 

You should expect that for up to several hours, even days. Especially

if the drift has never been previously calibrated, or the server has been

moved.

 

Where it's getting those numbers from is a mystery to me.

 

Easy, they are calculated from observations. The RFCs show how they

are calcualted.

 

It takes a LONG time for ntpd to pick the best time source, and then

to steer the system clock to it.

 

So, it looks good now, the only issue is your lack of patience. And

maybe you forgot -g on the ntpd command line.

 

RGDS

GARY

---------------------------------------------------------------------------

Gary E. Miller Rellim 109 NW Wilmington Ave., Suite E, Bend, OR 97703

address@hidden Tel:+1 541 382 8588

 

Veritas liberabit vos. -- Quid est veritas?

"If you can't measure it, you can't improve it." - Lord Kelvin