10 second delay after provision when using PB-ADV with PB-GATT enabled

[JonasJ]

When using the PB-ADV bearer there is a ~10 second delay after the Link is closed and the mesh stack starts working again.

This is related to my previous report https://devzone.nordicsemi.com/f/nordic-q-a/43992/10-second-delay-after-pb-gatt-completed-until-first-mesh-proxy-service-advertisement and https://devzone.nordicsemi.com/f/nordic-q-a/46583/scanner-is-disabled-after-provision-completes-with-pb-gatt-enabled-with-10-second-delay-workaround

I'm currently using the workaround suggested in the the above posts. However, while it works great for PB-GATT, it doesn't work for PB-ADV and the delay is still there.

Doing the initial workaround with scanner_disable()/scanner_enable() in nrf_mesh_disable()/nrf_mesh_enable() does actually improve the situation.

Here is a log from a node that is running a patched SDK For Mesh v3.1.0. Note the time between line 4 (Link opened) and line 15 (Provision Complete event) is ~10 seconds. I would expect that the Complete Event to happen quickly after the Link Closed Event. I've added a few more log lines to better spot where the delay is, i.e. it's waiting for the NRF_MESH_EVT_DISABLED event.

<t:      21882>, prov_bearer_adv.c  ,  400, PB-ADV: context at 0x20002CF0 added to bearer
<t:      21894>, mesh_app_utils.c   ,   65, Device UUID (raw): A6880470478AB741B644550AC49916F7
<t:      21898>, mesh_app_utils.c   ,   70, Device UUID : 700488A6-8A47-41B7-B644-550AC49916F7
<t:    1411152>, prov_bearer_adv.c  ,  849, PB-ADV: Link opened.
<t:    1413242>, prov_bearer_adv.c  ,  798, Received ACK for [ppdu1]
<t:    1419801>, prov_bearer_adv.c  ,  798, Received ACK for [ppdu3]
<t:    1426426>, prov_bearer_adv.c  ,  798, Received ACK for [ppdu5]
<t:    1428584>, prov_bearer_adv.c  ,  798, Received ACK for [ppdu6]
<t:    1432182>, prov_bearer_adv.c  ,  798, Received ACK for [ppdu8]
<t:    1432936>, mesh_provisionee.c ,  177, gatt_database_reset
<t:    1432940>, prov_bearer_adv.c  ,  904, PB-ADV: Link closed.
<t:    1740535>, mesh_provisionee.c ,   94, mesh_evt_handler
<t:    1740541>, mesh_provisionee.c ,  158, sd_state_evt_handler DISABLED
<t:    1740550>, mesh_provisionee.c ,  113, sd_state_evt_handler ENABLED
<t:    1741092>, main.c             ,   66, Successfully provisioned
<t:    1741102>, main.c             ,   76, Node Address: 0x002C

Thanks.

[Mttrinh]

Hi,

Doing the initial workaround with scanner_disable()/scanner_enable() in nrf_mesh_disable()/nrf_mesh_enable() does actually improve the situation.

How much does it improve? Does this delay also occur when you use an unmodified example from the SDK?

[JonasJ]

When running with an unmodified (almost, small modifications to the logging, see below) I get the following, notice the time difference between "gatt_database_reset" and "Successfully provisioned", ~9.5 seconds.

<t:       9308>, main.c,  218, Initializing and adding models
<t:       9312>, main.c,  113, App OnOff Model Handle: 2
<t:      14223>, prov_bearer_adv.c,  400, PB-ADV: context at 0x20003044 added to bearer
<t:      14236>, mesh_app_utils.c,   65, Device UUID (raw): 38E1F5E6712B054DAC7F4505C7950884
<t:      14241>, mesh_app_utils.c,   70, Device UUID : E6F5E138-2B71-4D05-AC7F-4505C7950884
<t:   15896418>, prov_bearer_adv.c,  849, PB-ADV: Link opened.
<t:   15898833>, prov_bearer_adv.c,  798, Received ACK for [ppdu1]
<t:   15905560>, prov_bearer_adv.c,  798, Received ACK for [ppdu3]
<t:   15912202>, prov_bearer_adv.c,  798, Received ACK for [ppdu5]
<t:   15914259>, prov_bearer_adv.c,  798, Received ACK for [ppdu6]
<t:   15917568>, prov_bearer_adv.c,  798, Received ACK for [ppdu8]
<t:   15918520>, mesh_provisionee.c,  176, gatt_database_reset
<t:   15918524>, prov_bearer_adv.c,  904, PB-ADV: Link closed.
<t:   15932489>, net_beacon.c,  265, BEACON TX CC:D8:7F:3
<t:   16229606>, mesh_provisionee.c,   94, mesh_evt_handler
<t:   16229613>, mesh_provisionee.c,  158, sd_state_evt_handler DISABLED
<t:   16229622>, mesh_provisionee.c,  113, sd_state_evt_handler ENABLED
<t:   16230166>, main.c,  198, Successfully provisioned
<t:   16230173>, main.c,  209, Node Address: 0x0013 

The SDK For Mesh 3.1.0 is running with the following patch

