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

Mark C. Stephens marks at non-stop.com.au
Wed Feb 8 10:39:58 UTC 2012


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?
------------------------------------------------------------------------------------------------------------------------
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

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

-----Original Message-----
From: Dave Hart [mailto:hart at ntp.org]
Sent: Wednesday, 8 February 2012 7:40 PM
To: Mark C. Stephens
Cc: questions at lists.ntp.org
Subject: Re: No PPSAPI WinNT with NMEA flag1 1 ntpd 4.2.7p238-o

On Tue, Feb 7, 2012 at 01:11, Mark C. Stephens <marks at non-stop.com.au> wrote:
> ntpq> peer
>     remote           refid      st t when poll reach   delay   offset
> jitter
> ======================================================================
> ========
> *GPS_NMEA(1)     .GPS.            0 l    -   16  377    0.000   -0.145
> 0.006
> +ntp             .GPS.            1 s   44   64  376    0.285    0.624
> +0.051
>
> ntpq> rv 28263
> associd=28263 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=d2daf4bf.814fa2d5  Tue, Feb  7 2012 11:54:23.505,
> rec=d2daf4c0.1efe3f37  Tue, Feb  7 2012 11:54:24.121, reach=377,
> unreach=0, hmode=3, pmode=4, hpoll=4, ppoll=4, headway=0, flash=00 ok,
> keyid=0, ttl=159, offset=-0.124, delay=0.000, dispersion=0.233,
> jitter=0.006, filtdelay=     0.00    0.00    0.00    0.00    0.00
> 0.00    0.00    0.00, filtoffset=   -0.12   -0.13   -0.13   -0.13
> -0.13   -0.13   -0.13   -0.13, filtdisp=      0.00    0.24    0.48
> 0.72    0.96    1.20    1.44    1.68
> ntpq> cv 28263
> associd=28263 status=0011 1 event, clk_no_reply, device="NMEA GPS
> Clock", timecode="$GPZDA,005440,07,02,2012,+00,00",
> poll=1732, noreply=1, badformat=0, baddata=0, fudgetime2=-495.000,
> stratum=0, refid=GPS, flags=1
>
> ppsapi in use:
>
> C:\Program Files\NTP\bin>ntpd.exe -n  -M -N -c "C:\Program Files\NTP\etc\ntp.conf"
>  7 Feb 11:57:06 ntpd[2748]: ntpd 4.2.7p238-o Dec 10 4:46:28.43
> (UTC-00:00) 2011  (1)
>  7 Feb 11:57:06 ntpd[2748]: Raised to realtime priority class
>  7 Feb 11:57:06 ntpd[2748]: MM timer resolution: 1..1000000 msec, set
> to 1 msec
>  7 Feb 11:57:06 ntpd[2748]: Performance counter frequency 1263.430 MHz
>  7 Feb 11:57:06 ntpd[2748]: Clock interrupt period 15.625 msec
> (startup slew 0.2 usec/period)
>  7 Feb 11:57:06 ntpd[2748]: Windows clock precision 15.625 msec, min.
> slew 6.400 ppm/s
>  7 Feb 11:57:06 ntpd[2748]: HZ 64.000 using 43 msec timer 23.256 Hz 64
> deep
>  7 Feb 11:57:08 ntpd[2748]: proto: precision = 0.800 usec
>  7 Feb 11:57:08 ntpd[2748]: Listen and drop on 0 v4wildcard
> 0.0.0.0:123
>  7 Feb 11:57:09 ntpd[2748]: Listen normally on 1 NIC1 192.168.5.8:123
>  7 Feb 11:57:09 ntpd[2748]: Listen normally on 2 MS TCP Loopback
> interface 127.0.0.1:123
>  7 Feb 11:57:09 ntpd[2748]: peers refreshed
>  7 Feb 11:57:09 ntpd[2748]: GPS_NMEA(1) serial /dev/gps1 open at 9600
> bps
> time_pps_create(4) got winhandle 00000620
> getenv(PPSAPI_DLLS) gives
> c:\serialpps\serialpps-ppsapi-provider\x86\serialpps-ppsapi-provider.d
> ll loaded PPSAPI provider serialpps.sys, serial.sys with CD
> timestamping added caps 0x3011 provider 00B6F710 serialpps
> prov_time_pps_create(00000620) returned 0

FYI 0 == success here

>  7 Feb 11:57:09 ntpd[2748]: 0.0.0.0 c012 02 freq_set ntpd 12.854 PPM
>  7 Feb 11:57:09 ntpd[2748]: 0.0.0.0 c016 06 restart
>  7 Feb 11:57:09 ntpd[2748]: DNS ntp.non-stop.com.au -> 192.168.5.112
>  7 Feb 11:57:09 ntpd[2748]: Using user-mode PPS timestamp for
> GPS_NMEA(1)
>  7 Feb 11:57:18 ntpd[2748]: 0.0.0.0 c61c 0c clock_step +0.171031 s
>  7 Feb 11:57:34 ntpd[2748]: HZ 64.000 using 43 msec timer 23.256 Hz 64
> deep
>  7 Feb 11:57:36 ntpd[2748]: 0.0.0.0 c615 05 clock_sync
>  7 Feb 11:57:36 ntpd[2748]: 0.0.0.0 c618 08 no_sys_peer
>  7 Feb 11:58:24 ntpd[2748]: 0.0.0.0 0613 03 spike_detect -0.193186 s
>
> Config:
> keys "C:\Program Files\NTP\etc\ntp.key"
> trustedkey  <removed>
> requestkey <removed>
> controlkey <removed>
> 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  # NMEA serial port, 16 = 9600 baud, 8 = $GPZDA
> fudge 127.127.20.1 flag1 1 time2 -0.495 peer ntp.non-stop.com.au #
> Aussie time servers <removed> <removed> <removed> <removed> logconfig
> =clockevents +syncevents +sysevents +clockstatus +syncstatus
> +sysstatus +clockinfo +syncinfo +sysinfo +clockall +syncall +sysall
> enable stats statsdir D:\ntp\stats statistics loopstats peerstats
> clockstats

I'm baffled by the lack of 'o' for the PPS peer in ntpq output.  You might double-check ntpq --version to be sure you're using a recent one.  I think using a sufficiently old ntpq would result in seeing * not o.

> Dave, does compiling in debug code affect performance and accuracy?

Not much.  In general, it means a bunch of code like this is compiled out:

#ifdef DEBUG
    if (debug >= X)
        printf("some trace output\n");
#endif DEBUG

which is sometimes written in the source as the functionally equivalent but briefer

    /* in ntpd, which defines global debug only #ifdef DEBUG */
    DPRINTF(X, ("some trace output\n"));
    /* or, in libntp and utils, which always have the global debug */
    TRACE(X, ("some trace output\n"));

On Windows, the debug builds also use a debug C runtime which is marginally slower due to extra checks which will do things like check if a file descriptor passed to close() is already closed and trigger a breakpoint (which does nothing if no debugger is attached) or popup assertion dialog.

The reason it doesn't make much difference is ntpd uses so little CPU either way when debug == 0, that is lacking -D or -d.

Cheers,
Dave Hart




More information about the questions mailing list