> -----Original Message----- > From: Vladimir Oltean [mailto:olte...@gmail.com] > Sent: Saturday, September 28, 2019 5:34 AM > To: richardcoch...@gmail.com > Cc: linuxptp-devel@lists.sourceforge.net > Subject: [Linuxptp-devel] [PATCH] port: Deal with higher-order sync/follow-up > reordering > > So a new port config option was introduced, called > sync_follow_up_history, with a default of 0 that keeps the same behavior > as what was previously intended (and which nobody apparently complained > about). So how does this solve the live lock? It doesn't: > > ptp4l[7502.451]: rms 4 max 8 freq +17765 +/- 8 delay 489 +/- 1 > ptp4l[7504.474]: rms 4 max 10 freq +17764 +/- 9 delay 489 +/- 1 > ptp4l[7504.912]: Tail-dropping sync 12899 due to reordering > ptp4l[7504.914]: Tail-dropping follow-up 12899 due to reordering > ptp4l[7504.944]: Tail-dropping sync 12900 due to reordering > ptp4l[7504.975]: Tail-dropping sync 12901 due to reordering > ptp4l[7504.977]: Tail-dropping follow-up 12900 due to reordering > ptp4l[7505.007]: Tail-dropping sync 12902 due to reordering > > The (important) differences are that: > - The user at least now *knows* what is going on. Previously the only > behavior was that ptp4l was silently dropping frames and > synchronization halted. This is still pretty much fatal even with this > patch, as long as the network keeps pushing frame sequences as above, > but right now it is much more verbose. > - The user has a knob to turn to fix this: increase > sync_follow_up_history while striking an acceptable balance with > logSyncInterval. >
So what's the argument for not increasing the default history depth a little to help alleviate the need to reconfigure it? I do agree this is a better approach and better messaging than before, and it is significantly more clear what's going wrong. Could we add a section to the man page describing this option and when it might make sense? The tail dropping due to re-ordering is clear but may not immediately be obvious to users which knobs to use to help resolve the problem. Thanks, Jake > Signed-off-by: Vladimir Oltean <olte...@gmail.com> > --- > config.c | 2 +- > configs/default.cfg | 2 +- > e2e_tc.c | 3 +- > port.c | 217 +++++++++++++++++++++----------------------- > port_private.h | 14 +-- > ptp4l.8 | 24 ++--- > ptp4l.c | 1 - > raw.c | 3 - > sk.c | 16 ---- > sk.h | 14 --- > udp.c | 3 - > udp6.c | 3 - > 12 files changed, 124 insertions(+), 178 deletions(-) > > diff --git a/config.c b/config.c > index 12eb1f908e36..7e47ae43b763 100644 > --- a/config.c > +++ b/config.c > @@ -214,7 +214,6 @@ struct config_item config_tab[] = { > GLOB_ITEM_INT("assume_two_step", 0, 0, 1), > PORT_ITEM_INT("boundary_clock_jbod", 0, 0, 1), > PORT_ITEM_ENU("BMCA", BMCA_PTP, bmca_enu), > - GLOB_ITEM_INT("check_fup_sync", 0, 0, 1), > GLOB_ITEM_INT("clockAccuracy", 0xfe, 0, UINT8_MAX), > GLOB_ITEM_INT("clockClass", 248, 0, UINT8_MAX), > GLOB_ITEM_STR("clockIdentity", "000000.0000.000000"), > @@ -289,6 +288,7 @@ struct config_item config_tab[] = { > GLOB_ITEM_DBL("step_threshold", 0.0, 0.0, DBL_MAX), > GLOB_ITEM_INT("summary_interval", 0, INT_MIN, INT_MAX), > PORT_ITEM_INT("syncReceiptTimeout", 0, 0, UINT8_MAX), > + PORT_ITEM_INT("sync_follow_up_history", 0, 0, 16), > GLOB_ITEM_INT("tc_spanning_tree", 0, 0, 1), > GLOB_ITEM_INT("timeSource", INTERNAL_OSCILLATOR, 0x10, 0xfe), > GLOB_ITEM_ENU("time_stamping", TS_HARDWARE, timestamping_enu), > diff --git a/configs/default.cfg b/configs/default.cfg > index 119df7b60663..e42124c5abec 100644 > --- a/configs/default.cfg > +++ b/configs/default.cfg > @@ -30,6 +30,7 @@ logMinPdelayReqInterval 0 > operLogPdelayReqInterval 0 > announceReceiptTimeout 3 > syncReceiptTimeout 0 > +sync_follow_up_history 0 > delayAsymmetry 0 > fault_reset_interval 4 > neighborPropDelayThresh 20000000 > @@ -59,7 +60,6 @@ use_syslog 1 > verbose 0 > summary_interval 0 > kernel_leap 1 > -check_fup_sync 0 > # > # Servo Options > # > diff --git a/e2e_tc.c b/e2e_tc.c > index 6aaf57206067..3f47c5ce45f9 100644 > --- a/e2e_tc.c > +++ b/e2e_tc.c > @@ -65,7 +65,8 @@ void e2e_dispatch(struct port *p, enum fsm_event event, int > mdiff) > port_set_announce_tmo(p); > break; > case PS_UNCALIBRATED: > - flush_last_sync(p); > + flush_sync(p); > + flush_follow_up(p); > flush_delay_req(p); > /* fall through */ > case PS_SLAVE: > diff --git a/port.c b/port.c > index 07ad3f069d06..5297d0702fb8 100644 > --- a/port.c > +++ b/port.c > @@ -48,13 +48,6 @@ > #define ALLOWED_LOST_RESPONSES 3 > #define ANNOUNCE_SPAN 1 > > -enum syfu_event { > - SYNC_MISMATCH, > - SYNC_MATCH, > - FUP_MISMATCH, > - FUP_MATCH, > -}; > - > static int port_is_ieee8021as(struct port *p); > static void port_nrate_initialize(struct port *p); > > @@ -501,18 +494,6 @@ static void free_foreign_masters(struct port *p) > } > } > > -static int fup_sync_ok(struct ptp_message *fup, struct ptp_message *sync) > -{ > - /* > - * NB - If the sk_check_fupsync option is not enabled, then > - * both of these time stamps will be zero. > - */ > - if (tmv_cmp(fup->hwts.sw, sync->hwts.sw) < 0) { > - return 0; > - } > - return 1; > -} > - > static int incapable_ignore(struct port *p, struct ptp_message *m) > { > if (port_capable(p)) { > @@ -1199,84 +1180,85 @@ static void port_synchronize(struct port *p, > * they can arrive on two different ports. In addition, time > * stamping in PHY devices might delay the event packets. > */ > -static void port_syfufsm(struct port *p, enum syfu_event event, > - struct ptp_message *m) > +static void port_consume_sync_follow_up(struct port *p) > { > + UInteger16 oldest_syn_seqnum, newest_syn_seqnum; > + UInteger16 oldest_fup_seqnum, newest_fup_seqnum; > + struct ptp_message *oldest_syn, *oldest_fup; > struct ptp_message *syn, *fup; > + UInteger16 newest_seqnum; > > - switch (p->syfu) { > - case SF_EMPTY: > - switch (event) { > - case SYNC_MISMATCH: > - msg_get(m); > - p->last_syncfup = m; > - p->syfu = SF_HAVE_SYNC; > - break; > - case FUP_MISMATCH: > - msg_get(m); > - p->last_syncfup = m; > - p->syfu = SF_HAVE_FUP; > - break; > - case SYNC_MATCH: > - break; > - case FUP_MATCH: > - break; > +find_match: > + oldest_syn_seqnum = 65535; > + newest_syn_seqnum = 0; > + oldest_syn = NULL; > + > + TAILQ_FOREACH(syn, &p->sync, list) { > + if (syn->header.sequenceId <= oldest_syn_seqnum) { > + oldest_syn_seqnum = syn->header.sequenceId; > + oldest_syn = syn; > } > - break; > + if (syn->header.sequenceId >= newest_syn_seqnum) { > + newest_syn_seqnum = syn->header.sequenceId; > + } > + } > > - case SF_HAVE_SYNC: > - switch (event) { > - case SYNC_MISMATCH: > - msg_put(p->last_syncfup); > - msg_get(m); > - p->last_syncfup = m; > - break; > - case SYNC_MATCH: > - break; > - case FUP_MISMATCH: > - msg_put(p->last_syncfup); > - msg_get(m); > - p->last_syncfup = m; > - p->syfu = SF_HAVE_FUP; > - break; > - case FUP_MATCH: > - syn = p->last_syncfup; > - port_synchronize(p, syn->hwts.ts, m->ts.pdu, > - syn->header.correction, > - m->header.correction, > - m->header.logMessageInterval); > - msg_put(p->last_syncfup); > - p->syfu = SF_EMPTY; > - break; > + oldest_fup_seqnum = 65535; > + newest_fup_seqnum = 0; > + oldest_fup = NULL; > + > + TAILQ_FOREACH(fup, &p->follow_up, list) { > + if (fup->header.sequenceId <= oldest_fup_seqnum) { > + oldest_fup_seqnum = fup->header.sequenceId; > + oldest_fup = fup; > } > - break; > + if (fup->header.sequenceId >= newest_fup_seqnum) { > + newest_fup_seqnum = fup->header.sequenceId; > + } > + } > > - case SF_HAVE_FUP: > - switch (event) { > - case SYNC_MISMATCH: > - msg_put(p->last_syncfup); > - msg_get(m); > - p->last_syncfup = m; > - p->syfu = SF_HAVE_SYNC; > - break; > - case SYNC_MATCH: > - fup = p->last_syncfup; > - port_synchronize(p, m->hwts.ts, fup->ts.pdu, > - m->header.correction, > - fup->header.correction, > - m->header.logMessageInterval); > - msg_put(p->last_syncfup); > - p->syfu = SF_EMPTY; > - break; > - case FUP_MISMATCH: > - msg_put(p->last_syncfup); > - msg_get(m); > - p->last_syncfup = m; > - break; > - case FUP_MATCH: > - break; > + if (newest_fup_seqnum > newest_syn_seqnum) > + newest_seqnum = newest_fup_seqnum; > + else > + newest_seqnum = newest_syn_seqnum; > + > + if (oldest_syn && oldest_fup && > + oldest_syn->header.sequenceId == oldest_fup->header.sequenceId) { > + /* Finally, something to consume */ > + port_synchronize(p, oldest_syn->hwts.ts, oldest_fup->ts.pdu, > + oldest_syn->header.correction, > + oldest_fup->header.correction, > + oldest_syn->header.logMessageInterval); > + TAILQ_REMOVE(&p->sync, oldest_syn, list); > + TAILQ_REMOVE(&p->follow_up, oldest_fup, list); > + msg_put(oldest_syn); > + msg_put(oldest_fup); > + /* Go back to try once more, this might have freed another > + * more recent sync/follow-up pair that was already ready > + * for consumption. > + */ > + goto find_match; > + } > + /* We don't want the queues to grow indefinitely, > + * so prune the old messages. > + */ > + TAILQ_FOREACH(syn, &p->sync, list) { > + if (newest_seqnum - syn->header.sequenceId > > + p->sync_follow_up_history) { > + TAILQ_REMOVE(&p->sync, syn, list); > + pr_err("Tail-dropping sync %d due to reordering", > + syn->header.sequenceId); > + msg_put(syn); > + } > + } > + TAILQ_FOREACH(fup, &p->follow_up, list) { > + if (newest_seqnum - fup->header.sequenceId > > + p->sync_follow_up_history) { > + TAILQ_REMOVE(&p->follow_up, fup, list); > + pr_err("Tail-dropping follow-up %d due to reordering", > + fup->header.sequenceId); > + msg_put(fup); > } > - break; > } > } > > @@ -1581,11 +1563,23 @@ int port_is_enabled(struct port *p) > return 1; > } > > -void flush_last_sync(struct port *p) > +void flush_sync(struct port *p) > { > - if (p->syfu != SF_EMPTY) { > - msg_put(p->last_syncfup); > - p->syfu = SF_EMPTY; > + struct ptp_message *m; > + > + while ((m = TAILQ_FIRST(&p->sync)) != NULL) { > + TAILQ_REMOVE(&p->sync, m, list); > + msg_put(m); > + } > +} > + > +void flush_follow_up(struct port *p) > +{ > + struct ptp_message *m; > + > + while ((m = TAILQ_FIRST(&p->follow_up)) != NULL) { > + TAILQ_REMOVE(&p->follow_up, m, list); > + msg_put(m); > } > } > > @@ -1627,7 +1621,8 @@ void port_disable(struct port *p) > int i; > > tc_flush(p); > - flush_last_sync(p); > + flush_sync(p); > + flush_follow_up(p); > flush_delay_req(p); > flush_peer_delay(p); > > @@ -1660,6 +1655,7 @@ int port_initialize(struct port *p) > p->ignore_source_id = config_get_int(cfg, p->name, > "ignore_source_id"); > p->announceReceiptTimeout = config_get_int(cfg, p->name, > "announceReceiptTimeout"); > p->syncReceiptTimeout = config_get_int(cfg, p->name, > "syncReceiptTimeout"); > + p->sync_follow_up_history = config_get_int(cfg, p->name, > "sync_follow_up_history"); > p->transportSpecific = config_get_int(cfg, p->name, > "transportSpecific"); > p->transportSpecific <<= 4; > p->match_transport_specific = !config_get_int(cfg, p->name, > "ignore_transport_specific"); > @@ -1951,7 +1947,6 @@ void process_delay_resp(struct port *p, struct > ptp_message *m) > > void process_follow_up(struct port *p, struct ptp_message *m) > { > - enum syfu_event event; > switch (p->state) { > case PS_INITIALIZING: > case PS_FAULTY: > @@ -1978,13 +1973,9 @@ void process_follow_up(struct port *p, struct > ptp_message *m) > clock_follow_up_info(p->clock, fui); > } > > - if (p->syfu == SF_HAVE_SYNC && > - p->last_syncfup->header.sequenceId == m->header.sequenceId) { > - event = FUP_MATCH; > - } else { > - event = FUP_MISMATCH; > - } > - port_syfufsm(p, event, m); > + msg_get(m); > + TAILQ_INSERT_HEAD(&p->follow_up, m, list); > + port_consume_sync_follow_up(p); > } > > int process_pdelay_req(struct port *p, struct ptp_message *m) > @@ -2255,7 +2246,6 @@ void process_pdelay_resp_fup(struct port *p, struct > ptp_message *m) > > void process_sync(struct port *p, struct ptp_message *m) > { > - enum syfu_event event; > switch (p->state) { > case PS_INITIALIZING: > case PS_FAULTY: > @@ -2287,18 +2277,13 @@ void process_sync(struct port *p, struct ptp_message > *m) > port_synchronize(p, m->hwts.ts, m->ts.pdu, > m->header.correction, 0, > m->header.logMessageInterval); > - flush_last_sync(p); > + flush_sync(p); > return; > } > > - if (p->syfu == SF_HAVE_FUP && > - fup_sync_ok(p->last_syncfup, m) && > - p->last_syncfup->header.sequenceId == m->header.sequenceId) { > - event = SYNC_MATCH; > - } else { > - event = SYNC_MISMATCH; > - } > - port_syfufsm(p, event, m); > + msg_get(m); > + TAILQ_INSERT_HEAD(&p->sync, m, list); > + port_consume_sync_follow_up(p); > } > > /* public methods */ > @@ -2391,7 +2376,8 @@ static void port_e2e_transition(struct port *p, enum > port_state next) > port_set_announce_tmo(p); > break; > case PS_UNCALIBRATED: > - flush_last_sync(p); > + flush_sync(p); > + flush_follow_up(p); > flush_delay_req(p); > /* fall through */ > case PS_SLAVE: > @@ -2436,7 +2422,8 @@ static void port_p2p_transition(struct port *p, enum > port_state next) > port_set_announce_tmo(p); > break; > case PS_UNCALIBRATED: > - flush_last_sync(p); > + flush_sync(p); > + flush_follow_up(p); > flush_peer_delay(p); > /* fall through */ > case PS_SLAVE: > @@ -2953,6 +2940,8 @@ struct port *port_open(int phc_index, > } > > memset(p, 0, sizeof(*p)); > + TAILQ_INIT(&p->sync); > + TAILQ_INIT(&p->follow_up); > TAILQ_INIT(&p->tc_transmitted); > > switch (type) { > diff --git a/port_private.h b/port_private.h > index 5789fbbafa43..bc0b0b8cd6df 100644 > --- a/port_private.h > +++ b/port_private.h > @@ -29,12 +29,6 @@ > > #define NSEC2SEC 1000000000LL > > -enum syfu_state { > - SF_EMPTY, > - SF_HAVE_SYNC, > - SF_HAVE_FUP, > -}; > - > enum link_state { > LINK_DOWN = (1<<0), > LINK_UP = (1<<1), > @@ -74,8 +68,8 @@ struct port { > > int jbod; > struct foreign_clock *best; > - enum syfu_state syfu; > - struct ptp_message *last_syncfup; > + TAILQ_HEAD(sync, ptp_message) sync; > + TAILQ_HEAD(follow_up, ptp_message) follow_up; > TAILQ_HEAD(delay_req, ptp_message) delay_req; > struct ptp_message *peer_delay_req; > struct ptp_message *peer_delay_resp; > @@ -113,6 +107,7 @@ struct port { > UInteger8 announceReceiptTimeout; > int announce_span; > UInteger8 syncReceiptTimeout; > + UInteger16 sync_follow_up_history; > UInteger8 transportSpecific; > UInteger8 localPriority; > Integer8 initialLogSyncInterval; > @@ -162,8 +157,9 @@ enum fsm_event p2p_event(struct port *p, int fd_index); > int clear_fault_asap(struct fault_interval *faint); > void delay_req_prune(struct port *p); > void fc_clear(struct foreign_clock *fc); > +void flush_sync(struct port *p); > +void flush_follow_up(struct port *p); > void flush_delay_req(struct port *p); > -void flush_last_sync(struct port *p); > int port_capable(struct port *p); > int port_clr_tmo(int fd); > int port_delay_request(struct port *p); > diff --git a/ptp4l.8 b/ptp4l.8 > index ab156d9ed010..c6e1b949739b 100644 > --- a/ptp4l.8 > +++ b/ptp4l.8 > @@ -203,6 +203,18 @@ running in gPTP mode according to the 802.1AS-2011 > standard. Setting > this option to zero will disable the sync message timeout. > The default is 0 or disabled. > .TP > +.B sync_follow_up_history > +Because of packet reordering that can occur in the network, in the > +hardware, or in the networking stack, a follow up message can appear > +to arrive in the application before the matching sync message (or in > +any other combinations). As this is a normal occurrence, and the sequenceID > +message field ensures proper matching, the ptp4l program accepts out of > +order packets. This option specifies the difference between the oldest and > +the newest sequenceID that will be queued by the application while waiting > +for a matching pair. > +The default is 0 (don't queue any sync or follow-up messages, drop them > +immediately once another message of the same type has arrived). > +.TP > .B transportSpecific > The transport specific field. Must be in the range 0 to 255. > The default is 0. > @@ -486,18 +498,6 @@ The number of milliseconds to poll waiting for the tx > time > stamp from the kernel > when a message has recently been sent. > The default is 1. > .TP > -.B check_fup_sync > -Because of packet reordering that can occur in the network, in the > -hardware, or in the networking stack, a follow up message can appear > -to arrive in the application before the matching sync message. As this > -is a normal occurrence, and the sequenceID message field ensures > -proper matching, the ptp4l program accepts out of order packets. This > -option adds an additional check using the software time stamps from > -the networking stack to verify that the sync message did arrive > -first. This option is only useful if you do not trust the sequence IDs > -generated by the master. > -The default is 0 (disabled). > -.TP > .B clock_servo > The servo which is used to synchronize the local clock. Valid values > are "pi" for a PI controller, "linreg" for an adaptive controller > diff --git a/ptp4l.c b/ptp4l.c > index 84661c5f0ea9..07993ecac7d1 100644 > --- a/ptp4l.c > +++ b/ptp4l.c > @@ -188,7 +188,6 @@ int main(int argc, char *argv[]) > print_set_level(config_get_int(cfg, NULL, "logging_level")); > > assume_two_step = config_get_int(cfg, NULL, "assume_two_step"); > - sk_check_fupsync = config_get_int(cfg, NULL, "check_fup_sync"); > sk_tx_timeout = config_get_int(cfg, NULL, "tx_timestamp_timeout"); > sk_hwts_filter_mode = config_get_int(cfg, NULL, "hwts_filter"); > > diff --git a/raw.c b/raw.c > index f1c92b9f8d90..a191822c54c2 100644 > --- a/raw.c > +++ b/raw.c > @@ -245,9 +245,6 @@ static int raw_open(struct transport *t, struct interface > *iface, > if (sk_timestamping_init(efd, name, ts_type, TRANS_IEEE_802_3)) > goto no_timestamping; > > - if (sk_general_init(gfd)) > - goto no_timestamping; > - > fda->fd[FD_EVENT] = efd; > fda->fd[FD_GENERAL] = gfd; > return 0; > diff --git a/sk.c b/sk.c > index e2111755aac5..193b5b207d4c 100644 > --- a/sk.c > +++ b/sk.c > @@ -40,7 +40,6 @@ > /* globals */ > > int sk_tx_timeout = 1; > -int sk_check_fupsync; > enum hwts_filter_mode sk_hwts_filter_mode = HWTS_FILTER_NORMAL; > > /* private methods */ > @@ -146,16 +145,6 @@ int sk_interface_index(int fd, const char *name) > return ifreq.ifr_ifindex; > } > > -int sk_general_init(int fd) > -{ > - int on = sk_check_fupsync ? 1 : 0; > - if (setsockopt(fd, SOL_SOCKET, SO_TIMESTAMPNS, &on, sizeof(on)) < 0) { > - pr_err("ioctl SO_TIMESTAMPNS failed: %m"); > - return -1; > - } > - return 0; > -} > - > int sk_get_ts_info(const char *name, struct sk_ts_info *sk_info) > { > #ifdef ETHTOOL_GET_TS_INFO > @@ -523,10 +512,5 @@ int sk_timestamping_init(int fd, const char *device, enum > timestamp_type type, > sk_revents = POLLERR; > } > > - /* Enable the sk_check_fupsync option, perhaps. */ > - if (sk_general_init(fd)) { > - return -1; > - } > - > return 0; > } > diff --git a/sk.h b/sk.h > index 04d26ee5d394..4e7b8d12df6e 100644 > --- a/sk.h > +++ b/sk.h > @@ -63,13 +63,6 @@ int sk_interface_fd(void); > */ > int sk_interface_index(int fd, const char *device); > > -/** > - * Prepare a given socket for PTP "general" messages. > - * @param fd An open socket. > - * @return Zero on success, non-zero otherwise. > - */ > -int sk_general_init(int fd); > - > /** > * Obtain supported timestamping information > * @param name The name of the interface > @@ -135,13 +128,6 @@ int sk_timestamping_init(int fd, const char *device, enum > timestamp_type type, > */ > extern int sk_tx_timeout; > > -/** > - * Enables the SO_TIMESTAMPNS socket option on the both the event and > - * general sockets in order to test the order of paired sync and > - * follow up messages using their network stack receipt time stamps. > - */ > -extern int sk_check_fupsync; > - > /** > * Hardware time-stamp setting mode > */ > diff --git a/udp.c b/udp.c > index 48af482b4526..6c2e720c007d 100644 > --- a/udp.c > +++ b/udp.c > @@ -182,9 +182,6 @@ static int udp_open(struct transport *t, struct interface > *iface, > if (sk_timestamping_init(efd, iface->ts_label, ts_type, TRANS_UDP_IPV4)) > goto no_timestamping; > > - if (sk_general_init(gfd)) > - goto no_timestamping; > - > event_dscp = config_get_int(t->cfg, NULL, "dscp_event"); > general_dscp = config_get_int(t->cfg, NULL, "dscp_general"); > > diff --git a/udp6.c b/udp6.c > index 74ebc7f0cf09..02df014fe15e 100644 > --- a/udp6.c > +++ b/udp6.c > @@ -199,9 +199,6 @@ static int udp6_open(struct transport *t, struct interface > *iface, > if (sk_timestamping_init(efd, iface->ts_label, ts_type, TRANS_UDP_IPV6)) > goto no_timestamping; > > - if (sk_general_init(gfd)) > - goto no_timestamping; > - > event_dscp = config_get_int(t->cfg, NULL, "dscp_event"); > general_dscp = config_get_int(t->cfg, NULL, "dscp_general"); > > -- > 2.17.1 > > > > _______________________________________________ > Linuxptp-devel mailing list > Linuxptp-devel@lists.sourceforge.net > https://lists.sourceforge.net/lists/listinfo/linuxptp-devel _______________________________________________ Linuxptp-devel mailing list Linuxptp-devel@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/linuxptp-devel