diff --git a/examples/common/src/mesh_provisionee.c b/examples/common/src/mesh_provisionee.c
index abffcfa..6f3be59 100644
--- a/examples/common/src/mesh_provisionee.c
+++ b/examples/common/src/mesh_provisionee.c
@@ -91,6 +91,8 @@ static void mesh_evt_handler(const nrf_mesh_evt_t * p_evt)
 {
     if (p_evt->type == NRF_MESH_EVT_DISABLED && m_doing_gatt_reset)
     {
+        __LOG(LOG_SRC_APP, LOG_LEVEL_DBG1, "%s\n", __func__);
+
         APP_ERROR_CHECK(nrf_sdh_disable_request());
         nrf_mesh_evt_handler_remove(&m_mesh_evt_handler);
     }
@@ -108,6 +110,8 @@ static void sd_state_evt_handler(nrf_sdh_state_evt_t state, void * p_context)
     {
         case NRF_SDH_EVT_STATE_ENABLED:
         {
+            __LOG(LOG_SRC_APP, LOG_LEVEL_DBG1, "%s ENABLED\n", __func__);
+
             uint32_t ram_start = 0;
             /* Set the default configuration (as defined through sdk_config.h). */
             uint32_t err_code = nrf_sdh_ble_default_cfg_set(MESH_SOFTDEVICE_CONN_CFG_TAG, &ram_start);
@@ -151,6 +155,7 @@ static void sd_state_evt_handler(nrf_sdh_state_evt_t state, void * p_context)
         }
         case NRF_SDH_EVT_STATE_DISABLED:
         {
+            __LOG(LOG_SRC_APP, LOG_LEVEL_DBG1, "%s DISABLED\n", __func__);
             uint32_t err_code = nrf_sdh_enable_request();
             APP_ERROR_CHECK(err_code);
             break;
@@ -168,6 +173,7 @@ NRF_SDH_STATE_OBSERVER(m_sdh_req_obs, MESH_PROVISIONEE_SDH_STATE_PRIORITY) =
 
 static void gatt_database_reset(void)
 {
+    __LOG(LOG_SRC_APP, LOG_LEVEL_DBG1, "%s\n", __func__);
     m_doing_gatt_reset = true;
     nrf_mesh_evt_handler_add(&m_mesh_evt_handler);
 
diff --git a/examples/light_switch/server/src/main.c b/examples/light_switch/server/src/main.c
index 5ccdf76..c854378 100644
--- a/examples/light_switch/server/src/main.c
+++ b/examples/light_switch/server/src/main.c
@@ -234,7 +234,7 @@ static void mesh_init(void)
 
 static void initialize(void)
 {
-    __LOG_INIT(LOG_SRC_APP | LOG_SRC_ACCESS | LOG_SRC_BEARER, LOG_LEVEL_INFO, LOG_CALLBACK_DEFAULT);
+    __LOG_INIT(0xFFFFFFFF, LOG_LEVEL_DBG3, LOG_CALLBACK_DEFAULT);
     __LOG(LOG_SRC_APP, LOG_LEVEL_INFO, "----- BLE Mesh Light Switch Server Demo -----\n");
 
     ERROR_CHECK(app_timer_init());

Applying the disable()/enable() workaround the log looks like this. This gives a delay of less than 2 ms.

<t:          0>, main.c,  238, ----- BLE Mesh Light Switch Server Demo -----
<t:       9324>, main.c,  218, Initializing and adding models
<t:       9328>, main.c,  113, App OnOff Model Handle: 2
<t:      14260>, prov_bearer_adv.c,  400, PB-ADV: context at 0x20003044 added to bearer
<t:      14273>, mesh_app_utils.c,   65, Device UUID (raw): 38E1F5E6712B054DAC7F4505C7950884
<t:      14277>, mesh_app_utils.c,   70, Device UUID : E6F5E138-2B71-4D05-AC7F-4505C7950884
<t:     518091>, prov_bearer_adv.c,  849, PB-ADV: Link opened.
<t:     520526>, prov_bearer_adv.c,  798, Received ACK for [ppdu1]
<t:     526390>, prov_bearer_adv.c,  798, Received ACK for [ppdu3]
<t:     532890>, prov_bearer_adv.c,  798, Received ACK for [ppdu5]
<t:     535182>, prov_bearer_adv.c,  798, Received ACK for [ppdu6]
<t:     538219>, prov_bearer_adv.c,  798, Received ACK for [ppdu8]
<t:     538977>, mesh_provisionee.c,  176, gatt_database_reset
<t:     538984>, prov_bearer_adv.c,  904, PB-ADV: Link closed.
<t:     538988>, mesh_provisionee.c,   94, mesh_evt_handler
<t:     538994>, mesh_provisionee.c,  158, sd_state_evt_handler DISABLED
<t:     539003>, mesh_provisionee.c,  113, sd_state_evt_handler ENABLED
<t:     539554>, main.c,  198, Successfully provisioned
<t:     539560>, main.c,  209, Node Address: 0x0016 

Thanks.

[Hung Bui]

Hi JonasJ, 

Actually there are 2 places need to be updated for that fix. Could you try the 2nd part (in bearer_handler_timer_irq_handler() ) as mentioned in this comment to see if it's improved: 
https://devzone.nordicsemi.com/f/nordic-q-a/43301/nrf_mesh_disable-function-changed-since-sdk-for-mesh-v3-1-0/180061#180061

[JonasJ]

Thanks, that solves the problem.