From 8206cd72805445e857fd76fb6a118b23a41fa41e Mon Sep 17 00:00:00 2001 From: Sergey Polyakov Date: Fri, 6 Sep 2024 18:52:07 +0200 Subject: [PATCH 1/8] delay() improvements --- system/inc/system_cloud.h | 3 ++ system/inc/system_task.h | 3 ++ system/src/main.cpp | 2 + system/src/system_cloud.cpp | 4 +- system/src/system_task.cpp | 99 +++++++++++++++++++++++++++++++------ 5 files changed, 95 insertions(+), 16 deletions(-) diff --git a/system/inc/system_cloud.h b/system/inc/system_cloud.h index 7cf701125d..a7dc950990 100644 --- a/system/inc/system_cloud.h +++ b/system/inc/system_cloud.h @@ -384,7 +384,10 @@ int spark_set_random_seed_from_cloud_handler(void (*handler)(unsigned int), void //#define SPARK_SERVER_IP "54.235.79.249" #define SPARK_SERVER_PORT 5683 #define PORT_COAPS (5684) + +// Periodicity of processing system/app events while in a delay() call #define SPARK_LOOP_DELAY_MILLIS 1000 //1sec + #define SPARK_RECEIVE_DELAY_MILLIS 10 //10ms #define TIMING_FLASH_UPDATE_TIMEOUT (300000) // 300sec diff --git a/system/inc/system_task.h b/system/inc/system_task.h index 31f9896178..79213b8559 100644 --- a/system/inc/system_task.h +++ b/system/inc/system_task.h @@ -125,6 +125,9 @@ int system_isr_task_queue_free_memory(void *ptrToFree); namespace particle::system { +// Time, in milliseconds since startup, the app event queue was last processed (in threaded mode) +extern system_tick_t g_lastAppLoopProcessTime; + /** * Allocate an object in the system pool. * diff --git a/system/src/main.cpp b/system/src/main.cpp index 80566d1ce0..96893c2992 100644 --- a/system/src/main.cpp +++ b/system/src/main.cpp @@ -528,6 +528,8 @@ void app_loop(bool threaded) void app_thread_idle() { + // The idle function is called by the app thread right after its event queue has been processed + system::g_lastAppLoopProcessTime = HAL_Timer_Get_Milli_Seconds(); app_loop(true); } diff --git a/system/src/system_cloud.cpp b/system/src/system_cloud.cpp index 6531f6e980..411aca9517 100644 --- a/system/src/system_cloud.cpp +++ b/system/src/system_cloud.cpp @@ -261,7 +261,9 @@ bool spark_process(void) #if PLATFORM_THREADING if (APPLICATION_THREAD_CURRENT()) { if (system_thread_get_state(NULL)) { - return ApplicationThread.process(); + bool result = ApplicationThread.process(); + g_lastAppLoopProcessTime = HAL_Timer_Get_Milli_Seconds(); + return result; } else { Spark_Idle_Events(true); } diff --git a/system/src/system_task.cpp b/system/src/system_task.cpp index 7ddf9c76d2..e615ed18cf 100644 --- a/system/src/system_task.cpp +++ b/system/src/system_task.cpp @@ -97,6 +97,12 @@ static struct SetThreadCurrentFunctionPointers { namespace particle { +namespace system { + +system_tick_t g_lastAppLoopProcessTime = 0; + +} // system + ISRTaskQueue SystemISRTaskQueue; } // particle @@ -543,18 +549,72 @@ void Spark_Idle_Events(bool force_events/*=false*/) system_shutdown_if_needed(); } -/* - * @brief This should block for a certain number of milliseconds and also execute spark_wlan_loop - */ -void system_delay_pump(unsigned long ms, bool force_no_background_loop=false) +namespace { + +#if PLATFORM_THREADING + +void delayThreadedImpl(system_tick_t duration, system_tick_t startMillis, system_tick_t startMicros, bool processAppEvents) { + if (processAppEvents) { + // Time elapsed since this function was called + system_tick_t elapsedSinceStart = 0; + + // Time elapsed since the app queue was last processed + auto elapsedSinceLoop = startMillis - g_lastAppLoopProcessTime; + + // Time to wait before the app queue can be processed again + system_tick_t leftUntilLoop = 0; + if (elapsedSinceLoop < SPARK_LOOP_DELAY_MILLIS) { + leftUntilLoop = SPARK_LOOP_DELAY_MILLIS - elapsedSinceLoop; + } + + for (;;) { + // Remaining time to run this function + auto leftUntilStop = duration - elapsedSinceStart; + if (leftUntilStop < leftUntilLoop) { + HAL_Delay_Milliseconds(leftUntilStop); + break; + } + + // Wait until the app queue can be processed again + HAL_Delay_Milliseconds(leftUntilLoop); + + ApplicationThread.process(); + auto now = HAL_Timer_Get_Milli_Seconds(); + g_lastAppLoopProcessTime = now; + + elapsedSinceStart = now - startMillis; + if (elapsedSinceStart >= duration) { + break; + } + leftUntilLoop = SPARK_LOOP_DELAY_MILLIS; + } + } else { + HAL_Delay_Milliseconds(duration); + } + + // Make sure not to return early by a fraction of a millisecond + if (duration < 60000) { // Just some threshold that a) is large enough for delay() to remain precise in typical use cases b) ensures that the micros counter couldn't wrap around more than once + duration *= 1000; + auto elapsedMicros = HAL_Timer_Get_Micro_Seconds() - startMicros; + if (elapsedMicros < duration) { + HAL_Delay_Microseconds(duration - elapsedMicros); + } + } else { + HAL_Delay_Milliseconds(1); // Wait until the next tick + } +} + +#endif // PLATFORM_THREADING + +// Legacy implementation for non-threaded mode +void delayNonThreadedImpl(unsigned long ms, system_tick_t start_millis, system_tick_t start_micros, bool force_no_background_loop=false) { if (ms==0) return; system_tick_t spark_loop_elapsed_millis = SPARK_LOOP_DELAY_MILLIS; spark_loop_total_millis += ms; - system_tick_t start_millis = HAL_Timer_Get_Milli_Seconds(); - system_tick_t end_micros = HAL_Timer_Get_Micro_Seconds() + (1000*ms); + system_tick_t end_micros = start_micros + (1000*ms); // Ensure that RTOS vTaskDelay(0) is called to force a reschedule to avoid task starvation in tight delay(1) loops HAL_Delay_Milliseconds(0); @@ -617,23 +677,32 @@ void system_delay_pump(unsigned long ms, bool force_no_background_loop=false) } } +} // unnamed + /** * On a non threaded platform, or when called from the application thread, then * run the background loop so that application events are processed. */ -void system_delay_ms(unsigned long ms, bool force_no_background_loop=false) +void system_delay_ms(unsigned long ms, bool force_no_background_loop) { - // if not threading, or we are the application thread, then implement delay - // as a background message pump + auto startMicros = HAL_Timer_Get_Micro_Seconds(); + auto startMillis = HAL_Timer_Get_Milli_Seconds(); - if ((!PLATFORM_THREADING || APPLICATION_THREAD_CURRENT()) && !hal_interrupt_is_isr()) - { - system_delay_pump(ms, force_no_background_loop); + if (hal_interrupt_is_isr()) { + return; } - else - { - HAL_Delay_Milliseconds(ms); + +#if PLATFORM_THREADING + if (!APPLICATION_THREAD_CURRENT()) { + delayThreadedImpl(ms, startMillis, startMicros, false /* processAppEvents */); + } else if (system_thread_get_state(nullptr)) { // Is system thread enabled? + delayThreadedImpl(ms, startMillis, startMicros, !force_no_background_loop); + } else { + delayNonThreadedImpl(ms, startMillis, startMicros, force_no_background_loop); } +#else // !PLATFORM_THREADING + delayNonThreadedImpl(ms, startMillis, startMicros, force_no_background_loop); +#endif } void cloud_disconnect(unsigned flags, cloud_disconnect_reason cloudReason, network_disconnect_reason networkReason, From 3eb4e3ce42db5851e9179b32b26e34bc8e46caa3 Mon Sep 17 00:00:00 2001 From: Sergey Polyakov Date: Sat, 7 Sep 2024 13:47:31 +0200 Subject: [PATCH 2/8] Minor refactoring --- system/inc/system_cloud.h | 2 +- system/inc/system_task.h | 2 +- system/src/main.cpp | 2 +- system/src/system_task.cpp | 36 ++++++++++++++++++++---------------- 4 files changed, 23 insertions(+), 19 deletions(-) diff --git a/system/inc/system_cloud.h b/system/inc/system_cloud.h index a7dc950990..f218095693 100644 --- a/system/inc/system_cloud.h +++ b/system/inc/system_cloud.h @@ -385,7 +385,7 @@ int spark_set_random_seed_from_cloud_handler(void (*handler)(unsigned int), void #define SPARK_SERVER_PORT 5683 #define PORT_COAPS (5684) -// Periodicity of processing system/app events while in a delay() call +// Periodicity of processing system/app events while delay() is running #define SPARK_LOOP_DELAY_MILLIS 1000 //1sec #define SPARK_RECEIVE_DELAY_MILLIS 10 //10ms diff --git a/system/inc/system_task.h b/system/inc/system_task.h index 79213b8559..8609ff1546 100644 --- a/system/inc/system_task.h +++ b/system/inc/system_task.h @@ -125,7 +125,7 @@ int system_isr_task_queue_free_memory(void *ptrToFree); namespace particle::system { -// Time, in milliseconds since startup, the app event queue was last processed (in threaded mode) +// Time the app event queue was last processed extern system_tick_t g_lastAppLoopProcessTime; /** diff --git a/system/src/main.cpp b/system/src/main.cpp index 96893c2992..91d928a774 100644 --- a/system/src/main.cpp +++ b/system/src/main.cpp @@ -528,7 +528,7 @@ void app_loop(bool threaded) void app_thread_idle() { - // The idle function is called by the app thread right after its event queue has been processed + // The idle function is called right after the app thread's event queue has been processed system::g_lastAppLoopProcessTime = HAL_Timer_Get_Milli_Seconds(); app_loop(true); } diff --git a/system/src/system_task.cpp b/system/src/system_task.cpp index e615ed18cf..c31c957377 100644 --- a/system/src/system_task.cpp +++ b/system/src/system_task.cpp @@ -555,11 +555,8 @@ namespace { void delayThreadedImpl(system_tick_t duration, system_tick_t startMillis, system_tick_t startMicros, bool processAppEvents) { if (processAppEvents) { - // Time elapsed since this function was called - system_tick_t elapsedSinceStart = 0; - // Time elapsed since the app queue was last processed - auto elapsedSinceLoop = startMillis - g_lastAppLoopProcessTime; + auto elapsedSinceLoop = HAL_Timer_Get_Milli_Seconds() - g_lastAppLoopProcessTime; // Time to wait before the app queue can be processed again system_tick_t leftUntilLoop = 0; @@ -568,6 +565,12 @@ void delayThreadedImpl(system_tick_t duration, system_tick_t startMillis, system } for (;;) { + // Time elapsed since delay() was called + auto elapsedSinceStart = HAL_Timer_Get_Milli_Seconds() - startMillis; + if (elapsedSinceStart >= duration) { + break; + } + // Remaining time to run this function auto leftUntilStop = duration - elapsedSinceStart; if (leftUntilStop < leftUntilLoop) { @@ -579,20 +582,20 @@ void delayThreadedImpl(system_tick_t duration, system_tick_t startMillis, system HAL_Delay_Milliseconds(leftUntilLoop); ApplicationThread.process(); - auto now = HAL_Timer_Get_Milli_Seconds(); - g_lastAppLoopProcessTime = now; + g_lastAppLoopProcessTime = HAL_Timer_Get_Milli_Seconds(); - elapsedSinceStart = now - startMillis; - if (elapsedSinceStart >= duration) { - break; - } leftUntilLoop = SPARK_LOOP_DELAY_MILLIS; } } else { - HAL_Delay_Milliseconds(duration); + auto elapsedSinceStart = HAL_Timer_Get_Milli_Seconds() - startMillis; + if (elapsedSinceStart < duration) { + HAL_Delay_Milliseconds(duration - elapsedSinceStart); + } } - // Make sure not to return early by a fraction of a millisecond + // XXX: Despite what the name suggests, HAL_Delay_Milliseconds() operates with ticks, not + // milliseconds. Depending on how far into the current tick the calling thread is, it may return + // earlier by a fraction of a millisecond so we need to adjust for that inaccuracy if (duration < 60000) { // Just some threshold that a) is large enough for delay() to remain precise in typical use cases b) ensures that the micros counter couldn't wrap around more than once duration *= 1000; auto elapsedMicros = HAL_Timer_Get_Micro_Seconds() - startMicros; @@ -600,14 +603,15 @@ void delayThreadedImpl(system_tick_t duration, system_tick_t startMillis, system HAL_Delay_Microseconds(duration - elapsedMicros); } } else { - HAL_Delay_Milliseconds(1); // Wait until the next tick + // Let delay() slip by one more millisecond or less + HAL_Delay_Milliseconds(1); } } #endif // PLATFORM_THREADING // Legacy implementation for non-threaded mode -void delayNonThreadedImpl(unsigned long ms, system_tick_t start_millis, system_tick_t start_micros, bool force_no_background_loop=false) +void delayNonThreadedImpl(unsigned long ms, system_tick_t start_millis, system_tick_t start_micros, bool force_no_background_loop) { if (ms==0) return; @@ -637,7 +641,7 @@ void delayNonThreadedImpl(unsigned long ms, system_tick_t start_millis, system_t if (delay > 100000) { return; } - HAL_Delay_Microseconds(min(delay/2, 1u)); + HAL_Delay_Microseconds(std::max(delay/2, 1)); } } else @@ -695,7 +699,7 @@ void system_delay_ms(unsigned long ms, bool force_no_background_loop) #if PLATFORM_THREADING if (!APPLICATION_THREAD_CURRENT()) { delayThreadedImpl(ms, startMillis, startMicros, false /* processAppEvents */); - } else if (system_thread_get_state(nullptr)) { // Is system thread enabled? + } else if (system_thread_get_state(nullptr)) { delayThreadedImpl(ms, startMillis, startMicros, !force_no_background_loop); } else { delayNonThreadedImpl(ms, startMillis, startMicros, force_no_background_loop); From 83cdc2ecbe1a5c73dd2fc0db365b54f5eab84df0 Mon Sep 17 00:00:00 2001 From: Sergey Polyakov Date: Tue, 10 Sep 2024 10:11:17 +0200 Subject: [PATCH 3/8] Rework the delay accuracy test --- system/src/system_task.cpp | 2 +- user/tests/wiring/no_fixture/delay.cpp | 47 ------------------- .../wiring/no_fixture_long_running/delay.cpp | 43 +++++++++++++++++ .../no_fixture_long_running.spec.js | 16 +++++++ 4 files changed, 60 insertions(+), 48 deletions(-) delete mode 100644 user/tests/wiring/no_fixture/delay.cpp create mode 100644 user/tests/wiring/no_fixture_long_running/delay.cpp diff --git a/system/src/system_task.cpp b/system/src/system_task.cpp index c31c957377..77da7097d3 100644 --- a/system/src/system_task.cpp +++ b/system/src/system_task.cpp @@ -595,7 +595,7 @@ void delayThreadedImpl(system_tick_t duration, system_tick_t startMillis, system // XXX: Despite what the name suggests, HAL_Delay_Milliseconds() operates with ticks, not // milliseconds. Depending on how far into the current tick the calling thread is, it may return - // earlier by a fraction of a millisecond so we need to adjust for that inaccuracy + // early by a fraction of a millisecond so we need to adjust for that inaccuracy if (duration < 60000) { // Just some threshold that a) is large enough for delay() to remain precise in typical use cases b) ensures that the micros counter couldn't wrap around more than once duration *= 1000; auto elapsedMicros = HAL_Timer_Get_Micro_Seconds() - startMicros; diff --git a/user/tests/wiring/no_fixture/delay.cpp b/user/tests/wiring/no_fixture/delay.cpp deleted file mode 100644 index 1e8d2a39c9..0000000000 --- a/user/tests/wiring/no_fixture/delay.cpp +++ /dev/null @@ -1,47 +0,0 @@ - -#include "application.h" -#include "unit-test/unit-test.h" - - -#if PLATFORM_THREADING -#define scheduler(b) os_thread_scheduling(b, NULL) -#else -#define scheduler(b) -#endif - -class DelayTest -{ - public: - - DelayTest(uint16_t duration) - { - HAL_Delay_Milliseconds(duration); - } -}; - -test(DELAY_01_delay_1ms_is_within_tolerance) -{ -#if HAL_PLATFORM_NRF52840 - // These errors are mainly due to processing overhead, which is a greater factor on NRF with a slower clock speed - const uint32_t delay_us_error = 200; // 20% -#elif HAL_PLATFORM_RTL872X - const uint32_t delay_us_error = 120; // 12% -#else -#error "Unsupported platform" -#endif - - DelayTest dt(10); - // on RTOS have to stop task scheduling for the delays or we may not - // be executed often enough - for (int i=0; i<100; i++) { - scheduler(false); - uint32_t start = micros(); - system_delay_ms(1, true); - uint32_t end = micros(); - scheduler(true); - - // Serial.printlnf("total time:%lu", end-start); - assertMoreOrEqual(end-start, 1000); - assertLessOrEqual(end-start, 1000 + delay_us_error); - } -} \ No newline at end of file diff --git a/user/tests/wiring/no_fixture_long_running/delay.cpp b/user/tests/wiring/no_fixture_long_running/delay.cpp new file mode 100644 index 0000000000..d81f379bb8 --- /dev/null +++ b/user/tests/wiring/no_fixture_long_running/delay.cpp @@ -0,0 +1,43 @@ +#include +#include + +#include "application.h" +#include "unit-test/unit-test.h" + +test(DELAY_01_init) { + Network.off(); +} + +test(DELAY_02_accuracy_is_within_tolerance) { + const unsigned minDelay = 2; // ms + const unsigned maxDelay = 10; // ms + const unsigned callCount = 1000; + + Vector variations; + assertTrue(variations.resize(callCount)); + + for (unsigned i = 0; i < callCount; ++i) { + auto duration = rand() % (maxDelay - 1) + minDelay; + auto t1 = micros(); + delay(duration); + auto dt = micros() - t1; + + assertMoreOrEqual(dt, duration * 1000); // delay() must never return early + variations[i] = dt - duration * 1000; + + Particle.process(); + + // Wait for the beginning of a tick and then for some arbitrary time within that tick + HAL_Delay_Milliseconds(1); + delayMicroseconds(rand() % 1000); + } + + std::sort(variations.begin(), variations.end()); + auto dtPct = variations[std::floor(callCount * 0.995)]; // Nth percentile + auto dtMax = variations.last(); + + assertLess(dtPct, 100); // us + assertLess(dtMax, 1000); // us + + pushMailboxMsg(String::format("%u,%u", dtPct, dtMax), 5000 /* wait */); +} diff --git a/user/tests/wiring/no_fixture_long_running/no_fixture_long_running.spec.js b/user/tests/wiring/no_fixture_long_running/no_fixture_long_running.spec.js index c3d2908cdb..16422add73 100644 --- a/user/tests/wiring/no_fixture_long_running/no_fixture_long_running.spec.js +++ b/user/tests/wiring/no_fixture_long_running/no_fixture_long_running.spec.js @@ -2,3 +2,19 @@ suite('No fixture long running'); platform('gen3', 'gen4'); timeout(32 * 60 * 1000); + +let device; + +before(function() { + device = this.particle.devices[0]; +}); + +test('DELAY_01_init', async () => { +}); + +test('DELAY_02_accuracy_is_within_tolerance', async () => { + expect(device.mailBox).to.not.be.empty; + const msg = device.mailBox[0].d.split(','); + console.log(`Nth percentile variation: ${msg[0]}us`); + console.log(`Maximum variation: ${msg[1]}us`); +}); From 39a7d901632fb98e4cbd0ae8212ba4c04a904c9d Mon Sep 17 00:00:00 2001 From: Sergey Polyakov Date: Tue, 10 Sep 2024 10:19:22 +0200 Subject: [PATCH 4/8] Add tests --- user/tests/wiring/no_fixture_long_running/delay.cpp | 12 +++++------- 1 file changed, 5 insertions(+), 7 deletions(-) diff --git a/user/tests/wiring/no_fixture_long_running/delay.cpp b/user/tests/wiring/no_fixture_long_running/delay.cpp index d81f379bb8..890cb75861 100644 --- a/user/tests/wiring/no_fixture_long_running/delay.cpp +++ b/user/tests/wiring/no_fixture_long_running/delay.cpp @@ -9,15 +9,13 @@ test(DELAY_01_init) { } test(DELAY_02_accuracy_is_within_tolerance) { - const unsigned minDelay = 2; // ms - const unsigned maxDelay = 10; // ms const unsigned callCount = 1000; Vector variations; assertTrue(variations.resize(callCount)); for (unsigned i = 0; i < callCount; ++i) { - auto duration = rand() % (maxDelay - 1) + minDelay; + auto duration = rand() % 9 + 2; // 2-10ms auto t1 = micros(); delay(duration); auto dt = micros() - t1; @@ -33,11 +31,11 @@ test(DELAY_02_accuracy_is_within_tolerance) { } std::sort(variations.begin(), variations.end()); - auto dtPct = variations[std::floor(callCount * 0.995)]; // Nth percentile - auto dtMax = variations.last(); + auto dtPct = variations[std::floor(callCount * 0.995)]; // Nth percentile variation, us + auto dtMax = variations.last(); // Maximum variation, us - assertLess(dtPct, 100); // us - assertLess(dtMax, 1000); // us + assertLess(dtPct, 100); + assertLess(dtMax, 1000); pushMailboxMsg(String::format("%u,%u", dtPct, dtMax), 5000 /* wait */); } From 1d7e11aa3988f6651e9034c2602181b6cf24a41c Mon Sep 17 00:00:00 2001 From: Sergey Polyakov Date: Thu, 12 Sep 2024 12:23:47 +0200 Subject: [PATCH 5/8] Add tests --- .../wiring/no_fixture_long_running/delay.cpp | 101 ++++++++++++++++++ .../no_fixture_long_running.spec.js | 3 + 2 files changed, 104 insertions(+) diff --git a/user/tests/wiring/no_fixture_long_running/delay.cpp b/user/tests/wiring/no_fixture_long_running/delay.cpp index 890cb75861..0d523681a0 100644 --- a/user/tests/wiring/no_fixture_long_running/delay.cpp +++ b/user/tests/wiring/no_fixture_long_running/delay.cpp @@ -1,9 +1,52 @@ #include +#include #include +#include "system_threading.h" +#include "scope_guard.h" + #include "application.h" #include "unit-test/unit-test.h" +namespace { + +os_semaphore_t g_sysThreadSuspendSem = nullptr; +int g_sysThreadSuspendCount = 0; + +void suspendSystemThread() { + if (!system_thread_get_state(nullptr /* reserved */)) { + return; + } + if (++g_sysThreadSuspendCount > 1) { + return; + } + if (!g_sysThreadSuspendSem) { + int r = os_semaphore_create(&g_sysThreadSuspendSem, 0xffffffffu /* max_count */, 0 /* initial_count */); + SPARK_ASSERT(r == 0); + } + auto sysThread = (ActiveObjectBase*)system_internal(1 /* item */, nullptr /* reserved */); + std::function fn = [&]() { + int r = os_semaphore_take(g_sysThreadSuspendSem, 0xffffffffu /* timeout */, false /* reserved */); + SPARK_ASSERT(r == 0); + }; + sysThread->invoke_async(std::move(fn)); + HAL_Delay_Milliseconds(1); +} + +void resumeSystemThread() { + if (!system_thread_get_state(nullptr /* reserved */)) { + return; + } + if (--g_sysThreadSuspendCount > 0) { + return; + } + SPARK_ASSERT(g_sysThreadSuspendCount == 0); + int r = os_semaphore_give(g_sysThreadSuspendSem, false /* reserved */); + SPARK_ASSERT(r == 0); +} + +} // namespace + test(DELAY_01_init) { Network.off(); } @@ -39,3 +82,61 @@ test(DELAY_02_accuracy_is_within_tolerance) { pushMailboxMsg(String::format("%u,%u", dtPct, dtMax), 5000 /* wait */); } + +test(DELAY_03_app_events_are_processed_at_expected_rate_in_threaded_mode) { + if (!system_thread_get_state(nullptr /* reserved */)) { + skip(); + return; + } + + // Prevent the system from sending events to the app while the test is running + suspendSystemThread(); + SCOPE_GUARD({ + resumeSystemThread(); + }); + + // Flush the event queue + while (Particle.process()) { + } + + auto appThread = (ActiveObjectBase*)system_internal(0 /* item */, nullptr /* reserved */); + + auto lastEventTime = millis(); + unsigned minEventInterval = std::numeric_limits::max(); + unsigned maxEventInterval = 0; + unsigned eventCount = 0; + bool running = true; + + std::function fn; + fn = [&]() { + if (!running) { + return; + } + auto now = millis(); + auto dt = now - lastEventTime; + lastEventTime = now; + if (dt < minEventInterval) { + minEventInterval = dt; + } + if (dt > maxEventInterval) { + maxEventInterval = dt; + } + ++eventCount; + appThread->invoke_async(fn); + }; + + appThread->invoke_async(fn); + + auto startTime = millis(); + do { + delay(rand() % 3000); + } while (millis() - startTime < 10000); + + running = false; + while (Particle.process()) { + } + + assertMoreOrEqual(minEventInterval, 999); // The maintained interval is not sub-tick precise + assertLessOrEqual(maxEventInterval, 1005); + assertMoreOrEqual(eventCount, 9); +} diff --git a/user/tests/wiring/no_fixture_long_running/no_fixture_long_running.spec.js b/user/tests/wiring/no_fixture_long_running/no_fixture_long_running.spec.js index 16422add73..eef685fd86 100644 --- a/user/tests/wiring/no_fixture_long_running/no_fixture_long_running.spec.js +++ b/user/tests/wiring/no_fixture_long_running/no_fixture_long_running.spec.js @@ -18,3 +18,6 @@ test('DELAY_02_accuracy_is_within_tolerance', async () => { console.log(`Nth percentile variation: ${msg[0]}us`); console.log(`Maximum variation: ${msg[1]}us`); }); + +test('DELAY_03_app_events_are_processed_at_expected_rate_in_threaded_mode', async () => { +}); From c82b784e820b88d21b866c48c92ad8b12c6ca6a8 Mon Sep 17 00:00:00 2001 From: Sergey Polyakov Date: Mon, 16 Sep 2024 18:58:29 +0200 Subject: [PATCH 6/8] Minor fix --- user/tests/wiring/no_fixture_long_running/delay.cpp | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/user/tests/wiring/no_fixture_long_running/delay.cpp b/user/tests/wiring/no_fixture_long_running/delay.cpp index 0d523681a0..0d75866537 100644 --- a/user/tests/wiring/no_fixture_long_running/delay.cpp +++ b/user/tests/wiring/no_fixture_long_running/delay.cpp @@ -74,10 +74,10 @@ test(DELAY_02_accuracy_is_within_tolerance) { } std::sort(variations.begin(), variations.end()); - auto dtPct = variations[std::floor(callCount * 0.995)]; // Nth percentile variation, us + auto dtPct = variations[std::floor(callCount * 0.99)]; // Nth percentile variation, us auto dtMax = variations.last(); // Maximum variation, us - assertLess(dtPct, 100); + assertLess(dtPct, 200); assertLess(dtMax, 1000); pushMailboxMsg(String::format("%u,%u", dtPct, dtMax), 5000 /* wait */); From 50cf15c79cbbe092db16ab57fad346baf3883d9d Mon Sep 17 00:00:00 2001 From: Sergey Polyakov Date: Tue, 17 Sep 2024 17:33:52 +0200 Subject: [PATCH 7/8] Minor fix --- user/tests/wiring/no_fixture_long_running/delay.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/user/tests/wiring/no_fixture_long_running/delay.cpp b/user/tests/wiring/no_fixture_long_running/delay.cpp index 0d75866537..33d8349576 100644 --- a/user/tests/wiring/no_fixture_long_running/delay.cpp +++ b/user/tests/wiring/no_fixture_long_running/delay.cpp @@ -78,7 +78,7 @@ test(DELAY_02_accuracy_is_within_tolerance) { auto dtMax = variations.last(); // Maximum variation, us assertLess(dtPct, 200); - assertLess(dtMax, 1000); + assertLess(dtMax, 2000); pushMailboxMsg(String::format("%u,%u", dtPct, dtMax), 5000 /* wait */); } From a5d1ef27d684ae7cb82815129091715267731679 Mon Sep 17 00:00:00 2001 From: Technobly Date: Tue, 17 Sep 2024 16:08:06 -0500 Subject: [PATCH 8/8] Adjusts test limits --- .../wiring/no_fixture_long_running/delay.cpp | 30 ++++++++++++++----- .../no_fixture_long_running.spec.js | 5 ++-- 2 files changed, 26 insertions(+), 9 deletions(-) diff --git a/user/tests/wiring/no_fixture_long_running/delay.cpp b/user/tests/wiring/no_fixture_long_running/delay.cpp index 33d8349576..c40e66bf5e 100644 --- a/user/tests/wiring/no_fixture_long_running/delay.cpp +++ b/user/tests/wiring/no_fixture_long_running/delay.cpp @@ -74,13 +74,29 @@ test(DELAY_02_accuracy_is_within_tolerance) { } std::sort(variations.begin(), variations.end()); - auto dtPct = variations[std::floor(callCount * 0.99)]; // Nth percentile variation, us - auto dtMax = variations.last(); // Maximum variation, us - - assertLess(dtPct, 200); - assertLess(dtMax, 2000); - - pushMailboxMsg(String::format("%u,%u", dtPct, dtMax), 5000 /* wait */); + auto dtPct95 = variations[std::floor(callCount * 0.95)]; // 95th percentile variation, us + auto dtPct99 = variations[std::floor(callCount * 0.99)]; // 99th percentile variation, us + auto dtMax = variations.last(); // Maximum variation, us (1 out of 1000) + // String temp = String::format("%u:%u:%u:%u:%u:%u:%u:%u:%u:%u:%u", + // variations[callCount-100], + // variations[callCount-90], + // variations[callCount-80], + // variations[callCount-70], + // variations[callCount-60], + // variations[callCount-50], + // variations[callCount-40], + // variations[callCount-30], + // variations[callCount-20], + // variations[callCount-10], + // variations[callCount-1]); + + assertLess(dtPct95, 100); // 95th percentile + assertLess(dtPct99, 200); // 99th percentile + assertLess(dtMax, 3000); // 1 out of 1000 + + // DEBUG: Can replace dtMax with temp string of more data (which also includes dtMax) + // pushMailboxMsg(String::format("%u,%u,%s", dtPct95, dtPct99, temp.c_str()), 5000 /* wait */); + pushMailboxMsg(String::format("%u,%u,%u", dtPct95, dtPct99, dtMax), 5000 /* wait */); } test(DELAY_03_app_events_are_processed_at_expected_rate_in_threaded_mode) { diff --git a/user/tests/wiring/no_fixture_long_running/no_fixture_long_running.spec.js b/user/tests/wiring/no_fixture_long_running/no_fixture_long_running.spec.js index eef685fd86..7c96d0fa1d 100644 --- a/user/tests/wiring/no_fixture_long_running/no_fixture_long_running.spec.js +++ b/user/tests/wiring/no_fixture_long_running/no_fixture_long_running.spec.js @@ -15,8 +15,9 @@ test('DELAY_01_init', async () => { test('DELAY_02_accuracy_is_within_tolerance', async () => { expect(device.mailBox).to.not.be.empty; const msg = device.mailBox[0].d.split(','); - console.log(`Nth percentile variation: ${msg[0]}us`); - console.log(`Maximum variation: ${msg[1]}us`); + console.log(`95th percentile variation: ${msg[0]}us`); + console.log(`99th percentile variation: ${msg[1]}us`); + console.log(`Maximum variation: ${msg[2]}us`); }); test('DELAY_03_app_events_are_processed_at_expected_rate_in_threaded_mode', async () => {