search

jclark / rpi-cm4-ptp-guide

Guide to using the hardware PTP support in the Raspberry Pi CM4
MIT License
85 stars 10 forks source link

Occasional bad, extra PPS pulses #5

Open jclark opened 2 years ago

jclark commented 2 years ago

I am seeing occasional (e.g. once every several days) extra PPS pulses, which cause ts2phc to perform some extreme adjustments. Here's an example, which is with a u-blox M8T with an outside, but ground-level antenna (so less than perfect sky-view).

Nov 13 16:38:42 wensleydale ts2phc: [104209.501] nmea sentence: GPRMC,093842.00,A,1343.91052,N,10038.68416,E,0.000,,131122,,,A,V
Nov 13 16:38:43 wensleydale ts2phc: [104210.488] nmea delay: 147943835 ns
Nov 13 16:38:43 wensleydale ts2phc: [104210.488] eth0 extts index 0 at 1668332359.999999995 corr 0 src 1668332360.987633605 diff -5
Nov 13 16:38:43 wensleydale ts2phc: [104210.488] eth0 master offset         -5 s2 freq  +13780
Nov 13 16:38:43 wensleydale ts2phc: [104210.504] nmea sentence: GPRMC,093843.00,A,1343.91052,N,10038.68416,E,0.000,,131122,,,A,V
Nov 13 16:38:44 wensleydale ts2phc: [104211.496] nmea delay: 150866287 ns
Nov 13 16:38:44 wensleydale ts2phc: [104211.496] eth0 extts index 0 at 1668332360.999999981 corr 0 src 1668332361.992675857 diff -19
Nov 13 16:38:44 wensleydale ts2phc: [104211.496] eth0 master offset        -19 s2 freq  +13765

Here it reads two nmea sentences without an intervening pulse

Nov 13 16:38:44 wensleydale ts2phc: [104211.504] nmea sentence: GPRMC,093844.00,A,1343.91052,N,10038.68416,E,0.000,,131122,,,A,V
Nov 13 16:38:45 wensleydale ts2phc: [104212.501] nmea sentence: GPRMC,093845.00,A,1343.91052,N,10038.68416,E,0.000,,131122,,,A,V
Nov 13 16:38:45 wensleydale ts2phc: [104212.504] nmea delay: 148658469 ns
Nov 13 16:38:45 wensleydale ts2phc: [104212.504] eth0 extts index 0 at 1668332361.999999998 corr 0 src 1668332362.2876398 diff -2
Nov 13 16:38:45 wensleydale ts2phc: [104212.504] eth0 master offset         -2 s2 freq  +13776
Nov 13 16:38:45 wensleydale ts2phc: [104213.008] nmea delay: 148658469 ns

This next pulse is is an extra, spurious pulse. I think 1668332362.43187178 is the PHC of the pulse. It's an extra one between the previous one, which is roughly 1668332362, and the next one, which is roughly 1668332363.

