When clocks diverge too much, packet sources might schedule packets into the past, resulting in error

[adamgeorge309]

When clocks diverge too much, it results in this error:

Cannot schedule message (inet::ClockEvent)ProductionTimer to the past, t=0.0469998 -- in module (inet::queueing::ActivePacketSource) ClockDriftShowcase.source2.app[0].source (id=208), at t=0.047s, event #142502

For reproduction: run OutOfBandSynchronizationRandomDrift config

NED:

//
// SPDX-License-Identifier: LGPL-3.0-or-later
//

package inet.showcases.tsn.timesynchronization.clockdrift;

import inet.networks.base.WiredNetworkBase;
import inet.node.ethernet.Eth1G;
import inet.node.ethernet.EthernetSwitch;
import inet.node.inet.StandardHost;

network ClockDriftShowcase extends WiredNetworkBase
{
    submodules:
        source1: StandardHost {
            @display("p=300,100");
        }
        source2: StandardHost {
            @display("p=300,300");
        }
        switch1: EthernetSwitch {
            @display("p=500,200");
        }
        switch2: EthernetSwitch {
            @display("p=700,200");
        }
        sink1: StandardHost {
            @display("p=900,100");
        }
        sink2: StandardHost {
            @display("p=900,300");
        }
    connections:
        switch1.ethg++ <--> Eth1G <--> switch2.ethg++;
        source1.ethg++ <--> Eth1G <--> switch1.ethg++;
        source2.ethg++ <--> Eth1G <--> switch1.ethg++;
        switch2.ethg++ <--> Eth1G <--> sink1.ethg++;
        switch2.ethg++ <--> Eth1G <--> sink2.ethg++;
}

INI:

[General]
network = ClockDriftShowcase
sim-time-limit = 0.1s

*.*.ethernet.typename = "EthernetLayer"

**.hasGlobalArp = true

*.source*.numApps = 1
*.source*.app[*].typename = "UdpSourceApp"
*.source*.app[0].source.packetLength = 800B
*.source*.app[0].source.productionInterval = 20us
*.source*.app[0].io.destPort = 1000

*.source1.app[0].io.destAddress = "sink1"
*.source1.app[0].source.packetNameFormat = "source1-%c"

*.source2.app[0].io.destAddress = "sink2"
*.source2.app[0].source.initialProductionOffset = 10us
*.source2.app[0].source.packetNameFormat = "source2-%c"

*.sink*.numApps = 1
*.sink*.app[*].typename = "UdpSinkApp"
*.sink*.app[0].io.localPort = 1000

*.*.eth[*].typename = "LayeredEthernetInterface"
*.*.eth[*].bitrate = 1Gbps
*.switch1.eth[0].macLayer.queue.typename = "GatingPriorityQueue"
*.switch1.eth[0].macLayer.queue.numQueues = 2
*.switch1.eth[0].macLayer.queue.classifier.typename = "ContentBasedClassifier"
*.switch1.eth[0].macLayer.queue.classifier.packetFilters = ["source1*", "source2*"]
*.switch1.eth[0].macLayer.queue.queue[*].typename = "DropTailQueue"
*.switch1.eth[0].macLayer.queue.gate[*].initiallyOpen = false
*.switch1.eth[0].macLayer.queue.gate[*].durations = [10us, 10us]
*.switch1.eth[0].macLayer.queue.gate[1].offset = 10us

[Config RandomClockDriftRate]
description = "Clocks with random drift rate"

*.source*.clock.typename = "OscillatorBasedClock"
*.source*.clock.oscillator.typename = "RandomDriftOscillator"
*.source1.clock.oscillator.driftRateChange = intuniform(-500ppm, 500ppm)
*.source2.clock.oscillator.driftRateChange = intuniform(-400ppm, 400ppm)
*.source1.clock.oscillator.changeInterval = 0.1ms
*.source2.clock.oscillator.changeInterval = 0.1ms
*.source*.app[0].source.clockModule = "^.^.clock"

*.switch1.clock.typename = "OscillatorBasedClock"
*.switch1.clock.oscillator.typename = "RandomDriftOscillator"
*.switch1.clock.oscillator.driftRateChange = intuniform(-300ppm, 300ppm)
*.switch1.clock.oscillator.changeInterval = 0.1ms
*.switch1.eth[0].macLayer.queue.gate[*].clockModule = "^.^.^.^.clock"

[Config OutOfBandSynchronizationRandomDrift]
description = "Clocks are periodically synchronized out-of-band, without a real protocol. Clocks use random drift oscillators."
extends = RandomClockDriftRate

*.source*.clock.typename = "SettableClock"
*.source*.clock.defaultOverdueClockEventHandlingMode = "execute"

*.source*.numApps = 2
*.source*.app[1].typename = "SimpleClockSynchronizer"
*.source*.app[1].masterClockModule = "^.^.switch1.clock"
*.source*.app[1].slaveClockModule = "^.clock"
*.source*.app[1].synchronizationInterval = 500us
*.source*.app[1].synchronizationClockTimeError = uniform(-10ns, 10ns)

[levy]

I analyzed this problem and here is what I found.

The clock time of a SettableClock is changed (e.g. from 100 -> 200) such that there are clock events which are overdue. In the above configuration overdue events are to be executed, but that means they have to be rescheduled for the current simulation time. Unfortunately, it's not possible to execute them right away while the clock is being set from 100 to 200, and rescheduling them for execution is also wrong because the clock will be already set to 200, so an event at clock time 150 will execute at 200.

The above exception comes when the completely unrelated drifting oscillator changes its drift rate (by a random walk process) and the clock wants to reschedule all to be executed events according to the new drift rate. The clock suddenly finds an event that needs to be rescheduled, which has an arrival clock time in the past. This should not normally happen, but the event was overdue at the last time the clock was set (e.g. moved forward from 100 to 200), and the event was not executed at that moment.

I still need to investigate this further to figure out what is the correct solution.