Merge pull request #2828 from particle-iot/fix_delay/sc-130532

Improve delay() behavior

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 delay() is running
 #define SPARK_LOOP_DELAY_MILLIS       1000    //1sec
+
 #define SPARK_RECEIVE_DELAY_MILLIS    10      //10ms
 
 #define TIMING_FLASH_UPDATE_TIMEOUT   (300000) // 300sec

system/inc/system_task.h

@@ -125,6 +125,9 @@ int system_isr_task_queue_free_memory(void *ptrToFree);
 
 namespace particle::system {
 
+// Time the app event queue was last processed
+extern system_tick_t g_lastAppLoopProcessTime;
+
 /**
  * Allocate an object in the system pool.
  *

system/src/main.cpp

@@ -528,6 +528,8 @@ void app_loop(bool threaded)
 
 void app_thread_idle()
 {
+    // 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);
 }
 

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);
         }

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,76 @@ 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 the app queue was last processed
+        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;
+        if (elapsedSinceLoop < SPARK_LOOP_DELAY_MILLIS) {
+            leftUntilLoop = SPARK_LOOP_DELAY_MILLIS - elapsedSinceLoop;
+        }
+
+        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) {
+                HAL_Delay_Milliseconds(leftUntilStop);
+                break;
+            }
+
+            // Wait until the app queue can be processed again
+            HAL_Delay_Milliseconds(leftUntilLoop);
+
+            ApplicationThread.process();
+            g_lastAppLoopProcessTime = HAL_Timer_Get_Milli_Seconds();
+
+            leftUntilLoop = SPARK_LOOP_DELAY_MILLIS;
+        }
+    } else {
+        auto elapsedSinceStart = HAL_Timer_Get_Milli_Seconds() - startMillis;
+        if (elapsedSinceStart < duration) {
+            HAL_Delay_Milliseconds(duration - elapsedSinceStart);
+        }
+    }
+
+    // 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
+    // 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;
+        if (elapsedMicros < duration) {
+            HAL_Delay_Microseconds(duration - elapsedMicros);
+        }
+    } else {
+        // 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)
 {
     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);
@@ -577,7 +641,7 @@ void system_delay_pump(unsigned long ms, bool force_no_background_loop=false)
                 if (delay > 100000) {
                     return;
                 }
-                HAL_Delay_Microseconds(min(delay/2, 1u));
+                HAL_Delay_Microseconds(std::max<system_tick_t>(delay/2, 1));
             }
         }
         else
@@ -617,23 +681,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)) {
+        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,

user/tests/wiring/no_fixture_long_running/delay.cpp

@@ -0,0 +1,158 @@
+#include <algorithm>
+#include <limits>
+#include <cmath>
+
+#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();
+}
+
+test(DELAY_02_accuracy_is_within_tolerance) {
+    const unsigned callCount = 1000;
+
+    Vector<unsigned> variations;
+    assertTrue(variations.resize(callCount));
+
+    for (unsigned i = 0; i < callCount; ++i) {
+        auto duration = rand() % 9 + 2; // 2-10ms
+        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 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) {
+    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<unsigned>::max();
+    unsigned maxEventInterval = 0;
+    unsigned eventCount = 0;
+    bool running = true;
+
+    std::function<void()> 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);
+}