Nov 13 16:38:45 wensleydale ts2phc: [104213.008] eth0 extts index 0 at 1668332362.431871787 corr 0 src 1668332363.506861520 diff -568128213
Nov 13 16:38:45 wensleydale ts2phc: [104213.008] eth0 master offset -568128213 s2 freq -100000000
Nov 13 16:38:46 wensleydale ts2phc: [104213.505] nmea sentence: GPRMC,093846.00,A,1343.91052,N,10038.68416,E,0.000,,131122,,,A,V
Nov 13 16:38:46 wensleydale ts2phc: [104213.512] nmea delay: 152682848 ns
Nov 13 16:38:46 wensleydale ts2phc: [104213.512] eth0 extts index 0 at 1668332363.034413526 corr 0 src 1668332363.6911093 diff 34413526
Nov 13 16:38:46 wensleydale ts2phc: [104213.512] eth0 master offset   34413526 s2 freq +34427304
Nov 13 16:38:47 wensleydale ts2phc: [104214.504] nmea sentence: GPRMC,093847.00,A,1343.91052,N,10038.68416,E,0.000,,131122,,,A,V
Nov 13 16:38:47 wensleydale ts2phc: [104214.521] nmea delay: 151118484 ns
Nov 13 16:38:47 wensleydale ts2phc: [104214.521] eth0 extts index 0 at 1668332364.021504083 corr 0 src 1668332364.16857268 diff 21504083
Nov 13 16:38:47 wensleydale ts2phc: [104214.521] eth0 master offset   21504083 s2 freq +31841918
Nov 13 16:38:48 wensleydale ts2phc: [104215.502] nmea sentence: GPRMC,093848.00,A,1343.91052,N,10038.68416,E,0.000,,131122,,,A,V
Nov 13 16:38:48 wensleydale ts2phc: [104215.528] nmea delay: 149682950 ns
Nov 13 16:38:48 wensleydale ts2phc: [104215.528] eth0 extts index 0 at 1668332364.989240046 corr 0 src 1668332365.25860902 diff -10759954
Nov 13 16:38:48 wensleydale ts2phc: [104215.528] eth0 master offset  -10759954 s2 freq +6029106
Nov 13 16:38:49 wensleydale ts2phc: [104216.504] nmea sentence: GPRMC,093849.00,A,1343.91052,N,10038.68416,E,0.000,,131122,,,A,V
Nov 13 16:38:49 wensleydale ts2phc: [104216.536] nmea delay: 151196759 ns
Nov 13 16:38:49 wensleydale ts2phc: [104216.536] eth0 extts index 0 at 1668332365.978683997 corr 0 src 1668332366.32350224 diff -21316003
Nov 13 16:38:49 wensleydale ts2phc: [104216.536] eth0 master offset  -21316003 s2 freq -7754929
Nov 13 16:38:50 wensleydale ts2phc: [104217.504] nmea sentence: GPRMC,093850.00,A,1343.91052,N,10038.68416,E,0.000,,131122,,,A,V
Nov 13 16:38:50 wensleydale ts2phc: [104217.544] nmea delay: 151323978 ns
Nov 13 16:38:50 wensleydale ts2phc: [104217.544] eth0 extts index 0 at 1668332366.983917652 corr 0 src 1668332367.40235709 diff -16082348
Nov 13 16:38:50 wensleydale ts2phc: [104217.544] eth0 master offset  -16082348 s2 freq -8916075
Nov 13 16:38:51 wensleydale ts2phc: [104218.504] nmea sentence: GPRMC,093851.00,A,1343.91052,N,10038.68416,E,0.000,,131122,,,A,V
Nov 13 16:38:51 wensleydale ts2phc: [104218.552] nmea delay: 151517308 ns
Nov 13 16:38:51 wensleydale ts2phc: [104218.552] eth0 extts index 0 at 1668332367.992624769 corr 0 src 1668332368.48024659 diff -7375231
Nov 13 16:38:51 wensleydale ts2phc: [104218.552] eth0 master offset   -7375231 s2 freq -5033662
Nov 13 16:38:52 wensleydale ts2phc: [104219.502] nmea sentence: GPRMC,093852.00,A,1343.91052,N,10038.68416,E,0.000,,131122,,,A,V
Nov 13 16:38:52 wensleydale ts2phc: [104219.560] nmea delay: 148823090 ns
Nov 13 16:38:52 wensleydale ts2phc: [104219.560] eth0 extts index 0 at 1668332368.998448447 corr 0 src 1668332369.58759544 diff -1551553
Nov 13 16:38:52 wensleydale ts2phc: [104219.560] eth0 master offset   -1551553 s2 freq -1422554
Nov 13 16:38:53 wensleydale ts2phc: [104220.501] nmea sentence: GPRMC,093853.00,A,1343.91052,N,10038.68416,E,0.000,,131122,,,A,V
Nov 13 16:38:53 wensleydale ts2phc: [104220.568] nmea delay: 147817069 ns
Nov 13 16:38:53 wensleydale ts2phc: [104220.568] eth0 extts index 0 at 1668332370.000636084 corr 0 src 1668332370.67735419 diff 636084
Nov 13 16:38:53 wensleydale ts2phc: [104220.568] eth0 master offset     636084 s2 freq +299618
jclark commented 2 years ago

Questions here:

We can bpftrace and see whether the bad pulse happens at the same time as explicitly requesting a timestamp.

