Set default timeout to default window time and add debug stats

Author: h2zero

src/NimBLEScan.cpp

@@ -33,6 +33,14 @@ static const char*         LOG_TAG = "NimBLEScan";
 static NimBLEScanCallbacks defaultScanCallbacks;
 static ble_npl_event       dummySrTimerEvent;
 
+# if MYNEWT_VAL(NIMBLE_CPP_LOG_LEVEL) >= 4
+static uint32_t srMinMs     = UINT32_MAX;
+static uint32_t srMaxMs     = 0;
+static uint32_t srTotalMs   = 0;
+static uint32_t srCount     = 0;
+static uint32_t lateSrCount = 0;
+# endif
+
 # if MYNEWT_VAL(BLE_EXT_ADV)
 struct ble_gap_ext_disc_desc dummyDesc{.props             = BLE_HCI_ADV_LEGACY_MASK,
                                        .data_status       = BLE_GAP_EXT_ADV_DATA_STATUS_COMPLETE,
@@ -55,6 +63,32 @@ static ble_gap_disc_desc dummyDesc{
 extern "C" void ble_gap_rx_adv_report(ble_gap_disc_desc* desc);
 # endif
 
+static void srStats(uint32_t ticks, uint16_t window) {
+# if MYNEWT_VAL(NIMBLE_CPP_LOG_LEVEL) >= 4
+    uint32_t ms;
+    ble_npl_time_ticks_to_ms(ticks, &ms);
+    if (ms >= (window ? window : BLE_GAP_SCAN_FAST_WINDOW) * 5) {
+        NIMBLE_LOGD(LOG_TAG, "Scan response time %" PRIu32 " outside scan window, not updating stats", ms);
+        return;
+    }
+
+    if (ms < srMinMs) {
+        srMinMs = ms;
+    }
+    if (ms > srMaxMs) {
+        srMaxMs = ms;
+    }
+    srTotalMs += ms;
+    srCount++;
+# endif
+}
+
+void srMissed() {
+# if MYNEWT_VAL(NIMBLE_CPP_LOG_LEVEL) >= 4
+    lateSrCount++;
+# endif
+}
+
 /**
  * @brief Sends dummy (null) scan response data to the scan event handler in order to
  * provide the scan result to the callbacks when a device hasn't responded to the
@@ -128,7 +162,7 @@ NimBLEScan::NimBLEScan()
       m_maxResults{0xFF} {
     ble_npl_callout_init(&m_srTimer, nimble_port_get_dflt_eventq(), NimBLEScan::srTimerCb, this);
     ble_npl_event_init(&dummySrTimerEvent, sendDummyScanResponse, NULL);
-    ble_npl_time_ms_to_ticks(MYNEWT_VAL(NIMBLE_CPP_SCAN_RSP_TIMEOUT), &m_srTimeoutTicks);
+    ble_npl_time_ms_to_ticks(BLE_GAP_SCAN_FAST_WINDOW, &m_srTimeoutTicks);
 } // NimBLEScan::NimBLEScan
 
 /**
@@ -206,6 +240,7 @@ int NimBLEScan::handleGapEvent(ble_gap_event* event, void* arg) {
                 }
 
                 if (isLegacyAdv && event_type == BLE_HCI_ADV_RPT_EVTYPE_SCAN_RSP) {
+                    srMissed();
                     NIMBLE_LOGI(LOG_TAG, "Scan response without advertisement: %s", advertisedAddress.toString().c_str());
                 }
 
@@ -217,6 +252,7 @@ int NimBLEScan::handleGapEvent(ble_gap_event* event, void* arg) {
                 advertisedDevice->update(event, event_type);
                 if (isLegacyAdv) {
                     if (event_type == BLE_HCI_ADV_RPT_EVTYPE_SCAN_RSP) {
+                        srStats(ble_npl_time_get() - advertisedDevice->m_time, pScan->m_scanParams.window * 625 / 1000);
                         NIMBLE_LOGI(LOG_TAG, "Scan response from: %s", advertisedAddress.toString().c_str());
                     } else {
                         NIMBLE_LOGI(LOG_TAG, "Duplicate; updated: %s", advertisedAddress.toString().c_str());
@@ -270,7 +306,23 @@ int NimBLEScan::handleGapEvent(ble_gap_event* event, void* arg) {
         case BLE_GAP_EVENT_DISC_COMPLETE: {
             ble_npl_callout_stop(&pScan->m_srTimer);
             NIMBLE_LOGD(LOG_TAG, "discovery complete; reason=%d", event->disc_complete.reason);
-
+# if MYNEWT_VAL(NIMBLE_CPP_LOG_LEVEL) >= 4
+            if (srCount > 0) {
+                NIMBLE_LOGD(LOG_TAG,
+                            "Scan response stats: count=%" PRIu32 ", min=%" PRIu32 " ms, max=%" PRIu32
+                            " ms, avg=%" PRIu32 " ms, missed=%" PRIu32,
+                            srCount,
+                            srMinMs,
+                            srMaxMs,
+                            srTotalMs / srCount,
+                            lateSrCount);
+            }
+            srCount     = 0;
+            srMinMs     = UINT32_MAX;
+            srMaxMs     = 0;
+            srTotalMs   = 0;
+            lateSrCount = 0;
+# endif
             pScan->m_pScanCallbacks->onScanEnd(pScan->m_scanResults, event->disc_complete.reason);
             if (pScan->m_maxResults == 0) {
                 pScan->clearResults();

src/nimconfig.h

@@ -69,14 +69,6 @@
 /** @brief Un-comment to change the stack size for the NimBLE host task */
 // #define MYNEWT_VAL_NIMBLE_HOST_TASK_STACK_SIZE 4096
 
-/**
- * @brief Un-comment to change the default scan response timeout, in milliseconds.
- * @details This is the time to wait for a scan response before calling the onResult scan callback,
- * lower values increase callback rates but will lose data more often, higher values give full data more
- * often. Setting this to 0 will disable the scan response timeout.
- */
- // #define MYNEWT_VAL_NIMBLE_CPP_SCAN_RSP_TIMEOUT (200)
-
 /**
  * @brief Un-comment to change the bit used to block tasks during BLE operations
  * that call NimBLEUtils::taskWait. This should be different than any other

src/syscfg/syscfg.h

@@ -2023,8 +2023,4 @@
 #define MYNEWT_VAL_NIMBLE_CPP_ENABLE_ADVERTISEMENT_TYPE_TEXT (0)
 #endif
 
-#ifndef MYNEWT_VAL_NIMBLE_CPP_SCAN_RSP_TIMEOUT
-#define MYNEWT_VAL_NIMBLE_CPP_SCAN_RSP_TIMEOUT (30)
-#endif
-
 #endif /* H_SYSCFG_ */