go to holdover and meanfreq when samples are not processed in time

Summary: the servo fails to adjust PHC properly if PTP samples are coming too soon or delayed. make PHC go to holdover with mean frequency in this case

Reviewed By: leoleovich

Differential Revision: D52667242

fbshipit-source-id: e1e9d4061abe59eb6cbdba51be65aaf5b29768d5

ptp/sptp/client/sptp.go

@@ -314,6 +314,14 @@ func (p *SPTP) handleExchangeError(addr string, err error) {
 	}
 }
 
+func (p *SPTP) setMeanFreq() (float64, servo.State) {
+	freqAdj := p.pi.MeanFreq()
+	if err := p.clock.AdjFreqPPB(-1 * freqAdj); err != nil {
+		log.Errorf("failed to adjust freq to %v: %v", -1*freqAdj, err)
+	}
+	return freqAdj, servo.StateHoldover
+}
+
 func (p *SPTP) processResults(results map[string]*RunResult) {
 	defer func() {
 		for addr, res := range results {
@@ -322,15 +330,17 @@ func (p *SPTP) processResults(results map[string]*RunResult) {
 		}
 	}()
 
+	isBadTick := false
 	now := time.Now()
 	if !p.lastTick.IsZero() {
 		tickDuration := now.Sub(p.lastTick)
 		log.Debugf("tick took %vms sys time", tickDuration.Milliseconds())
 		// +-10% of interval
+		p.stats.SetCounter("ptp.sptp.tick_duration_ns", int64(tickDuration))
 		if 100*tickDuration > 110*p.cfg.Interval || 100*tickDuration < 90*p.cfg.Interval {
 			log.Warningf("tick took %vms, which is outside of expected +-10%% from the interval %vms", tickDuration.Milliseconds(), p.cfg.Interval.Milliseconds())
+			isBadTick = true
 		}
-		p.stats.SetCounter("ptp.sptp.tick_duration_ns", int64(tickDuration))
 	}
 	p.lastTick = now
 	gmsTotal := len(results)
@@ -365,11 +375,7 @@ func (p *SPTP) processResults(results map[string]*RunResult) {
 	if best == nil {
 		log.Warningf("no Best Master selected")
 		p.bestGM = ""
-		freqAdj := p.pi.MeanFreq()
-		state := servo.StateHoldover
-		if err := p.clock.AdjFreqPPB(-1 * freqAdj); err != nil {
-			log.Errorf("failed to adjust freq to %v: %v", -1*freqAdj, err)
-		}
+		freqAdj, state := p.setMeanFreq()
 		log.Infof("offset Unknown s%d freq %+7.0f path delay Unknown", state, freqAdj)
 		return
 	}
@@ -380,6 +386,11 @@ func (p *SPTP) processResults(results map[string]*RunResult) {
 		p.bestGM = bestAddr
 	}
 	log.Debugf("best master %q (%s)", bestAddr, bm.Announce.GrandmasterIdentity)
+	if isBadTick {
+		freqAdj, state := p.setMeanFreq()
+		log.Infof("offset %10d s%d freq %+7.0f path delay %10d", bm.Offset.Nanoseconds(), state, freqAdj, bm.Delay.Nanoseconds())
+		return
+	}
 	freqAdj, state := p.pi.Sample(int64(bm.Offset), uint64(bm.Timestamp.UnixNano()))
 	log.Infof("offset %10d s%d freq %+7.0f path delay %10d", bm.Offset.Nanoseconds(), state, freqAdj, bm.Delay.Nanoseconds())
 	switch state {

ptp/sptp/client/sptp_test.go

@@ -136,6 +136,8 @@ func TestProcessResultsSingle(t *testing.T) {
 	p.processResults(results)
 	require.Equal(t, "192.168.0.10", p.bestGM)
 
+	// we have to wait a second to avoid "samples are too fast" error
+	time.Sleep(time.Second)
 	results["192.168.0.10"].Measurement.Offset = -100001 * time.Microsecond
 	// we adj here
 	mockStatsServer.EXPECT().SetCounter("ptp.sptp.gms.total", int64(1))
@@ -146,6 +148,59 @@ func TestProcessResultsSingle(t *testing.T) {
 	require.Equal(t, "192.168.0.10", p.bestGM)
 }
 
+func TestProcessResultsFastSamples(t *testing.T) {
+	ts, err := time.Parse(time.RFC3339, "2021-05-21T13:32:05+01:00")
+	require.Nil(t, err)
+	ctrl := gomock.NewController(t)
+	defer ctrl.Finish()
+	mockClock := NewMockClock(ctrl)
+	mockClock.EXPECT().AdjFreqPPB(gomock.Any()).Return(nil)
+	mockClock.EXPECT().Step(gomock.Any()).Return(nil)
+	mockServo := NewMockServo(ctrl)
+	mockServo.EXPECT().Sample(int64(-200002000), gomock.Any()).Return(12.3, servo.StateJump)
+	mockServo.EXPECT().MeanFreq().Return(12.3)
+	mockStatsServer := NewMockStatsServer(ctrl)
+	mockStatsServer.EXPECT().SetCounter("ptp.sptp.gms.total", int64(1))
+	mockStatsServer.EXPECT().SetCounter("ptp.sptp.gms.available_pct", int64(100))
+	mockStatsServer.EXPECT().SetGMStats(gomock.Any())
+
+	cfg := DefaultConfig()
+	cfg.Servers = map[string]int{
+		"192.168.0.10": 1,
+	}
+	p := &SPTP{
+		clock: mockClock,
+		pi:    mockServo,
+		stats: mockStatsServer,
+		cfg:   cfg,
+	}
+	results := map[string]*RunResult{
+		"192.168.0.10": {
+			Server: "192.168.0.10",
+			Measurement: &MeasurementResult{
+				Delay:     299995 * time.Microsecond,
+				S2CDelay:  100,
+				C2SDelay:  110,
+				Offset:    -200002 * time.Microsecond,
+				Timestamp: ts,
+			},
+		},
+	}
+	err = p.initClients()
+	require.NoError(t, err)
+	// we step here
+	p.processResults(results)
+	require.Equal(t, "192.168.0.10", p.bestGM)
+
+	// we stick to holdover mode and mean freq
+	mockStatsServer.EXPECT().SetCounter("ptp.sptp.gms.total", int64(1))
+	mockStatsServer.EXPECT().SetCounter("ptp.sptp.gms.available_pct", int64(100))
+	mockStatsServer.EXPECT().SetCounter("ptp.sptp.tick_duration_ns", gomock.Any())
+	mockStatsServer.EXPECT().SetGMStats(gomock.Any())
+	p.processResults(results)
+	require.Equal(t, "192.168.0.10", p.bestGM)
+}
+
 func TestProcessResultsMulti(t *testing.T) {
 	ts, err := time.Parse(time.RFC3339, "2021-05-21T13:32:05+01:00")
 	require.Nil(t, err)
@@ -204,6 +259,9 @@ func TestProcessResultsMulti(t *testing.T) {
 	p.processResults(results)
 	require.Equal(t, "192.168.0.10", p.bestGM)
 
+	// we have to wait a second to avoid "samples are too fast" error
+	time.Sleep(time.Second)
+
 	results["192.168.0.10"].Measurement.Offset = -100001 * time.Microsecond
 	results["192.168.0.11"].Error = nil
 	results["192.168.0.11"].Measurement = &MeasurementResult{