diff options
author | Eyrak Paen | 2021-05-12 17:28:10 +0000 |
---|---|---|
committer | Eyrak Paen | 2021-06-10 13:28:29 +0000 |
commit | 3d46aebbcf54bd9e2fa8a46928078be938933a68 (patch) | |
tree | e4a942c744629b223de2d304511ccdf8b1b160d0 | |
parent | 048540fb1d7b77341bc273fae46cb0e62c452337 (diff) | |
download | org.eclipse.etrice-3d46aebbcf54bd9e2fa8a46928078be938933a68.tar.gz org.eclipse.etrice-3d46aebbcf54bd9e2fa8a46928078be938933a68.tar.xz org.eclipse.etrice-3d46aebbcf54bd9e2fa8a46928078be938933a68.zip |
[modellib.c] Add ATimerService late timeout recovery
- Also refactor test structure and allow testing with simulated time
Bug: 573233
Change-Id: I8d17fdb8ab9a5f4d7582019ec000022f2b42bdb0
3 files changed, 332 insertions, 133 deletions
diff --git a/runtime/org.eclipse.etrice.modellib.c/model/etrice/api/timer.room b/runtime/org.eclipse.etrice.modellib.c/model/etrice/api/timer.room index 5f23f487e..e4f24aecd 100644 --- a/runtime/org.eclipse.etrice.modellib.c/model/etrice/api/timer.room +++ b/runtime/org.eclipse.etrice.modellib.c/model/etrice/api/timer.room @@ -92,7 +92,18 @@ RoomModel etrice.api.timer { } } - /** Provides a service to create and control timer. */ + /** + * Provides a service to create and control timers. The service runs according to the polling + * interval of its assigned physical thread, meaning that the effective resolution of the + * timeouts sent by the service is bounded by the polling interval. + * + * <p><b>Late Periodic Timeout Recovery:</b><br/> + * It is possible that a periodic timeout is late enough, that the next scheduled timeout + * would already be in the past. In this case, the service will attempt to recover by + * rescheduling the timeout for the current time plus period interval. This recovery attempt is + * intended to mitigate the scenario where too many late timeouts overrun the message service. + * </p> + */ async ActorClass ATimerService { Interface { SPP timer: PTimer @@ -220,6 +231,10 @@ RoomModel etrice.api.timer { t1->nSec-=1000000000L; }''' + Operation getTime(t: targetTime ref) ''' + getTimeFromTarget(t); + ''' + // Operation printList(){ // "etTimerControlBlock* temp=usedTcbsRoot;" // " printf(\"list: \");" @@ -257,7 +272,7 @@ RoomModel etrice.api.timer { timer->pTime.sec = 0; timer->pTime.nSec = 0; timer->portIdx=((etReplSubPort*)ifitem)->index; - getTimeFromTarget(&(timer->expTime)); + getTime(&(timer->expTime)); addTime(&(timer->expTime),&t); putTcbToUsedList(timer); }''' @@ -274,7 +289,7 @@ RoomModel etrice.api.timer { t.nSec=(transitionData%1000)*1000000L; timer->pTime = t; timer->portIdx=((etReplSubPort*)ifitem)->index; - getTimeFromTarget(&(timer->expTime)); + getTime(&(timer->expTime)); addTime(&(timer->expTime),&t); putTcbToUsedList(timer); }''' @@ -292,29 +307,37 @@ RoomModel etrice.api.timer { etTimerControlBlock* temp; etTime t; - getTimeFromTarget(&t); - while (usedTcbsRoot !=0 ){ - if (isTimeGreater(&t,&(usedTcbsRoot->expTime))){ + getTime(&t); + while (usedTcbsRoot !=0 ) { + if (isTimeGreater(&t,&(usedTcbsRoot->expTime))) { // maintain deviation hig water mark - subTime(&t, &(usedTcbsRoot->expTime)); - if (isTimeGreater(&t,&timerDeviationHighWaterMark)){ - timerDeviationHighWaterMark = t; - } + etTime delta = t; + subTime(&delta, &(usedTcbsRoot->expTime)); + if (isTimeGreater(&delta,&timerDeviationHighWaterMark)) { + timerDeviationHighWaterMark = delta; + } timer[usedTcbsRoot->portIdx].timeout(); temp=usedTcbsRoot; usedTcbsRoot=usedTcbsRoot->next; - if((temp->pTime.sec==0)&&(temp->pTime.nSec==0)){ + if((temp->pTime.sec==0)&&(temp->pTime.nSec==0)) { /* single shot timer */ returnTcb(temp); - }else{ + } else { /* periodic timer */ addTime(&temp->expTime,&temp->pTime); - putTcbToUsedList(temp); + // if new expiry time is before current time, recover and notify + if (isTimeGreater(&t, &(temp->expTime))) { + temp->expTime = t; + addTime(&(temp->expTime), &(temp->pTime)); + etLogger_logError("ATimerService: late periodic timeout dropped and rescheduled!"); } - }else{ - break; - } - }''' + putTcbToUsedList(temp); + } + } else { + break; + } + } + ''' } Transition tr2: Operational -> Operational { triggers { diff --git a/tests/org.eclipse.etrice.generator.c.tests/model/timerServiceTest/TimerServiceTest.etphys b/tests/org.eclipse.etrice.generator.c.tests/model/timerServiceTest/TimerServiceTest.etphys index 1dafcb534..f76c76fe1 100644 --- a/tests/org.eclipse.etrice.generator.c.tests/model/timerServiceTest/TimerServiceTest.etphys +++ b/tests/org.eclipse.etrice.generator.c.tests/model/timerServiceTest/TimerServiceTest.etphys @@ -10,7 +10,7 @@ PhysicalModel TimerServiceTest { priomax = 10 DefaultThread DefaultPhysicalThread { execmode = mixed - interval = 300ms + interval = 10ms prio = 0 stacksize = 1024 msgblocksize = 64 @@ -19,7 +19,7 @@ PhysicalModel TimerServiceTest { } RuntimeClass DefaultRuntimeClass { - model = multiThreaded + model = singleThreaded } } diff --git a/tests/org.eclipse.etrice.generator.c.tests/model/timerServiceTest/TimerServiceTest.room b/tests/org.eclipse.etrice.generator.c.tests/model/timerServiceTest/TimerServiceTest.room index 42c96182e..d99f501aa 100644 --- a/tests/org.eclipse.etrice.generator.c.tests/model/timerServiceTest/TimerServiceTest.room +++ b/tests/org.eclipse.etrice.generator.c.tests/model/timerServiceTest/TimerServiceTest.room @@ -1,127 +1,131 @@ /** * Functional tests for etrice.api.timer.ATimerService and related etrice model API. * - * NOTE: These tests assume that the standard etrice platform implementation is used, which means - * that they will rely on the underlying OS timing and thread behavior. Consider implementing a - * partially stubbed runtime with simulated timing and scheduling, if this causes issues in CI. + * NOTE: These tests extends the ATimerService class to allow setting simulated time for testing. */ RoomModel TimerServiceTest { import etrice.api.types.* import etrice.api.timer.ATimerService import etrice.api.timer.PTimer + import etrice.api.timer.targetTime import etrice.api.testcontrol.PTestControl import etrice.api.testcontrol.ControllableSequentialTestExecutor - /** - * ATimerService should send a timeout once per the expected number of polling intervals, - * given the timer interval specified with setTimer. + /** + * Extended ATimerService used by the test cases. Overrides getTime Operation so that simulated + * target time can be injected into the ATimerService. Time can be set with the added + * PTimeTestCtl SPP. The reason why this is not just done in the actor StateMachine is to avoid + * overriding internal StateMachine behavior of the ATimerService under test. + * + * NOTE: Only one PTimeTestCtl SAP should be active at any given time. The getTime operation + * will cycle through all SAPs and select the time from the first enabled one. + * */ - async ActorClass APolledPeriodicTimeoutTest { + async ActorClass ATimerServiceOverrideGetTime extends ATimerService { Interface { - Port ctl: PTestControl + SPP testTimeCtl: PTestTimeControl } Structure { - usercode2 ''' - #include <etUnit/etUnit.h> - #include <helpers/etTimeHelpers.h> - ''' - usercode3 ''' - enum TestEventEnum { - TESTEVENT_POLLING_CYCLE, - TESTEVENT_TIMEOUT, - TESTEVENT_END - }; + ServiceImplementation of testTimeCtl + } + Behavior { + override Operation getTime(t: targetTime ref) ''' + t->sec = 0; + t->nSec = 0; + PTestTimeControlConjReplPort* replPort = (PTestTimeControlConjReplPort*)&self->constData->testTimeCtl; + etInt32 numPorts = PTestTimeControlConjReplPort_getReplication(replPort); + for (etInt32 i = 0; i < numPorts; ++i) { + PTestTimeControlConjPort* port = (PTestTimeControlConjPort*)&replPort->ports[i].port; + if (PTestTimeControlPort_isTestControlEnabled(port)) { + PTestTimeControlPort_getTestControlTime(port, t); + break; + } + } ''' - external Port ctl - SAP timer: PTimer - Attribute testId: int16 - Attribute startTime: int32 - Attribute pollingCycles: int32 - Attribute timeouts: int32 } + } + + /** + * ATimerService should send a timeout once per the expected number of polling intervals, + * given the timer interval specified with setTimer. + */ + async ActorClass APolledPeriodicTimeoutTest extends APolledTimerServiceTestBase { Behavior { - ctor ''' - pollingCycles = 0; - timeouts = 0; - ''' - Operation currentTime(): int32 ''' - etTime curr; - getTimeFromTarget(&curr); - int32 result = etTimeHelpers_convertToMSec(&curr); + override Operation getTestName(): string ''' + return "ShouldSendPeriodicTimeoutsWithinExpectedPollingIntervals"; + ''' + override Operation getExpectedEvents(): DTestEvents ''' + static int16 expectedTestEvents[] = { + ETestEvent.POLLING_CYCLE, // given polling interval 300ms, startTimer 500ms at >0ms + ETestEvent.POLLING_CYCLE, + ETestEvent.POLLING_CYCLE, + ETestEvent.TIMEOUT, // timeout at 500ms -> queued during polling cycle 3 + ETestEvent.POLLING_CYCLE, + ETestEvent.POLLING_CYCLE, + ETestEvent.TIMEOUT, // timeout at 1000ms -> queued during polling cycle 5 + ETestEvent.POLLING_CYCLE, + ETestEvent.END, + }; + DTestEvents result = { + .elements = expectedTestEvents, + .size = sizeof(expectedTestEvents)/sizeof(expectedTestEvents[0]), + }; return result; ''' - StateMachine { - Transition init: initial -> Pre - State Pre - Transition start: Pre -> Running { - triggers { <start: ctl> } - action ''' - testId = etUnit_openTestCase("ShouldSendPeriodicTimeoutsWithinExpectedPollingIntervals"); - - // Define event expectations. - // NOTE: the timeout messages are dispatched after the polling handlers - // have been executed, which is why the timeout events always follow after - // the polling cycle in which they were queued. - static int16 expectedTestEvents[] = { - TESTEVENT_POLLING_CYCLE, // given polling interval 300ms, setTimer 500ms - TESTEVENT_POLLING_CYCLE, - TESTEVENT_POLLING_CYCLE, - TESTEVENT_TIMEOUT, // timeout at 500ms -> queued during polling cycle 3 at 600ms - TESTEVENT_POLLING_CYCLE, - TESTEVENT_POLLING_CYCLE, - TESTEVENT_TIMEOUT, // timeout at 1000ms -> queued during polling cycle 5 at 1200ms - TESTEVENT_POLLING_CYCLE, - TESTEVENT_END, - }; - EXPECT_ORDER_START(testId, expectedTestEvents, sizeof(expectedTestEvents)/sizeof(expectedTestEvents[0])); - ''' + override Operation doTestSequenceStep(cycle: int32) ''' + if (cycle == 0) { + // Initiate test sequence, synchronized to polling interval. + etLogger_logInfo("sending startTimer request"); + timer.startTimer(500); } - State Running { - do ''' - // Initiate test sequence, synchronized to polling interval. - // NOTE: the value of the polling interval is not available during runtime, - // so startTimer value has to be hardcoded based on etphys configuration! - if (pollingCycles == 0) { - startTime = currentTime(); - etLogger_logInfo("sending startTimer request"); - timer.startTimer(500); - } + ''' + override Operation getSimTimeIncrement(cycle: int32): targetTime ''' + etTime increment = {0, 300 * 1000000}; // 300ms + return increment; + ''' + } + } - ++pollingCycles; - etLogger_logInfoF("pollingCycles: %d, %d", pollingCycles, currentTime()-startTime); - EXPECT_ORDER(testId, "pollingCycle", TESTEVENT_POLLING_CYCLE); - ''' - } - Transition recvTimeout: Running -> Running { - triggers { <timeout:timer> } - action ''' - ++timeouts; - etLogger_logInfoF("timeout: %d (%d)", timeouts, currentTime()-startTime); - EXPECT_ORDER(testId, "timeout", TESTEVENT_TIMEOUT); - ''' - } - Transition done: Running -> Post { - guard '''timeouts == 2''' - action ''' - // End test sequence - EXPECT_ORDER_END(testId, "done", TESTEVENT_END); - timer.kill(); - etUnit_closeTestCase(testId); - ctl.done(true); - ''' - } - Transition abort: Running -> Post { - triggers { <abort: ctl> } - action ''' - timer.kill(); - EXPECT_TRUE(testId, "Aborted test", ET_FALSE); - etUnit_closeTestCase(testId); - ctl.done(true); - ''' + /** + * ATimerService should drop any periodic timeouts that are scheduled before the current time. + */ + async ActorClass ADroppedPeriodicTimeoutTest extends APolledTimerServiceTestBase { + Behavior { + override Operation getTestName(): string ''' + return "ShouldDropPeriodicTimeoutsScheduledBeforeCurrentTargetTime"; + ''' + override Operation getExpectedEvents(): DTestEvents ''' + static int16 expectedTestEvents[] = { + ETestEvent.POLLING_CYCLE, + ETestEvent.POLLING_CYCLE, + // timeout at 100ms -> scheduled at polling cycle 300ms, next timeout at + // 200ms is in the past, so should be dropped and rescheduled for 400ms + ETestEvent.TIMEOUT, + ETestEvent.POLLING_CYCLE, + // timeout at 400ms -> scheduled at polling cycle 600ms, next timeout at + // 500ms is in the past, so should be dropped and rescheduled for 700ms + ETestEvent.TIMEOUT, + ETestEvent.POLLING_CYCLE, + ETestEvent.END, + }; + DTestEvents result = { + .elements = expectedTestEvents, + .size = sizeof(expectedTestEvents)/sizeof(expectedTestEvents[0]), + }; + return result; + ''' + override Operation doTestSequenceStep(cycle: int32) ''' + if (cycle == 0) { + // Initiate test sequence, synchronized to polling interval. + etLogger_logInfo("sending startTimer request"); + timer.startTimer(100); } - State Post - } + ''' + override Operation getSimTimeIncrement(cycle: int32): targetTime ''' + etTime increment = {0, 300 * 1000000}; // 300ms + return increment; + ''' } } @@ -131,13 +135,16 @@ RoomModel TimerServiceTest { Structure { usercode2 ''' #include <etUnit/etUnit.h> + #include <osal/etSema.h> + #include <runtime/etRuntime.h> ''' conjugated Port runnerCtl: PTestControl ActorRef runner: ControllableSequentialTestExecutor ActorRef t1: APolledPeriodicTimeoutTest + ActorRef t2: ADroppedPeriodicTimeoutTest Binding runner.control and t1.ctl + Binding runner.control and t2.ctl Binding runner.exeControl and runnerCtl - SAP testSuiteTimeout: PTimer } Behavior { StateMachine { @@ -145,28 +152,21 @@ RoomModel TimerServiceTest { action ''' etUnit_open("log", "TimerServiceTest"); etUnit_openTestSuite("org.eclipse.etrice.generator.c.tests.TimerServiceTest"); - // Overall timeout of 10 seconds - testSuiteTimeout.startTimeout(10000); runnerCtl.start(); ''' } State Running - Transition timedOut: Running -> Running { - triggers { <timeout:testSuiteTimeout> } - action ''' - etLogger_logError("test timed out!"); - runnerCtl.abort(); - ''' - } Transition done: Running -> Finished { - triggers { <done: runnerCtl> } + triggers { + <done: runnerCtl> + } action ''' etUnit_closeTestSuite(); etUnit_close(); - etUnit_testFinished(0); + etSema_wakeup(etRuntime_getTerminateSemaphore()); ''' } - State Finished + State Finished } } } @@ -174,13 +174,189 @@ RoomModel TimerServiceTest { SubSystemClass TimerServiceTestSubSys { LogicalThread defaultThread + ActorRef actorUnderTest: ATimerServiceOverrideGetTime ActorRef tests: ATestHarness - ActorRef actorUnderTest: ATimerService LayerConnection ref tests satisfied_by actorUnderTest.timer LayerConnection ref tests satisfied_by actorUnderTest.supervisionControl + LayerConnection ref tests satisfied_by actorUnderTest.testTimeCtl } LogicalSystem TimerServiceTestLogSys { SubSystemRef main: TimerServiceTestSubSys } + + /** + * The polling based ATimerService test cases all have a similar structure. The expectations are + * defined as a sequence of events. Each polling cycle, the test sequence will be advanced and + * a message will be sent to update simulated time injected into the ATimerService for the next + * cycle. + * + * <p>Concrete test cases shall override the four Operations in the base actor behavior.</p> + */ + abstract async ActorClass APolledTimerServiceTestBase { + Interface { + Port ctl: PTestControl + } + Structure { + usercode2 ''' + #include <debugging/etMSCLogger.h> + #include <etUnit/etUnit.h> + #include <helpers/etTimeHelpers.h> + #include "TimerServiceTest/ETestEvent.h" + ''' + external Port ctl + SAP testTimeCtl: PTestTimeControl + SAP timer: PTimer + Attribute testId: int16 + Attribute pollingCycles: int32 + Attribute timeouts: int32 + Attribute simTimeCurrent: targetTime // The sim time that the unit under test currently sees + Attribute simTimeNew: targetTime // The new requested sim time + Attribute dummyEvent: ETestEvent // included to allow C translation of . operation on ETestEvent type + } + Behavior { + Operation getTestName(): string ''' + return ""; + ''' + + // Define event expectations. + // NOTE: the timeout messages are dispatched after the polling handlers + // have been executed, which is why: + // - the timeout events always follow after the polling cycle in which they were queued. + // - the ATimerService only reflects new setTime changes in the *next* polling cycle. + Operation getExpectedEvents(): DTestEvents ''' + DTestEvents e = {0}; + return e; + ''' + + Operation doTestSequenceStep(cycle: int32) ''' + ''' + + Operation getSimTimeIncrement(cycle: int32): targetTime ''' + etTime t = {0}; + return t; + ''' + + StateMachine { + Transition init: initial -> Pre + State Pre + Transition start: Pre -> Running { + triggers { + <start: ctl> + } + action ''' + testId = etUnit_openTestCase(getTestName()); + DTestEvents expectedEvents = getExpectedEvents(); + EXPECT_ORDER_START(testId, expectedEvents.elements, expectedEvents.size); + testTimeCtl.enable(); + testTimeCtl.setTime(&simTimeNew); + ''' + } + State Running { + do ''' + doTestSequenceStep(pollingCycles); + + // Increment simulated time + simTimeCurrent = simTimeNew; + etTime interval = getSimTimeIncrement(pollingCycles); + etTimeHelpers_add(&simTimeNew, &interval); + testTimeCtl.setTime(&simTimeNew); + + etLogger_logInfoF("polling cycle %d (timer service sees %d)", pollingCycles, etTimeHelpers_convertToMSec(&simTimeCurrent)); + EXPECT_ORDER(testId, "pollingCycle", ETestEvent.POLLING_CYCLE); + ++pollingCycles; + ''' + } + Transition recvTimeout: Running -> Running { + triggers { + <timeout: timer> + } + action ''' + ++timeouts; + etLogger_logInfoF("timeout %d (>%d)", timeouts, etTimeHelpers_convertToMSec(&simTimeCurrent)); + EXPECT_ORDER(testId, "timeout", ETestEvent.TIMEOUT); + ''' + } + Transition done: Running -> Post { + guard '''timeouts == 2''' + action ''' + // End test sequence + etLogger_logInfo("testcase done"); + EXPECT_ORDER_END(testId, "done", ETestEvent.END); + ctl.done(true); + ''' + } + Transition tooManyCycles: Running -> Post { + guard '''pollingCycles > 30''' + action ''' + EXPECT_TRUE(testId, "Too many polling cycles", ET_FALSE); + ctl.done(false); + ''' + } + Transition abort: Running -> Post { + triggers { <abort: ctl> } + action ''' + EXPECT_TRUE(testId, "Aborted test", ET_FALSE); + ctl.done(false); + ''' + } + State Post { + entry ''' + timer.kill(); + testTimeCtl.disable(); + etUnit_closeTestCase(testId); + ''' + } + } + } + } + + Enumeration ETestEvent of int16 { + POLLING_CYCLE = 0, + TIMEOUT = 1, + END = 2 + } + + DataClass DTestEvents { + Attribute elements: ETestEvent ref + Attribute size: int16 + } + + ProtocolClass PTestTimeControl { + incoming { + Message setTime(targetTime) + Message enable() + Message disable() + } + regular PortClass + { + usercode ''' + #include "base/etMemory.h" + #include "debugging/etLogger.h" + #include "debugging/etMSCLogger.h" + #include "osal/etTime.h" + ''' + Attribute time: targetTime + Attribute isEnabled: boolean = "ET_FALSE" + Operation getTestControlTime(t: targetTime ref) ''' + *t = time; + ''' + Operation isTestControlEnabled(): boolean ''' + return isEnabled; + ''' + handle incoming setTime ''' + time = *(etTime*)(((char*)msg)+MEM_CEIL(sizeof(etMessage))); + etLogger_logInfoF("PTimeTestControl setTime(%d)", etTimeHelpers_convertToMSec(&time)); + (*receiveMessageFunc)(actor, self, msg); + ''' + handle incoming enable ''' + isEnabled = ET_TRUE; + (*receiveMessageFunc)(actor, self, msg); + ''' + handle incoming disable ''' + isEnabled = ET_FALSE; + (*receiveMessageFunc)(actor, self, msg); + ''' + } + } }
\ No newline at end of file |