[ntp:questions] No PPSAPI WinNT with NMEA flag1 1 (was ntpd 4.2.7p238-o) now ntpd 4.2.7p253-o

Dave Hart hart at ntp.org
Wed Feb 8 19:46:52 UTC 2012


On Wed, Feb 8, 2012 at 10:58, Mark C. Stephens <marks at non-stop.com.au> wrote:
> Going to have to make a script that collects all of this, I left the peer out:
>
> ntpq> peer
>     remote           refid      st t when poll reach   delay   offset  jitter
> ==============================================================================
> *GPS_NMEA(1)     .GPS.            0 l   15   16  377    0.000    2.821   0.099
> +ntp             .GPS.            1 s   41   64  376    0.129  -11.265   0.405
> -<removed> .ATOM.           1 u   17   64  377   39.607   -7.085   1.650
> -<removed> 210.9.192.50     2 u   18   64  377   60.035  -32.563  38.523
> +<removed> .ATOM.           1 u   19   64  377   29.725   -6.104   0.331
> ntpq>
>
>
> -----Original Message-----
> From: Mark C. Stephens
> Sent: Wednesday, 8 February 2012 9:40 PM
> To: 'Dave Hart'
> Cc: questions at lists.ntp.org
> Subject: RE: No PPSAPI WinNT with NMEA flag1 1 (was ntpd 4.2.7p238-o) now ntpd 4.2.7p253-o
>
> Hello Mate,
>
>
> Connected to your ftp site (thank you) and updated to ntpd 4.2.7p253-o
>
> Here is -D2 out:
>
> C:\Program Files\NTP\bin>ntpd-d.exe -n -D 2 -M -N -c "C:\Program Files\NTP\etc\ntp.conf" -l D:\ntp\ntpd.log attempting to open log D:\ntp\ntpd.log
>  8 Feb 21:20:43 ntpd-d[4620]: ntpd 4.2.7p253-o Jan 26 7:02:17.87 (UTC-00:00) 2012  (1)
>  8 Feb 21:20:43 ntpd-d[4620]: Raised to realtime priority class
>  8 Feb 21:20:43 ntpd-d[4620]: MM timer resolution: 1..1000000 msec, set to 1 msec
>  8 Feb 21:20:43 ntpd-d[4620]: Performance counter frequency 1263.430 MHz
>  8 Feb 21:20:43 ntpd-d[4620]: Clock interrupt period 15.625 msec (startup slew 0.9 usec/period)
>  8 Feb 21:20:43 ntpd-d[4620]: Windows clock precision 15.626 msec, min. slew 6.400 ppm/s Wiring to processor 2 (0 means all) affinity mask 2
>  8 Feb 21:20:43 ntpd-d[4620]: HZ 64.000 using 43 msec timer 23.256 Hz 64 deep
>  8 Feb 21:20:46 ntpd-d[4620]: set_process_priority: Attempt to set priority: priority_done is <0>
>  8 Feb 21:20:46 ntpd-d[4620]: proto: precision = 1.900 usec (-19) Finished Parsing!!
> create_sockets(123)
>  8 Feb 21:20:46 ntpd-d[4620]: Listen and drop on 0 v4wildcard 0.0.0.0:123 created interface #0: fd=1820, bfd=-1, name=v4wildcard, flags=0x89, ifindex=0, sin=0.0.0.0, bcast=0.0.0.0, mask=255.255.255.255, Disabled:
> create_interface(192.168.5.8#123)
>  8 Feb 21:20:46 ntpd-d[4620]: Listen normally on 1 NIC1 192.168.5.8:123
> restrict: op 1 addr 192.168.5.8 mask 255.255.255.255 mflags 00003000 flags 00000001 created interface #1: fd=1588, bfd=-1, name=NIC1, flags=0x19, ifindex=0, sin=192.168.5.8, bcast=192.168.5.255, mask=255.255.255.0, Enabled:
> create_interface(127.0.0.1#123)
>  8 Feb 21:20:46 ntpd-d[4620]: Listen normally on 2 MS TCP Loopback interface 127.0.0.1:123
> restrict: op 1 addr 127.0.0.1 mask 255.255.255.255 mflags 00003000 flags 00000001 created interface #2: fd=1576, bfd=-1, name=MS TCP Loopback interface, flags=0x15, ifindex=0, sin=127.0.0.1, mask=255.255.255.255, Enabled:
>  8 Feb 21:20:46 ntpd-d[4620]: peers refreshed
> create_sockets: Total interfaces = 3
> auth_setkey: key 1 type 4 len 7 66726f646f3132
> auth_setkey: key 100 type 4 len 7 66726f646f3132
> auth_setkey: key 101 type 4 len 7 66726f646f3132
> proto_config: code 11 value 1 dvalue 0.000000
> loop_config: item 10 freq 13.017000
> findexistingpeer_addr(127.127.20.1:123, NULL, 3, 0x1)
> key_expire: at 0 associd 38332
> peer_clear: at 0 next 1 associd 38332 refid INIT common_serial_open given /dev/gps1 common_serial_open skipped to ending digits leaving 1 windows device \\.\COM1
>  8 Feb 21:20:46 ntpd-d[4620]: GPS_NMEA(1) serial /dev/gps1 open at 9600 bps event at 0 GPS_NMEA(1) 8011 81 mobilize assoc 38332
> newpeer: 127.0.0.1->127.127.20.1 mode 3 vers 4 poll 4 4 flags 0x9 0x1 ttl 24 key 00000000 blocking_getaddrinfo given node ntp.non-stop.com.au serv ntp fam 0 flags 0 getnetnum given 127.127.20.1, got 127.127.20.1 findexistingpeer_addr(127.127.20.1:123, NULL, -1, 0x0) blocking_getaddrinfo given node <removed>serv ntp fam 0 flags 0
> time_pps_create(5) got winhandle 00000620 blocking_getaddrinfo given node <removed> serv ntp fam 0 flags 0
> getenv(PPSAPI_DLLS) gives c:\serialpps\serialpps-ppsapi-provider\x86\serialpps-ppsapi-provider.dll
> blocking_getaddrinfo given node <removed> serv ntp fam 0 flags 0 loaded PPSAPI provider serialpps.sys, serial.sys with CD timestamping added caps 0x3011 provider 00C04948 serialpps prov_time_pps_create(00000620) returned 0
> loop_config: item 1 freq 0.000000
>  8 Feb 21:20:46 ntpd-d[4620]: 0.0.0.0 c012 02 freq_set ntpd 13.017 PPM event at 0 0.0.0.0 c012 02 freq_set ntpd 13.017 PPM
> local_clock: mu 0 state 2 poll 3 count 0
>  8 Feb 21:20:46 ntpd-d[4620]: 0.0.0.0 c016 06 restart event at 0 0.0.0.0 c016 06 restart
> SetSystemTimeAdjustment(+2)
> refclock_transmit: at 1 127.127.20.1
> event at 1 GPS_NMEA(1) 802b 8b clock_event clk_no_reply
> poll_update: at 1 127.127.20.1 poll 4 burst 0 retry 0 head 0 early 2 next 16
> auth_agekeys: at 1 keys 3 expired 0
> timer: interface update
> peer_name_resolved(ntp.non-stop.com.au) rescode 0
>  8 Feb 21:20:46 ntpd-d[4620]: DNS ntp.non-stop.com.au -> 192.168.5.112 findexistingpeer_addr(192.168.5.112:123, NULL, 1, 0x1)
> key_expire: at 1 associd 38333
> peer_clear: at 1 next 6 associd 38333 refid INIT event at 1 192.168.5.112 8011 81 mobilize assoc 38333
> newpeer: 192.168.5.8->192.168.5.112 mode 1 vers 4 poll 6 10 flags 0x1 0x1 ttl 0 key 00000000
> peer_name_resolved(<removed>) rescode 0
>  8 Feb 21:20:46 ntpd-d[4620]: DNS <removed>-> <removed> findexistingpeer_addr(<removed>:123, NULL, 3, 0x1)
> key_expire: at 1 associd 38334
> peer_clear: at 1 next 6 associd 38334 refid INIT event at 1 <removed> 8011 81 mobilize assoc 38334
> newpeer: 192.168.5.8-><removed> mode 3 vers 4 poll 6 10 flags 0x1 0x1 ttl 0 key 00000000
> peer_name_resolved(<removed>) rescode 0
>  8 Feb 21:20:46 ntpd-d[4620]: DNS <removed> -> <removed> findexistingpeer_addr(<removed>:123, NULL, 3, 0x1)
> key_expire: at 1 associd 38335
> peer_clear: at 1 next 6 associd 38335 refid INIT event at 1 <removed> 8011 81 mobilize assoc 38335
> newpeer: 192.168.5.8-><removed> mode 3 vers 4 poll 6 10 flags 0x1 0x1 ttl 0 key 00000000
> peer_name_resolved(<removed>) rescode 0
>  8 Feb 21:20:46 ntpd-d[4620]: DNS <removed> -> <removed> findexistingpeer_addr(<removed>:123, NULL, 3, 0x1)
> key_expire: at 1 associd 38336
> peer_clear: at 1 next 6 associd 38336 refid INIT event at 1 <removed> 8011 81 mobilize assoc 38336
> newpeer: 192.168.5.8-><removed> mode 3 vers 4 poll 6 10 flags 0x1 0x1 ttl 0 key 00000000 Received 12 bytes fd 1576 in buffer 00BFDAA8 from 127.0.0.1
> receive: at 1 127.0.0.1<-127.0.0.1 flags 15 restrict 000 sendpkt(1576, dst=127.0.0.1, src=127.0.0.1, ttl=-6, len=368) Received 12 bytes fd 1576 in buffer 00BFC938 from 127.0.0.1
> receive: at 1 127.0.0.1<-127.0.0.1 flags 15 restrict 000 sendpkt(1576, dst=127.0.0.1, src=127.0.0.1, ttl=-6, len=32) Received 12 bytes fd 1576 in buffer 00BFDAA8 from 127.0.0.1
> receive: at 1 127.0.0.1<-127.0.0.1 flags 15 restrict 000 sendpkt(1576, dst=127.0.0.1, src=127.0.0.1, ttl=-6, len=428) sendpkt(1576, dst=127.0.0.1, src=127.0.0.1, ttl=-6, len=152) Received 12 bytes fd 1576 in buffer 00BFC938 from 127.0.0.1
> receive: at 1 127.0.0.1<-127.0.0.1 flags 15 restrict 000 sendpkt(1576, dst=127.0.0.1, src=127.0.0.1, ttl=-6, len=428) sendpkt(1576, dst=127.0.0.1, src=127.0.0.1, ttl=-6, len=152) Received 12 bytes fd 1576 in buffer 00BFDAA8 from 127.0.0.1
> receive: at 1 127.0.0.1<-127.0.0.1 flags 15 restrict 000 sendpkt(1576, dst=127.0.0.1, src=127.0.0.1, ttl=-6, len=428) sendpkt(1576, dst=127.0.0.1, src=127.0.0.1, ttl=-6, len=152) Received 12 bytes fd 1576 in buffer 00BFC938 from 127.0.0.1
> receive: at 1 127.0.0.1<-127.0.0.1 flags 15 restrict 000 sendpkt(1576, dst=127.0.0.1, src=127.0.0.1, ttl=-6, len=428) sendpkt(1576, dst=127.0.0.1, src=127.0.0.1, ttl=-6, len=152) Received 12 bytes fd 1576 in buffer 00BFDAA8 from 127.0.0.1
> receive: at 1 127.0.0.1<-127.0.0.1 flags 15 restrict 000 sendpkt(1576, dst=127.0.0.1, src=127.0.0.1, ttl=-6, len=428) sendpkt(1576, dst=127.0.0.1, src=127.0.0.1, ttl=-6, len=152)
>  8 Feb 21:20:47 ntpd-d[4620]: Using user-mode PPS timestamp for GPS_NMEA(1)
> refclock_gtraw: fd 5 time 3537685247.531752 timecode 34
> $GPZDA,102048,08,02,2012,+00,00
>
> GPS_NMEA(1) gpsread: 31 '$GPZDA,102048,08,02,2012,+00,00'
> GPS_NMEA(1) processing 31 bytes, timecode '$GPZDA,102048,08,02,2012,+00,00'
> GPS_NMEA(1) effective timecode: 2012-02-08 10:20:48
> GPS_NMEA(1) using '$GPZDA,102048,08,02,2012,+00,00'
> GPS_NMEA(1) PPS_RELATE_NONE
>
> Does PPS_RELATE_NONE mean anything?

Yes, I think you've found the problem.  From refclock_nmea.c in 4.2.7p253:

/*
 * -------------------------------------------------------------------
 * refclock_ppsrelate(...) -- correlate with PPS edge
 *
 * This function is used to correlate a receive time stamp and a
 * reference time with a PPS edge time stamp. It applies the necessary
 * fudges (fudge1 for PPS, fudge2 for receive time) and then tries to
 * move the receive time stamp to the corresponding edge. This can warp
 * into future, if a transmission delay of more than 500ms is not
 * compensated with a corresponding fudge time2 value, because then the
 * next PPS edge is nearer than the last. (Similiar to what the PPS ATOM
 * driver does, but we deal with full time stamps here, not just phase
 * shift information.) Likewise, a negative fudge time2 value must be
 * used if the reference time stamp correlates with the *following* PPS
 * pulse.
 *
 * Note that the receive time fudge value only needs to move the receive
 * stamp near a PPS edge but that close proximity is not required;
 * +/-100ms precision should be enough. But since the fudge value will
 * probably also be used to compensate the transmission delay when no
 * PPS edge can be related to the time stamp, it's best to get it as
 * close as possible.
 *
 * It should also be noted that the typical use case is matching to the
 * preceeding edge, as most units relate their sentences to the current
 * second.
 *
 * The function returns PPS_RELATE_NONE (0) if no PPS edge correlation
 * can be fixed; PPS_RELATE_EDGE (1) when a PPS edge could be fixed, but
 * the distance to the reference time stamp is too big (exceeds
 * +/-400ms) and the ATOM driver PLL cannot be used to fix the phase;
 * and PPS_RELATE_PHASE (2) when the ATOM driver PLL code can be used.
 *
 * On output, the receive time stamp is replaced with the corresponding
 * PPS edge time if a fix could be made; the PPS fudge is updated to
 * reflect the proper fudge time to apply. (This implies that
 * 'refclock_process_offset()' must be used!)
 * -------------------------------------------------------------------
 */
#define PPS_RELATE_NONE	 0	/* no pps correlation possible	  */
#define PPS_RELATE_EDGE	 1	/* recv time fixed, no phase lock */
#define PPS_RELATE_PHASE 2	/* recv time fixed, phase lock ok */

Looking at the code that follows, I think the mention of 400ms should
be 450ms.  Basically, PPS_RELATE_NONE is saying the NMEA driver is
rejecting the PPS timestamp as it's more than 450ms away from the
end-of-sentence timestamp.

A wrinkle on Windows is the user-mode timestamp hack is replacing the
end-of-sentence timestamp for the first sentence received after each
PPS event with the user-mode PPS timestamp from watching the DCD line
transitions in ntpd's Windows serial port I/O code.  If your GPS
generates more than one sentence each second, only the first sentence
received after each PPS is so mangled.  As a result, unlike on
non-Windows systems, you should not need a large fudge time2 if you're
using the first sentence each cycle.  Changing or removing that fudge
time2 should allow you get PPS_RELATE_PHASE and hence the 'o' tally
code in the peers billboard.

> ------------------------------------------------------------------------------------------------------------------------
> ntpq> ass
>
> ind assid status  conf reach auth condition  last_event cnt ===========================================================
>  1 40800  964a   yes   yes  none  sys.peer    sys_peer  4
>  2 40801  9424   yes   yes  none candidate   reachable  2
>  3 40802  9424   yes   yes  none candidate   reachable  2
>  4 40803  9324   yes   yes  none   outlyer   reachable  2
>  5 40804  9324   yes   yes  none   outlyer   reachable  2
>
> ntpq> rv 40800
> associd=40800 status=964a conf, reach, sel_sys.peer, 4 events, sys_peer, srcadr=GPS_NMEA(1), srcport=123, dstadr=127.0.0.1, dstport=123, leap=00, stratum=0, precision=-9, rootdelay=0.000, rootdisp=0.000, refid=GPS,
> reftime=d2dcce2e.8376d162  Wed, Feb  8 2012 21:34:22.513,
> rec=d2dcce2e.dbab3538  Wed, Feb  8 2012 21:34:22.858, reach=377, unreach=0, hmode=3, pmode=4, hpoll=4, ppoll=4, headway=0, flash=00 ok, keyid=0, ttl=187, offset=0.417, delay=0.000, dispersion=0.236, jitter=0.269,
> filtdelay=     0.00    0.00    0.00    0.00    0.00    0.00    0.00    0.00,
> filtoffset=    0.42    0.36    0.24    0.20    0.16    0.10    0.07    0.04,
> filtdisp=      0.01    0.24    0.49    0.72    0.96    1.20    1.44    1.68
>
> ntpq> cv 40800
> associd=40800 status=0011 1 event, clk_no_reply, device="NMEA GPS Clock", timecode="$GPZDA,103452,08,02,2012,+00,00",
> poll=40, noreply=1, badformat=0, baddata=0, fudgetime2=-486.000, stratum=0, refid=GPS, flags=1
>
> ntpq> kern
> associd=0 status=0415 leap_none, sync_uhf_radio, 1 event, clock_sync,
> pll offset:            0
> pll frequency:         0
> maximum error:         0
> estimated error:       0
> pll time constant:     0
> precision:             0
> frequency tolerance:   0
> pps frequency:         0
> pps stability:         0
> pps jitter:            0
> calibration interval   0
> calibration cycles:    0
> jitter exceeded:       0
> stability exceeded:    0
> calibration errors:    0

The kerninfo on Windows will always be all zeroes -- there is no
kernel NTP loop discipline on Windows, it's always using the ntpd
daemon loop discipline.

>
> ntpd.conf:
>
> keys "C:\Program Files\NTP\etc\ntp.key"
> trustedkey 1 100 101
> requestkey 100
> controlkey 101
>
> # Use drift file
> driftfile "D:\NTP\ntp.drift"
>
> # enable calibrate
> #
> #server 127.127.22.1 minpoll 4 maxpoll 4 #fudge 127.127.22.1 time1 -0.525 flag3 1 server 127.127.20.1 mode 24 minpoll 4 maxpoll 4  # prefer # noselect fudge 127.127.20.1 flag1 1 time2 -0.486 peer ntp.non-stop.com.au # Aussie time servers <removed> <removed> <removed>
>
> #ignore_bigtimestep yes
> logconfig =clockevents +syncevents +sysevents +clockstatus +syncstatus +sysstatus +clockinfo +syncinfo +sysinfo +clockall +syncall +sysall enable stats statsdir D:\ntp\stats statistics loopstats peerstats clockstats

Good luck!

There seems to have been an explosion of mail to questions@ in the
last 10 hours or so.  I need to handle other chores for a while before
diving into any more responses.

Cheers,
Dave Hart


More information about the questions mailing list