diff --git a/ptp/sptp/client/sptp.go b/ptp/sptp/client/sptp.go index 0c478ae6..8e4f9dad 100644 --- a/ptp/sptp/client/sptp.go +++ b/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 { diff --git a/ptp/sptp/client/sptp_test.go b/ptp/sptp/client/sptp_test.go index da17729d..22ee26da 100644 --- a/ptp/sptp/client/sptp_test.go +++ b/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{