Hello, I've got some odd PTP behaviour from a Metamako switch (which runs it's own version of linuxptp-1.9), and have reproduced similar behaviour with linuxptp-2.0.
We've got a new Grand Master appliance on trial, an Orelia VelaSync 2. It's plugged into a LAN in our lab along side it's predecessor, the VelaSync 1 (which is really FSM Labs' TimeKeeper Server). These masters deal with the UTC offset and leap seconds differently. The VS1 / TimeKeeper takes the inventive approach of publishing PTP messages containing UTC time and a UTC offset of zero (it does this so it can be in control of leap second slewing). The VS2 simply publishes TAI time with a UTC offset of 37 seconds. As I understand it, net result should be the same: UTC - 0s and TAI - 37s. I've set the VS2 priority1 field to 127, higher than the VS1's priority1 of 128 (the point of the exercise is to test the VS2). What appears to happen is ptp4l first tries to calibrate to the VS1 (the VS1 sends a boat load more Announce messages than the VS2), and sets the UTC offset to zero: ptp4l[419887.425]: selected best master clock 248a07.fffe.fdb701 ptp4l[419887.425]: updating UTC offset to 0 ptp4l[419887.425]: port 1: LISTENING to UNCALIBRATED on RS_SLAVE ptp4l[419888.699]: rms 172 max 221 freq -24777 +/- 102 delay 2141 +/- 7 ptp4l[419889.727]: rms 96 max 141 freq -24730 +/- 28 delay 2142 +/- 4 ptp4l[419890.739]: rms 54 max 79 freq -24747 +/- 41 delay 2145 +/- 3 Not long after the VS2 is discovered, and selected as the best clock. The new UTC offset flag is set to match the different time in the Follow_Up messages, but the clock jumps 37 seconds anyway: ptp4l[419888.434]: port 1: new foreign master ec0d9a.fffe.2a5680-1 ptp4l[419892.434]: selected best master clock ffffff.ffff.ffffff ptp4l[419892.434]: updating UTC offset to 37 ptp4l[419892.434]: port 1: SLAVE to UNCALIBRATED on RS_SLAVE ptp4l[419892.811]: port 1: UNCALIBRATED to SLAVE on MASTER_CLOCK_SELECTED ptp4l[419893.306]: selected best master clock ffffff.ffff.ffffff ptp4l[419893.306]: updating UTC offset to 37 ptp4l[419893.434]: rms 32034559090 max 37000000060 freq -23256182 +/- 13412686 delay 2139 +/- 20 ptp4l[419894.434]: rms 36963221067 max 36976771182 freq -31000000 +/- 0 ptp4l[419894.841]: selected best master clock ffffff.ffff.ffffff ptp4l[419894.841]: updating UTC offset to 37 ptp4l[419895.352]: selected best master clock ffffff.ffff.ffffff ptp4l[419895.352]: updating UTC offset to 37 ptp4l[419895.434]: rms 36930870374 max 36945061895 freq -31000000 +/- 0 delay -1099123 +/- 367074 Note the clock ID of 0xffff here is a bogus value from the VS2 announce messages, it's populating it's grandmasterClockIdentity field with a reserved address. I've already emailed Orelia about it (side question; why is ptp4l logging the grandmasterClockIdentity field in the log file as the "master" and not the clockIdentity field?). When we were just running the VS1, everything was fine, this worked. If you shut off the VS1 (or change it's PTP domain number) so just the VS2 messages are "seen", everything is also fine, it works. The craziness only occurs when there is a mix of messages from both masters on the LAN. Also, this doesn't affect 'ptpd' (which is what most of my clients run), it only affects ptp4l. The other odd thing from the log (and the Metamako switch) is it constantly spits out these messages: selected best master clock ffffff.ffff.ffffff Which comes from handle_state_decision_event() in clock.c (remember, ignore the clock ID), and: updating UTC offset to 37 Which is in clock_update_slave(). That seems odd to me... I would expect to see them during/after a BMC election, not over and over again. The PTP priority hasn't changed, VS2 is still best clock. Part of the condition of the second message is: (c->tds.currentUtcOffset > c->utc_offset) I wonder if the VS1 messages are somehow being processed (even though it's not master), and the UTC offset flag is being polluted and this is what's jamming the clock away from real time? Full ptp4l log file is attached. -- Luke Bigum Head of Systems, LMAX Exchange
ptp4l[419886.766]: config item (null).assume_two_step is 0 ptp4l[419886.766]: config item (null).check_fup_sync is 0 ptp4l[419886.766]: config item (null).tx_timestamp_timeout is 1 ptp4l[419886.766]: config item (null).clock_servo is 0 ptp4l[419886.766]: config item (null).clock_type is 32768 ptp4l[419886.766]: config item (null).clock_servo is 0 ptp4l[419886.766]: config item (null).clockClass is 248 ptp4l[419886.766]: config item (null).clockAccuracy is 254 ptp4l[419886.766]: config item (null).offsetScaledLogVariance is 65535 ptp4l[419886.766]: config item (null).productDescription is ';;' ptp4l[419886.766]: config item (null).revisionData is ';;' ptp4l[419886.766]: config item (null).userDescription is '' ptp4l[419886.766]: config item (null).manufacturerIdentity is '00:00:00' ptp4l[419886.766]: config item (null).domainNumber is 0 ptp4l[419886.766]: config item (null).slaveOnly is 1 ptp4l[419886.766]: config item (null).gmCapable is 1 ptp4l[419886.766]: config item (null).gmCapable is 1 ptp4l[419886.766]: config item (null).G.8275.defaultDS.localPriority is 128 ptp4l[419886.766]: config item (null).time_stamping is 1 ptp4l[419886.766]: config item (null).twoStepFlag is 1 ptp4l[419886.766]: config item (null).twoStepFlag is 1 ptp4l[419886.766]: config item (null).time_stamping is 1 ptp4l[419886.766]: config item (null).priority1 is 255 ptp4l[419886.766]: config item (null).priority2 is 128 ptp4l[419886.766]: interface index 2 is up ptp4l[419886.766]: config item (null).free_running is 0 ptp4l[419886.766]: selected /dev/ptp5 as PTP clock ptp4l[419886.766]: config item (null).uds_address is '/var/run/ptp4l' ptp4l[419886.766]: section item /var/run/ptp4l.announceReceiptTimeout now 0 ptp4l[419886.766]: section item /var/run/ptp4l.delay_mechanism now 0 ptp4l[419886.766]: section item /var/run/ptp4l.network_transport now 0 ptp4l[419886.766]: section item /var/run/ptp4l.delay_filter_length now 1 ptp4l[419886.766]: config item (null).free_running is 0 ptp4l[419886.766]: config item (null).freq_est_interval is 1 ptp4l[419886.766]: config item (null).gmCapable is 1 ptp4l[419886.766]: config item (null).kernel_leap is 1 ptp4l[419886.766]: config item (null).utc_offset is 37 ptp4l[419886.766]: config item (null).timeSource is 160 ptp4l[419886.768]: config item (null).pi_proportional_const is 0.000000 ptp4l[419886.768]: config item (null).pi_integral_const is 0.000000 ptp4l[419886.768]: config item (null).pi_proportional_scale is 0.000000 ptp4l[419886.768]: config item (null).pi_proportional_exponent is -0.300000 ptp4l[419886.768]: config item (null).pi_proportional_norm_max is 0.700000 ptp4l[419886.768]: config item (null).pi_integral_scale is 0.000000 ptp4l[419886.768]: config item (null).pi_integral_exponent is 0.400000 ptp4l[419886.768]: config item (null).pi_integral_norm_max is 0.300000 ptp4l[419886.768]: config item (null).step_threshold is 0.000000 ptp4l[419886.768]: config item (null).first_step_threshold is 0.000020 ptp4l[419886.768]: config item (null).max_frequency is 900000000 ptp4l[419886.768]: config item (null).dataset_comparison is 0 ptp4l[419886.768]: config item (null).delay_filter_length is 10 ptp4l[419886.768]: config item (null).delay_filter is 1 ptp4l[419886.768]: config item (null).tsproc_mode is 0 ptp4l[419886.768]: config item (null).initial_delay is 0 ptp4l[419886.768]: config item (null).summary_interval is 0 ptp4l[419886.768]: config item (null).sanity_freq_limit is 200000000 ptp4l[419886.768]: PI servo: sync interval 1.000 kp 0.700 ki 0.300000 ptp4l[419886.768]: config item /var/run/ptp4l.boundary_clock_jbod is 0 ptp4l[419886.768]: config item /var/run/ptp4l.network_transport is 0 ptp4l[419886.768]: config item /var/run/ptp4l.delayAsymmetry is 0 ptp4l[419886.768]: config item /var/run/ptp4l.follow_up_info is 0 ptp4l[419886.768]: config item /var/run/ptp4l.freq_est_interval is 1 ptp4l[419886.768]: config item /var/run/ptp4l.net_sync_monitor is 0 ptp4l[419886.768]: config item /var/run/ptp4l.path_trace_enabled is 0 ptp4l[419886.768]: config item /var/run/ptp4l.tc_spanning_tree is 0 ptp4l[419886.768]: config item /var/run/ptp4l.ingressLatency is 0 ptp4l[419886.768]: config item /var/run/ptp4l.egressLatency is 0 ptp4l[419886.768]: config item /var/run/ptp4l.delay_mechanism is 0 ptp4l[419886.768]: config item /var/run/ptp4l.hybrid_e2e is 0 ptp4l[419886.768]: config item /var/run/ptp4l.fault_badpeernet_interval is 16 ptp4l[419886.768]: config item /var/run/ptp4l.fault_reset_interval is 4 ptp4l[419886.768]: config item /var/run/ptp4l.delay_filter_length is 1 ptp4l[419886.768]: config item /var/run/ptp4l.delay_filter is 1 ptp4l[419886.768]: config item /var/run/ptp4l.tsproc_mode is 0 ptp4l[419886.768]: config item em1.boundary_clock_jbod is 0 ptp4l[419886.768]: config item em1.network_transport is 1 ptp4l[419886.768]: config item em1.delayAsymmetry is 0 ptp4l[419886.768]: config item em1.follow_up_info is 0 ptp4l[419886.768]: config item em1.freq_est_interval is 1 ptp4l[419886.768]: config item em1.net_sync_monitor is 0 ptp4l[419886.768]: config item em1.path_trace_enabled is 0 ptp4l[419886.768]: config item em1.tc_spanning_tree is 0 ptp4l[419886.768]: config item em1.ingressLatency is 0 ptp4l[419886.768]: config item em1.egressLatency is 0 ptp4l[419886.768]: config item em1.delay_mechanism is 1 ptp4l[419886.768]: config item em1.unicast_master_table is 0 ptp4l[419886.768]: config item em1.unicast_listen is 0 ptp4l[419886.768]: config item em1.hybrid_e2e is 0 ptp4l[419886.768]: config item em1.fault_badpeernet_interval is 16 ptp4l[419886.768]: config item em1.fault_reset_interval is 4 ptp4l[419886.768]: config item em1.delay_filter_length is 10 ptp4l[419886.768]: config item em1.delay_filter is 1 ptp4l[419886.768]: config item em1.tsproc_mode is 0 ptp4l[419886.768]: config item em1.logMinDelayReqInterval is 0 ptp4l[419886.768]: config item em1.logAnnounceInterval is 1 ptp4l[419886.768]: config item em1.announceReceiptTimeout is 3 ptp4l[419886.768]: config item em1.syncReceiptTimeout is 0 ptp4l[419886.768]: config item em1.transportSpecific is 0 ptp4l[419886.768]: config item em1.ignore_transport_specific is 0 ptp4l[419886.768]: config item em1.masterOnly is 0 ptp4l[419886.768]: config item em1.G.8275.portDS.localPriority is 128 ptp4l[419886.768]: config item em1.logSyncInterval is 0 ptp4l[419886.768]: config item em1.logMinPdelayReqInterval is 0 ptp4l[419886.768]: config item em1.neighborPropDelayThresh is 20000000 ptp4l[419886.768]: config item em1.min_neighbor_prop_delay is -20000000 ptp4l[419886.768]: config item em1.udp_ttl is 3 ptp4l[419886.784]: config item (null).dscp_event is 0 ptp4l[419886.784]: config item (null).dscp_general is 0 ptp4l[419886.784]: port 1: INITIALIZING to LISTENING on INIT_COMPLETE ptp4l[419886.784]: config item /var/run/ptp4l.logMinDelayReqInterval is 0 ptp4l[419886.784]: config item /var/run/ptp4l.logAnnounceInterval is 1 ptp4l[419886.784]: config item /var/run/ptp4l.announceReceiptTimeout is 0 ptp4l[419886.784]: config item /var/run/ptp4l.syncReceiptTimeout is 0 ptp4l[419886.784]: config item /var/run/ptp4l.transportSpecific is 0 ptp4l[419886.784]: config item /var/run/ptp4l.ignore_transport_specific is 0 ptp4l[419886.784]: config item /var/run/ptp4l.masterOnly is 0 ptp4l[419886.784]: config item /var/run/ptp4l.G.8275.portDS.localPriority is 128 ptp4l[419886.784]: config item /var/run/ptp4l.logSyncInterval is 0 ptp4l[419886.784]: config item /var/run/ptp4l.logMinPdelayReqInterval is 0 ptp4l[419886.784]: config item /var/run/ptp4l.neighborPropDelayThresh is 20000000 ptp4l[419886.784]: config item /var/run/ptp4l.min_neighbor_prop_delay is -20000000 ptp4l[419886.784]: config item (null).uds_address is '/var/run/ptp4l' ptp4l[419886.784]: port 0: INITIALIZING to LISTENING on INIT_COMPLETE ptp4l[419886.784]: port 1: received link status notification ptp4l[419886.784]: interface index 2 is up ptp4l[419886.809]: port 1: setting asCapable ptp4l[419886.918]: port 1: new foreign master 248a07.fffe.fdb701-54 ptp4l[419887.425]: selected best master clock 248a07.fffe.fdb701 ptp4l[419887.425]: updating UTC offset to 0 ptp4l[419887.425]: port 1: LISTENING to UNCALIBRATED on RS_SLAVE ptp4l[419887.476]: port 1: delay timeout ptp4l[419887.476]: port 1: minimum delay request interval 2^-2 ptp4l[419887.682]: PI servo: sync interval 0.250 kp 1.061 ki 0.172305 ptp4l[419887.936]: port 1: delay timeout ptp4l[419887.936]: delay filtered 2146 raw 2146 ptp4l[419888.190]: port 1: UNCALIBRATED to SLAVE on MASTER_CLOCK_SELECTED ptp4l[419888.297]: port 1: delay timeout ptp4l[419888.298]: delay filtered 2132 raw 2119 ptp4l[419888.434]: port 1: new foreign master ec0d9a.fffe.2a5680-1 ptp4l[419888.611]: port 1: delay timeout ptp4l[419888.611]: delay filtered 2146 raw 2157 ptp4l[419888.699]: rms 172 max 221 freq -24777 +/- 102 delay 2141 +/- 7 ptp4l[419888.941]: port 1: delay timeout ptp4l[419888.941]: delay filtered 2139 raw 2132 ptp4l[419889.210]: port 1: delay timeout ptp4l[419889.210]: delay filtered 2146 raw 2156 ptp4l[419889.473]: port 1: delay timeout ptp4l[419889.473]: delay filtered 2139 raw 2131 ptp4l[419889.696]: port 1: delay timeout ptp4l[419889.697]: delay filtered 2146 raw 2411 ptp4l[419889.727]: rms 96 max 141 freq -24730 +/- 28 delay 2142 +/- 4 ptp4l[419889.775]: port 1: delay timeout ptp4l[419889.775]: delay filtered 2139 raw 2127 ptp4l[419889.855]: port 1: delay timeout ptp4l[419889.856]: delay filtered 2146 raw 2147 ptp4l[419890.117]: port 1: delay timeout ptp4l[419890.117]: delay filtered 2146 raw 2166 ptp4l[419890.612]: port 1: delay timeout ptp4l[419890.612]: delay filtered 2148 raw 2150 ptp4l[419890.674]: port 1: delay timeout ptp4l[419890.674]: delay filtered 2148 raw 2130 ptp4l[419890.739]: rms 54 max 79 freq -24747 +/- 41 delay 2145 +/- 3 ptp4l[419891.073]: port 1: delay timeout ptp4l[419891.073]: delay filtered 2148 raw 2199 ptp4l[419891.485]: port 1: delay timeout ptp4l[419891.485]: delay filtered 2152 raw 2155 ptp4l[419891.691]: port 1: delay timeout ptp4l[419891.691]: delay filtered 2148 raw 2141 ptp4l[419891.768]: rms 52 max 91 freq -24767 +/- 59 delay 2149 +/- 2 ptp4l[419892.149]: port 1: delay timeout ptp4l[419892.149]: delay filtered 2152 raw 2164 ptp4l[419892.215]: port 1: delay timeout ptp4l[419892.215]: delay filtered 2148 raw 2146 ptp4l[419892.296]: port 1: delay timeout ptp4l[419892.296]: delay filtered 2148 raw 2144 ptp4l[419892.310]: port 1: delay timeout ptp4l[419892.310]: delay filtered 2148 raw 2126 ptp4l[419892.434]: selected best master clock ffffff.ffff.ffffff ptp4l[419892.434]: updating UTC offset to 37 ptp4l[419892.434]: port 1: SLAVE to UNCALIBRATED on RS_SLAVE ptp4l[419892.559]: PI servo: sync interval 0.125 kp 1.306 ki 0.130583 ptp4l[419892.718]: port 1: delay timeout ptp4l[419892.718]: delay filtered 2098 raw 2098 ptp4l[419892.718]: port 1: minimum delay request interval 2^0 ptp4l[419892.787]: selected best master clock ffffff.ffff.ffffff ptp4l[419892.787]: updating UTC offset to 37 ptp4l[419892.811]: port 1: UNCALIBRATED to SLAVE on MASTER_CLOCK_SELECTED ptp4l[419893.306]: selected best master clock ffffff.ffff.ffffff ptp4l[419893.306]: updating UTC offset to 37 ptp4l[419893.434]: rms 32034559090 max 37000000060 freq -23256182 +/- 13412686 delay 2139 +/- 20 ptp4l[419893.824]: selected best master clock ffffff.ffff.ffffff ptp4l[419893.824]: updating UTC offset to 37 ptp4l[419894.333]: selected best master clock ffffff.ffff.ffffff ptp4l[419894.333]: updating UTC offset to 37 ptp4l[419894.434]: rms 36963221067 max 36976771182 freq -31000000 +/- 0 ptp4l[419894.529]: port 1: delay timeout ptp4l[419894.529]: negative delay -1466197 ptp4l[419894.529]: delay = (t2 - t3) * rr + (t4 - t1) ptp4l[419894.529]: t2 - t3 = -97747432 ptp4l[419894.529]: t4 - t1 = +94815037 ptp4l[419894.529]: rr = 1.000000000 ptp4l[419894.529]: delay filtered -732049 raw -1466197 ptp4l[419894.681]: port 1: delay timeout ptp4l[419894.681]: negative delay -1886125 ptp4l[419894.681]: delay = (t2 - t3) * rr + (t4 - t1) ptp4l[419894.681]: t2 - t3 = -125700639 ptp4l[419894.681]: t4 - t1 = +121928388 ptp4l[419894.681]: rr = 1.000000000 ptp4l[419894.681]: delay filtered -1466197 raw -1886125 ptp4l[419894.841]: selected best master clock ffffff.ffff.ffffff ptp4l[419894.841]: updating UTC offset to 37 ptp4l[419895.352]: selected best master clock ffffff.ffff.ffffff ptp4l[419895.352]: updating UTC offset to 37 ptp4l[419895.434]: rms 36930870374 max 36945061895 freq -31000000 +/- 0 delay -1099123 +/- 367074 ptp4l[419895.853]: port 1: delay timeout ptp4l[419895.853]: negative delay -673978 ptp4l[419895.853]: delay = (t2 - t3) * rr + (t4 - t1) ptp4l[419895.853]: t2 - t3 = -45009856 ptp4l[419895.853]: t4 - t1 = +43661900 ptp4l[419895.853]: rr = 1.000000000 ptp4l[419895.853]: delay filtered -1070087 raw -673978 ptp4l[419895.863]: selected best master clock ffffff.ffff.ffffff ptp4l[419895.863]: updating UTC offset to 37 ptp4l[419896.079]: port 1: delay timeout ptp4l[419896.079]: negative delay -303003 ptp4l[419896.079]: delay = (t2 - t3) * rr + (t4 - t1) ptp4l[419896.079]: t2 - t3 = -20314017 ptp4l[419896.079]: t4 - t1 = +19708010 ptp4l[419896.079]: rr = 1.000000000 ptp4l[419896.079]: delay filtered -673978 raw -303003 ptp4l[419896.381]: selected best master clock ffffff.ffff.ffffff ptp4l[419896.381]: updating UTC offset to 37 ptp4l[419896.434]: rms 36900199647 max 36913354422 freq -31000000 +/- 0 delay -872032 +/- 198054
_______________________________________________ Linuxptp-users mailing list Linuxptp-users@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/linuxptp-users