jclark commented 2 years ago

Here's another one:

Nov 16 12:39:14 wensleydale ts2phc: [349041.521] eth0 extts index 0 at 1668577190.999999988 corr 0 src 1668577191.18746814 diff -12
Nov 16 12:39:14 wensleydale ts2phc: [349041.521] eth0 master offset        -12 s2 freq  +13717
Nov 16 12:39:15 wensleydale ts2phc: [349042.501] nmea sentence: GPRMC,053915.00,A,1343.91052,N,10038.68416,E,0.000,,161122,,,A,V
Nov 16 12:39:15 wensleydale ts2phc: [349042.528] nmea delay: 148205941 ns
Nov 16 12:39:15 wensleydale ts2phc: [349042.529] eth0 extts index 0 at 1668577191.999999996 corr 0 src 1668577192.27544879 diff -4
Nov 16 12:39:15 wensleydale ts2phc: [349042.529] eth0 master offset         -4 s2 freq  +13721
Nov 16 12:39:16 wensleydale ts2phc: [349043.500] nmea sentence: GPRMC,053916.00,A,1343.91052,N,10038.68416,E,0.000,,161122,,,A,V
Nov 16 12:39:16 wensleydale ts2phc: [349043.536] nmea delay: 146878696 ns
Nov 16 12:39:16 wensleydale ts2phc: [349043.537] eth0 extts index 0 at 1668577192.999999980 corr 0 src 1668577193.36885194 diff -20
Nov 16 12:39:16 wensleydale ts2phc: [349043.537] eth0 master offset        -20 s2 freq  +13704
Nov 16 12:39:16 wensleydale ts2phc: [349044.292] nmea delay: 146878696 ns

This pulse is bad. It's an extra one. Previous one is roughly 1668577193. Next one is roughly 1668577194. This one is roughly 1668577193.75.

Nov 16 12:39:16 wensleydale ts2phc: [349044.293] eth0 extts index 0 at 1668577193.752813037 corr 0 src 1668577194.792838697 diff -247186963
Nov 16 12:39:16 wensleydale ts2phc: [349044.293] eth0 master offset -247186963 s2 freq -100000000
Nov 16 12:39:17 wensleydale ts2phc: [349044.501] nmea sentence: GPRMC,053917.00,A,1343.91052,N,10038.68416,E,0.000,,161122,,,A,V
Nov 16 12:39:17 wensleydale ts2phc: [349044.544] nmea delay: 148458442 ns
Nov 16 12:39:17 wensleydale ts2phc: [349044.545] eth0 extts index 0 at 1668577194.005987505 corr 0 src 1668577194.43304278 diff 5987505
Nov 16 12:39:17 wensleydale ts2phc: [349044.545] eth0 master offset    5987505 s2 freq +6001223
Nov 16 12:39:18 wensleydale ts2phc: [349045.500] nmea sentence: GPRMC,053918.00,A,1343.91052,N,10038.68416,E,0.000,,161122,,,A,V
Nov 16 12:39:18 wensleydale ts2phc: [349045.552] nmea delay: 147272812 ns
Nov 16 12:39:18 wensleydale ts2phc: [349045.553] eth0 extts index 0 at 1668577195.020366422 corr 0 src 1668577195.52504131 diff 20366422
Nov 16 12:39:18 wensleydale ts2phc: [349045.553] eth0 master offset   20366422 s2 freq +22176391
Nov 16 12:39:19 wensleydale ts2phc: [349046.500] nmea sentence: GPRMC,053919.00,A,1343.91052,N,10038.68416,E,0.000,,161122,,,A,V
Nov 16 12:39:19 wensleydale ts2phc: [349046.560] nmea delay: 147516834 ns
Nov 16 12:39:19 wensleydale ts2phc: [349046.561] eth0 extts index 0 at 1668577196.001441159 corr 0 src 1668577196.60270471 diff 1441159
Nov 16 12:39:19 wensleydale ts2phc: [349046.561] eth0 master offset    1441159 s2 freq +9361055
Nov 16 12:39:20 wensleydale ts2phc: [349047.501] nmea sentence: GPRMC,053920.00,A,1343.91052,N,10038.68416,E,0.000,,161122,,,A,V
Nov 16 12:39:20 wensleydale ts2phc: [349047.568] nmea delay: 148233424 ns
Nov 16 12:39:20 wensleydale ts2phc: [349047.569] eth0 extts index 0 at 1668577196.989426097 corr 0 src 1668577197.67511875 diff -10573903
Nov 16 12:39:20 wensleydale ts2phc: [349047.569] eth0 master offset  -10573903 s2 freq -2221659
Nov 16 12:39:21 wensleydale ts2phc: [349048.500] nmea sentence: GPRMC,053921.00,A,1343.91052,N,10038.68416,E,0.000,,161122,,,A,V
Nov 16 12:39:21 wensleydale ts2phc: [349048.576] nmea delay: 147325390 ns
Nov 16 12:39:21 wensleydale ts2phc: [349048.577] eth0 extts index 0 at 1668577197.989158247 corr 0 src 1668577198.76451844 diff -10841753
Nov 16 12:39:21 wensleydale ts2phc: [349048.577] eth0 master offset  -10841753 s2 freq -5661680
Nov 16 12:39:22 wensleydale ts2phc: [349049.501] nmea sentence: GPRMC,053922.00,A,1343.91052,N,10038.68416,E,0.000,,161122,,,A,V
Nov 16 12:39:23 wensleydale ts2phc: [349050.500] nmea sentence: GPRMC,053923.00,A,1343.91052,N,10038.68416,E,0.000,,161122,,,A,V
Nov 16 12:39:23 wensleydale ts2phc: [349050.579] poll returns zero, no events
Nov 16 12:39:23 wensleydale ts2phc: [349050.592] nmea delay: 147205838 ns
Nov 16 12:39:23 wensleydale ts2phc: [349050.592] eth0 extts index 0 at 1668577199.999738067 corr 0 src 1668577200.92387277 diff -261933
Nov 16 12:39:23 wensleydale ts2phc: [349050.592] eth0 master offset    -261933 s2 freq +1665614

