void
updateDelay(Filter * owd_filt, RunTimeOpts * rtOpts, PtpClock * ptpClock, TimeInternal * correctionField)
{
/* updates paused, leap second pending - do nothing */
if(ptpClock->leapSecondInProgress)
return;
DBGV("updateDelay\n");
/* todo: do all intermediate calculations on temp vars */
TimeInternal prev_meanPathDelay = ptpClock->meanPathDelay;
ptpClock->char_last_msg = 'D';
{
//perform basic checks, using local variables only
TimeInternal slave_to_master_delay;
/* calc 'slave_to_master_delay' */
subTime(&slave_to_master_delay, &ptpClock->delay_req_receive_time,
&ptpClock->delay_req_send_time);
if (rtOpts->maxDelay && /* If maxDelay is 0 then it's OFF */
rtOpts->offset_first_updated) {
if ((slave_to_master_delay.nanoseconds < 0) &&
(abs(slave_to_master_delay.nanoseconds) > rtOpts->maxDelay)) {
INFO("updateDelay aborted, "
"delay (sec: %d ns: %d) is negative\n",
slave_to_master_delay.seconds,
slave_to_master_delay.nanoseconds);
INFO("send (sec: %d ns: %d)\n",
ptpClock->delay_req_send_time.seconds,
ptpClock->delay_req_send_time.nanoseconds);
INFO("recv (sec: %d n s: %d)\n",
ptpClock->delay_req_receive_time.seconds,
ptpClock->delay_req_receive_time.nanoseconds);
goto display;
}
if (slave_to_master_delay.seconds && rtOpts->maxDelay) {
INFO("updateDelay aborted, delay %d.%d greater than 1 second\n",
slave_to_master_delay.seconds,
slave_to_master_delay.nanoseconds);
if (rtOpts->displayPackets)
msgDump(ptpClock);
goto display;
}
if (slave_to_master_delay.nanoseconds > rtOpts->maxDelay) {
INFO("updateDelay aborted, delay %d greater than "
"administratively set maximum %d\n",
slave_to_master_delay.nanoseconds,
rtOpts->maxDelay);
if (rtOpts->displayPackets)
msgDump(ptpClock);
goto display;
}
}
}
/*
* The packet has passed basic checks, so we'll:
* - update the global delaySM variable
* - calculate a new filtered MPD
*/
if (rtOpts->offset_first_updated) {
/*
* calc 'slave_to_master_delay' (Master to Slave delay is
* already computed in updateOffset )
*/
DBG("==> UpdateDelay(): %s\n",
dump_TimeInternal2("Req_RECV:", &ptpClock->delay_req_receive_time,
"Req_SENT:", &ptpClock->delay_req_send_time));
#ifdef PTPD_STATISTICS
if (rtOpts->delaySMOutlierFilterEnabled) {
subTime(&ptpClock->rawDelaySM, &ptpClock->delay_req_receive_time,
&ptpClock->delay_req_send_time);
if(!isDoublePeircesOutlier(ptpClock->delaySMRawStats, timeInternalToDouble(&ptpClock->rawDelaySM), rtOpts->delaySMOutlierFilterThreshold)) {
ptpClock->delaySM = ptpClock->rawDelaySM;
ptpClock->delaySMoutlier = FALSE;
} else {
ptpClock->delaySMoutlier = TRUE;
ptpClock->counters.delaySMOutliersFound++;
if (!rtOpts->delaySMOutlierFilterDiscard) {
ptpClock->delaySM = doubleToTimeInternal(ptpClock->delaySMFiltered->mean);
} else {
goto statistics;
}
}
} else {
subTime(&ptpClock->delaySM, &ptpClock->delay_req_receive_time,
&ptpClock->delay_req_send_time);
}
#else
subTime(&ptpClock->delaySM, &ptpClock->delay_req_receive_time,
&ptpClock->delay_req_send_time);
#endif
/* update 'one_way_delay' */
addTime(&ptpClock->meanPathDelay, &ptpClock->delaySM,
&ptpClock->delayMS);
/* Substract correctionField */
subTime(&ptpClock->meanPathDelay, &ptpClock->meanPathDelay,
correctionField);
/* Compute one-way delay */
div2Time(&ptpClock->meanPathDelay);
if (ptpClock->meanPathDelay.seconds) {
DBG("update delay: cannot filter with large OFM, "
"clearing filter\n");
INFO("Servo: Ignoring delayResp because of large OFM\n");
FilterClear(owd_filt);
/* revert back to previous value */
ptpClock->meanPathDelay = prev_meanPathDelay;
goto display;
}
if(ptpClock->meanPathDelay.nanoseconds < 0){
DBG("update delay: found negative value for OWD, "
"so ignoring this value: %d\n",
ptpClock->meanPathDelay.nanoseconds);
/* revert back to previous value */
ptpClock->meanPathDelay = prev_meanPathDelay;
#ifdef PTPD_STATISTICS
goto statistics;
#else
goto display;
#endif /* PTPD_STATISTICS */
}
{
// TODO: remove hack
char s_text[32];
sprintf(s_text, "%d", rtOpts->s);
FilterConfigure(owd_filt, "stiffness", s_text);
}
FilterFeed(owd_filt, &ptpClock->meanPathDelay.nanoseconds);
/* Update relevant statistics containers, feed outlier filter thresholds etc. */
#ifdef PTPD_STATISTICS
statistics:
if (rtOpts->delaySMOutlierFilterEnabled) {
double dDelaySM = timeInternalToDouble(&ptpClock->rawDelaySM);
/* If this is an outlier, bring it by a factor closer to mean before allowing to influence stdDev */
if(ptpClock->delaySMoutlier) {
/* Allow [weight] * [deviation from mean] to influence std dev in the next outlier checks */
DBG("DelaySM outlier: %.09f\n", dDelaySM);
if((rtOpts->calibrationDelay<1) || ptpClock->isCalibrated)
dDelaySM = ptpClock->delaySMRawStats->meanContainer->mean + rtOpts->delaySMOutlierWeight * ( dDelaySM - ptpClock->delaySMRawStats->meanContainer->mean);
}
feedDoubleMovingStdDev(ptpClock->delaySMRawStats, dDelaySM);
feedDoubleMovingMean(ptpClock->delaySMFiltered, timeInternalToDouble(&ptpClock->delaySM));
}
feedDoublePermanentStdDev(&ptpClock->slaveStats.owdStats, timeInternalToDouble(&ptpClock->meanPathDelay));
#endif
DBGV("delay filter %d\n", ptpClock->meanPathDelay.nanoseconds);
} else {
INFO("Ignoring delayResp because we didn't receive any sync yet\n");
}
display:
logStatistics(rtOpts, ptpClock);
}
void
updateClock(RunTimeOpts * rtOpts, PtpClock * ptpClock)
{
/* updates paused, leap second pending - do nothing */
if(ptpClock->leapSecondInProgress)
return;
DBGV("==> updateClock\n");
if(ptpClock->panicMode) {
DBG("Panic mode - skipping updateClock");
}
/*
if(rtOpts->delayMSOutlierFilterEnabled && rtOpts->delayMSOutlierFilterDiscard && ptpClock->delayMSoutlier)
goto display;
*/
if (rtOpts->maxReset) { /* If maxReset is 0 then it's OFF */
if (ptpClock->offsetFromMaster.seconds && rtOpts->maxReset) {
INFO("updateClock aborted, offset greater than 1"
" second.");
if (rtOpts->displayPackets)
msgDump(ptpClock);
goto display;
}
if (ptpClock->offsetFromMaster.nanoseconds > rtOpts->maxReset) {
INFO("updateClock aborted, offset %d greater than "
"administratively set maximum %d\n",
ptpClock->offsetFromMaster.nanoseconds,
rtOpts->maxReset);
if (rtOpts->displayPackets)
msgDump(ptpClock);
goto display;
}
}
if (ptpClock->offsetFromMaster.seconds) {
/* if secs, reset clock or set freq adjustment to max */
/*
if offset from master seconds is non-zero, then this is a "big jump:
in time. Check Run Time options to see if we will reset the clock or
set frequency adjustment to max to adjust the time
*/
/*
* noAdjust = cannot do any change to clock
* noResetClock = if can change the clock, can we also step it?
*/
if (!rtOpts->noAdjust) {
if(rtOpts->enablePanicMode && !ptpClock->panicOver) {
if(ptpClock->panicMode)
goto display;
if(ptpClock->panicOver) {
ptpClock->panicMode = FALSE;
ptpClock->panicOver = FALSE;
#ifdef PTPD_STATISTICS
ptpClock->isCalibrated = FALSE;
#endif /* PTPD_STATISTICS */
goto display;
}
CRITICAL("Offset above 1 second - entering panic mode\n");
ptpClock->panicMode = TRUE;
ptpClock->panicModeTimeLeft = 2 * rtOpts->panicModeDuration;
timerStart(PANIC_MODE_TIMER, 30, ptpClock->itimer);
#ifdef PTPD_NTPDC
/* Trigger NTP failover as part of panic mode */
if(rtOpts->ntpOptions.enableEngine && rtOpts->panicModeNtp) {
/* Make sure we log ntp control errors now */
ptpClock->ntpControl.requestFailed = FALSE;
/* We have a timeout defined */
if(rtOpts->ntpOptions.failoverTimeout) {
DBG("NTP failover timer started - panic mode\n");
timerStart(NTPD_FAILOVER_TIMER,
rtOpts->ntpOptions.failoverTimeout,
ptpClock->itimer);
/* Fail over to NTP straight away */
} else {
DBG("Initiating NTP failover\n");
ptpClock->ntpControl.isRequired = TRUE;
ptpClock->ntpControl.isFailOver = TRUE;
if(!ntpdControl(&rtOpts->ntpOptions, &ptpClock->ntpControl, FALSE))
DBG("PANIC MODE instant NTP failover - could not fail over\n");
}
}
#endif /* PTPD_NTPDC */
goto display;
}
if(rtOpts->enablePanicMode) {
if(ptpClock->panicOver)
CRITICAL("Panic mode timeout - accepting current offset. Clock will jump\n");
ptpClock->panicOver = FALSE;
timerStop(PANIC_MODE_TIMER, ptpClock->itimer);
#ifdef PTPD_NTPDC
/* Exiting ntp failover - getting out of panic mode */
if(rtOpts->ntpOptions.enableEngine && rtOpts->panicModeNtp) {
timerStop(NTPD_FAILOVER_TIMER, ptpClock->itimer);
ptpClock->ntpControl.isRequired = FALSE;
ptpClock->ntpControl.isFailOver = FALSE;
if(!ntpdControl(&rtOpts->ntpOptions, &ptpClock->ntpControl, FALSE))
DBG("NTPdcontrol - could not return from NTP panic mode\n");
}
#endif /* PTPD_NTPDC */
}
if (!rtOpts->noResetClock) {
servo_perform_clock_step(rtOpts, ptpClock);
} else {
#ifdef HAVE_SYS_TIMEX_H
if(ptpClock->offsetFromMaster.nanoseconds > 0)
ptpClock->servo.observedDrift = rtOpts->servoMaxPpb;
else
ptpClock->servo.observedDrift = -rtOpts->servoMaxPpb;
warn_operator_slow_slewing(rtOpts, ptpClock);
adjFreq_wrapper(rtOpts, ptpClock, -ptpClock->servo.observedDrift);
/* its not clear how the APPLE case works for large jumps */
#endif /* HAVE_SYS_TIMEX_H */
}
}
} else {
/* If we're in panic mode, either exit if no threshold configured, or exit if we're outside the exit threshold */
if(rtOpts->enablePanicMode &&
((ptpClock->panicMode && ( rtOpts->panicModeExitThreshold == 0 || ((rtOpts->panicModeExitThreshold > 0) && ((ptpClock->offsetFromMaster.seconds == 0) && (ptpClock->offsetFromMaster.nanoseconds < rtOpts->panicModeExitThreshold)))) ) || ptpClock->panicOver)) {
ptpClock->panicMode = FALSE;
ptpClock->panicOver = FALSE;
timerStop(PANIC_MODE_TIMER, ptpClock->itimer);
NOTICE("Offset below 1 second again: exiting panic mode\n");
#ifdef PTPD_NTPDC
/* exiting ntp failover - panic mode over */
if(rtOpts->ntpOptions.enableEngine && rtOpts->panicModeNtp) {
timerStop(NTPD_FAILOVER_TIMER, ptpClock->itimer);
ptpClock->ntpControl.isRequired = FALSE;
ptpClock->ntpControl.isFailOver = FALSE;
if(!ntpdControl(&rtOpts->ntpOptions, &ptpClock->ntpControl, FALSE))
DBG("NTPdcontrol - could not return from NTP panic mode\n");
}
#endif /* PTPD_NTPDC */
}
/* Servo dT is the log sync interval */
/* TODO: if logsyincinterval is 127 [unicast], switch to measured */
if(rtOpts->servoDtMethod == DT_CONSTANT)
ptpClock->servo.logdT = ptpClock->logSyncInterval;
/* If the last delayMS was an outlier and filter action is discard, skip servo run */
#ifdef PTPD_STATISTICS
if(rtOpts->delayMSOutlierFilterEnabled && rtOpts->delayMSOutlierFilterDiscard && ptpClock->delayMSoutlier)
goto statistics;
#endif /* PTPD_STATISTICS */
#ifndef HAVE_SYS_TIMEX_H
adjTime(ptpClock->offsetFromMaster.nanoseconds);
#else
#ifdef PTPD_STATISTICS
/* if statistics are enabled, only run the servo if we are calibrted - if calibration delay configured */
if(!rtOpts->calibrationDelay || ptpClock->isCalibrated)
#endif /*PTPD_STATISTICS */
/* Adjust the clock first -> the PI controller runs here */
adjFreq_wrapper(rtOpts, ptpClock, runPIservo(&ptpClock->servo, ptpClock->offsetFromMaster.nanoseconds));
/* Unset STA_UNSYNC */
unsetTimexFlags(STA_UNSYNC, TRUE);
/* "Tell" the clock about maxerror, esterror etc. */
informClockSource(ptpClock);
#endif /* HAVE_SYS_TIMEX_H */
}
/* Update relevant statistics containers, feed outlier filter thresholds etc. */
#ifdef PTPD_STATISTICS
statistics:
if (rtOpts->delayMSOutlierFilterEnabled) {
double dDelayMS = timeInternalToDouble(&ptpClock->rawDelayMS);
if(ptpClock->delayMSoutlier) {
/* Allow [weight] * [deviation from mean] to influence std dev in the next outlier checks */
DBG("DelayMS Outlier: %.09f\n", dDelayMS);
dDelayMS = ptpClock->delayMSRawStats->meanContainer->mean +
rtOpts->delayMSOutlierWeight * ( dDelayMS - ptpClock->delayMSRawStats->meanContainer->mean);
}
feedDoubleMovingStdDev(ptpClock->delayMSRawStats, dDelayMS);
feedDoubleMovingMean(ptpClock->delayMSFiltered, timeInternalToDouble(&ptpClock->delayMS));
}
feedDoublePermanentStdDev(&ptpClock->slaveStats.ofmStats, timeInternalToDouble(&ptpClock->offsetFromMaster));
feedDoublePermanentStdDev(&ptpClock->servo.driftStats, ptpClock->servo.observedDrift);
#endif /* PTPD_STATISTICS */
display:
logStatistics(rtOpts, ptpClock);
DBGV("\n--Offset Correction-- \n");
DBGV("Raw offset from master: %10ds %11dns\n",
ptpClock->delayMS.seconds,
ptpClock->delayMS.nanoseconds);
DBGV("\n--Offset and Delay filtered-- \n");
if (ptpClock->delayMechanism == P2P) {
DBGV("one-way delay averaged (P2P): %10ds %11dns\n",
ptpClock->peerMeanPathDelay.seconds,
ptpClock->peerMeanPathDelay.nanoseconds);
} else if (ptpClock->delayMechanism == E2E) {
DBGV("one-way delay averaged (E2E): %10ds %11dns\n",
ptpClock->meanPathDelay.seconds,
ptpClock->meanPathDelay.nanoseconds);
}
DBGV("offset from master: %10ds %11dns\n",
ptpClock->offsetFromMaster.seconds,
ptpClock->offsetFromMaster.nanoseconds);
DBGV("observed drift: %10d\n", ptpClock->servo.observedDrift);
}
/* 2 x fairy dust, 3 x unicorn droppings, 1 x magic beanstalk juice. blend, spray on the affected area twice per day */
static Boolean
outlierFilterFilter(OutlierFilter *filter, double sample)
{
/* true = accepted - this is to tell the user if we advised to throw away the sample */
Boolean ret = TRUE;
/* step change: outlier mean - accepted mean from last sampling period */
double step = 0.0;
if(!filter->config.enabled) {
filter->output = sample;
return TRUE;
}
step = fabs(filter->outlierStats.mean - filter->acceptedStats.bufferedMean);
if(filter->config.autoTune) {
filter->autoTuneSamples++;
}
/* no outlier first - more convenient this way */
if(!isDoublePeircesOutlier(filter->rawStats, sample, filter->threshold) && (filter->delay == 0)) {
filter->lastOutlier = FALSE;
filter->output = sample;
/* filter is about to accept after a blocking period */
if(filter->consecutiveOutliers) {
DBG_LOCAL_ID(filter,"consecutive: %d, mean: %.09fm accepted bmean: %.09f\n", filter->consecutiveOutliers,
filter->outlierStats.mean,filter->acceptedStats.bufferedMean);
/* we are about to open up but the offset has risen above step level, we will block again, but not forever */
if(filter->config.stepDelay &&
(fabs(filter->acceptedStats.bufferedMean) < ((filter->config.stepThreshold + 0.0) / 1E9)) &&
(step > ((filter->config.stepLevel + 0.0) / 1E9))) {
/* if we're to enter blocking, we need 2 * consecutiveOutliers credit */
/* if we're already blocking, we just need enough credit */
/* if we're already blocking, make sure we block no more than maxDelay */
if((filter->blocking && ((filter->config.maxDelay > filter->totalDelay) && (filter->delayCredit >= filter->consecutiveOutliers))) ||
(!filter->blocking && (filter->delayCredit >= filter->consecutiveOutliers * 2 ))) {
if(!filter->blocking) {
INFO_LOCAL_ID(filter,"%.03f us step detected, filter will now block\n", step * 1E6);
}
DBG_LOCAL_ID(filter,"step: %.09f, credit left %d, requesting %d\n",step,
filter->delayCredit, filter->consecutiveOutliers);
filter->delay = filter->consecutiveOutliers;
filter->totalDelay += filter->consecutiveOutliers;
filter->delayCredit -= filter->consecutiveOutliers;
filter->blocking = TRUE;
resetDoublePermanentMean(&filter->outlierStats);
filter->lastOutlier = TRUE;
DBG_LOCAL_ID(filter,"maxdelay: %d, totaldelay: %d\n",filter->config.maxDelay, filter->totalDelay);
return FALSE;
/* much love for the ultra magnetic, cause everybody knows you never got enough credit */
/* we either ran out of credit while blocking, or we did not have enough to start with */
} else {
if(filter->blocking) {
INFO_LOCAL_ID(filter,"blocking time exhausted, filter will stop blocking\n");
} else {
INFO_LOCAL_ID(filter,"%.03f us step detected but filter cannot block\n", step * 1E6);
}
DBG_LOCAL_ID(filter,"credit out (has %d, needed %d)\n", filter->delayCredit, filter->consecutiveOutliers);
}
/* NO STEP */
} else {
if (filter->blocking) {
INFO_LOCAL_ID(filter,"step event over, filter will stop blocking\n");
}
filter->blocking = FALSE;
}
if(filter->totalDelay != 0) {
DBG_LOCAL_ID(filter,"Total waited %d\n", filter->totalDelay);
filter->totalDelay = 0;
}
}
filter->consecutiveOutliers = 0;
resetDoublePermanentMean(&filter->outlierStats);
feedDoublePermanentMean(&filter->acceptedStats, sample);
/* it's an outlier, Sir! */
} else {
filter->lastOutlier = TRUE;
feedDoublePermanentMean(&filter->outlierStats, sample);
if(filter->delay) {
DBG_LOCAL_ID(filter,"delay left: %d\n", filter->delay);
filter->delay--;
return FALSE;
}
filter->autoTuneOutliers++;
filter->consecutiveOutliers++;
if(filter->config.discard) {
ret = FALSE;
} else {
filter->output = filter->filteredStats->mean;
}
DBG_LOCAL_ID(filter,"Outlier: %.09f\n", sample);
/* Allow [weight] * [deviation from mean] to influence std dev in the next outlier checks */
sample = filter->rawStats->meanContainer->mean + filter->config.weight * ( sample - filter->rawStats->meanContainer->mean);
}
/* keep stats containers updated */
feedDoubleMovingStdDev(filter->rawStats, sample);
feedDoubleMovingMean(filter->filteredStats, filter->output);
/* re-tune filter twice per window */
if( (filter->rawStats->meanContainer->counter % ( filter->rawStats->meanContainer->capacity / 2)) == 0) {
outlierFilterTune(filter);
}
/* replenish filter credit once per window */
if( filter->config.stepDelay && ((filter->rawStats->meanContainer->counter % filter->rawStats->meanContainer->capacity) == 0)) {
filter->delayCredit += filter->config.creditIncrement;
if(filter->delayCredit >= filter->config.delayCredit) {
filter->delayCredit = filter->config.delayCredit;
}
DBG_LOCAL_ID(filter,"credit added, now %d\n", filter->delayCredit);
}
return ret;
}