Part of fix #442: Detect late RX/TX launches; improve HAL timing a bit

src/hal/hal.cpp

@@ -248,16 +248,30 @@ static s4_t delta_time(u4_t time) {
     return (s4_t)(time - hal_ticks());
 }
 
-void hal_waitUntil (u4_t time) {
+u4_t hal_waitUntil (u4_t time) {
     s4_t delta = delta_time(time);
+    // check for already too late.
+    if (delta < 0)
+        return -delta;
+
     // From delayMicroseconds docs: Currently, the largest value that
-    // will produce an accurate delay is 16383.
-    while (delta > (16000 / US_PER_OSTICK)) {
-        delay(16);
-        delta -= (16000 / US_PER_OSTICK);
+    // will produce an accurate delay is 16383. Also, STM32 does a better
+    // job with delay is less than 10,000 us; so reduce in steps.
+    while (delta > (9000 / US_PER_OSTICK)) {
+        // deliberately delay 8ms rather than 9ms, so we
+        // will exit loop with delta typically positive.
+        // Depends on BSP keeping time accurately even if interrupts
+        // are disabled.
+        delay(8);
+        // re-synchronize.
+        delta = delta_time(time);
     }
     if (delta > 0)
         delayMicroseconds(delta * US_PER_OSTICK);
+
+    // we aren't "late". Callers are interested in gross delays, not
+    // necessarily delays due to poor timekeeping here.
+    return 0;
 }
 
 // check and rewind for target time

src/lmic/hal.h

@@ -110,9 +110,10 @@ void hal_sleep (void);
 u4_t hal_ticks (void);
 
 /*
- * busy-wait until specified timestamp (in ticks) is reached.
+ * busy-wait until specified timestamp (in ticks) is reached. If on-time, return 0,
+ * otherwise return the number of ticks we were late.
  */
-void hal_waitUntil (u4_t time);
+u4_t hal_waitUntil (u4_t time);
 
 /*
  * check and rewind timer for target time.

src/lmic/lmic.h

@@ -417,6 +417,32 @@ struct lmic_client_data_s {
 
 /*
 
+Structure:  lmic_radio_data_t
+
+Function:
+    Holds LMIC radio driver.
+
+Description:
+    Eventually this will be used for all portable things for the radio driver,
+    but for now it's where we can start to add things.
+
+*/
+
+typedef struct lmic_radio_data_s lmic_radio_data_t;
+
+struct lmic_radio_data_s {
+    // total os ticks of accumulated delay error. Can overflow!
+    ostime_t    rxlate_ticks;
+    // number of rx late launches.
+    unsigned    rxlate_count;
+    // total os ticks of accumulated tx delay error. Can overflow!
+    ostime_t    txlate_ticks;
+    // number of tx late launches.
+    unsigned    txlate_count;
+};
+
+/*
+
 Structure:  lmic_t
 
 Function:
@@ -439,6 +465,9 @@ struct lmic_t {
     rxsched_t   ping;         // pingable setup
 #endif
 
+    // the radio driver portable context
+    lmic_radio_data_t   radio;
+
     /* (u)int32_t things */
 
     // Radio settings TX/RX (also accessed by HAL)

src/lmic/radio.c

@@ -781,8 +781,13 @@ static void txfsk () {
     hal_pin_rxtx(1);
 
     // now we actually start the transmission
-    if (LMIC.txend)
-        hal_waitUntil(LMIC.txend); // busy wait until exact rx time
+    if (LMIC.txend) {
+        u4_t nLate = hal_waitUntil(LMIC.txend); // busy wait until exact tx time
+        if (nLate > 0) {
+            LMIC.radio.txlate_ticks += nLate;
+            ++LMIC.radio.txlate_count;
+        }
+    }
     LMICOS_logEventUint32("+Tx FSK", LMIC.dataLen);
     opmode(OPMODE_TX);
 }
@@ -828,8 +833,13 @@ static void txlora () {
     hal_pin_rxtx(1);
 
     // now we actually start the transmission
-    if (LMIC.txend)
-        hal_waitUntil(LMIC.txend); // busy wait until exact rx time
+    if (LMIC.txend) {
+        u4_t nLate = hal_waitUntil(LMIC.txend); // busy wait until exact tx time
+        if (nLate) {
+            LMIC.radio.txlate_ticks += nLate;
+            ++LMIC.radio.txlate_count;
+        }
+    }
     LMICOS_logEventUint32("+Tx LoRa", LMIC.dataLen);
     opmode(OPMODE_TX);
 
@@ -955,9 +965,14 @@ static void rxlora (u1_t rxmode) {
 
     // now instruct the radio to receive
     if (rxmode == RXMODE_SINGLE) { // single rx
-        hal_waitUntil(LMIC.rxtime); // busy wait until exact rx time
-        LMICOS_logEvent("+Rx LoRa Single");
+        u4_t nLate = hal_waitUntil(LMIC.rxtime); // busy wait until exact rx time
+        LMICOS_logEventUint32("+Rx LoRa Single", nLate);
         opmode(OPMODE_RX_SINGLE);
+        if (nLate)
+            {
+            ++LMIC.radio.rxlate_count;
+            LMIC.radio.rxlate_ticks += nLate;
+            }
 #if LMIC_DEBUG_LEVEL > 0
         ostime_t now = os_getTime();
         LMIC_DEBUG_PRINTF("start single rx: now-rxtime: %"LMIC_PRId_ostime_t"\n", now - LMIC.rxtime);
@@ -1026,9 +1041,13 @@ static void rxfsk (u1_t rxmode) {
 
     // now instruct the radio to receive
     if (rxmode == RXMODE_SINGLE) {
-        hal_waitUntil(LMIC.rxtime); // busy wait until exact rx time
-        LMICOS_logEvent("+Rx FSK");
+        u4_t nLate = hal_waitUntil(LMIC.rxtime); // busy wait until exact rx time
+        LMICOS_logEventUint32("+Rx FSK", nLate);
         opmode(OPMODE_RX); // no single rx mode available in FSK
+        if (nLate) {
+            LMIC.radio.rxlate_ticks += nLate;
+            ++LMIC.radio.rxlate_count;
+        }
     } else {
         LMICOS_logEvent("+Rx FSK Continuous");
         opmode(OPMODE_RX);