Relevant entries from bpftrace on ptp_clock_event:

ptp_clock_event sys=349029424702674, phc=1668577179000000000
ptp_clock_event sys=349030432693033, phc=1668577180000000001
ptp_clock_event sys=349031440677301, phc=1668577181000000001
ptp_clock_event sys=349032448696752, phc=1668577181999999976
ptp_clock_event sys=349033456687149, phc=1668577183000000006
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=349033549559048, pid=545
ptp_clock_event sys=349034464703606, phc=1668577184000000002
ptp_clock_event sys=349035472667843, phc=1668577185000000014
ptp_clock_event sys=349036480688877, phc=1668577185999999983
ptp_clock_event sys=349037488682595, phc=1668577186999999997
ptp_clock_event sys=349038496688518, phc=1668577188000000015
ptp_clock_event sys=349039504696644, phc=1668577189000000001
ptp_clock_event sys=349040512759824, phc=1668577190000000009
ptp_clock_event sys=349041520703488, phc=1668577190999999988
ptp_clock_event sys=349042528693077, phc=1668577191999999996
ptp_clock_event sys=349043536697314, phc=1668577192999999980
ptp_clock_event sys=349044292671057, phc=1668577193752813037  # spurious
ptp_clock_event sys=349044544702626, phc=1668577194005987505
ptp_clock_event sys=349045552713830, phc=1668577195020366422
ptp_clock_event sys=349046560722063, phc=1668577196001441159
ptp_clock_event sys=349047568692370, phc=1668577196989426097
ptp_clock_event sys=349048576695085, phc=1668577197989158247
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=349049563136215, pid=545
ptp_clock_event sys=349050592698242, phc=1668577199999738067
ptp_clock_event sys=349051600720277, phc=1668577200999846246
ptp_clock_event sys=349052356684894, phc=1668577201998172099

This means the kernel is generating the extra pulse. The last PTP_SYS_OFFSET_EXTENDED is 11 seconds before, which I think means it's unlikely to be confusion between the two kinds of timestamp.

jclark commented 2 years ago

I'm not seeing this at all on another system.

System that shows the problem:

System that does not show the problem