Help, Classic BT delays too long

dabraham
Posts: 2
Joined: Wed Apr 03, 2019 3:29 pm

Help, Classic BT delays too long

Postby dabraham » Wed Apr 10, 2019 6:02 pm

I coded up a classic BT master-slave communications program based upon examples at github in order to see the system delays when sending 16 data bytes on BT. The data I send is static - I am just measuring delay. I need to make a wireless CAN bridge for a cost-down solution in a system, and I need the delays to be as small as possible. The issue I have is that the delays are too long and I need some help on what to do/try next.

In the two pictures I have enclosed, the yellow trace is the master and the blue trace is the slave. Master sets a bit when a message is sent from a 1000 mS timer and clears the bit when the slave responds to the original sent message from the master. Slave sets a bit when message is received from master and clears the bit when the send to master event complete takes place. I triggered the scope on the rising edge of the slave bit (blue trace). The picture smallest.jpg represents the best timing I have seen and this can be acceptable for the product. The persistence.jpg file shows an accumulation of all samples for about one hour - or about 3,600 communication sessions. Here the large delays can be seen. 28ish mS from master send to master receive, and 88ish mS from slave send to master receive. These two nodes are the only BT devices in the area.

What is interesting is that slave blue trace occupies two BT time slots like it should (one rxed data and one tx data) without any addition delay or slot jitter. It appears on the other hand that many time slots are needed for the rxed data to actually trigger the rxed event. The max number of devices is set to 2 in sdkconfig, so I am curious as to why things are taking so very long.

I use Arduino 1.8.8 with the build 1.0.1 and doit devkit v1. I had to modify the sdkconfig in order to build. The debug level needs to be set to either error, information or debug. I am not a programmer, so excuse my coding.

Code: Select all


#include <cstdint>
#include <cstring>
#include "nvs.h"
#include "nvs_flash.h"
#include "esp_bt.h"
#include "esp_bt_main.h"
#include "esp_bt_device.h"
#include "esp_gap_bt_api.h"
#include "esp_spp_api.h"
#include "esp_log.h"

#define FOREVER                         1      
#define NOTKNOWN                        0  
#define SLAVE                           1  
#define MASTER                          2  
#define MSGDATALEN                      16

#define TESTPIN                        ((gpio_num_t)25)

static const char* TAG = "cBT";

constexpr auto bt_dev_name{"can_bt_bridge"};              // BT device name
constexpr auto bt_spp_server_name{"can_bt_server"};       // BT SPP server name

constexpr auto inquiry_duration_min{1};                   // Min and max inquiry duration (for BT discovery a random duration between min and max is picked)
constexpr auto inquiry_duration_max{2};

uint8_t               Connect = 0;
uint8_t               role = NOTKNOWN;
uint8_t               txbuf[MSGDATALEN];             // 
uint8_t               sendbuf = 0;
uint8_t               wrbufen = 0;

uint32_t              BTHandle = NULL; 
esp_bd_addr_t         own_bda{};                                          // Own BT device address
esp_bd_addr_t         remote_bda{};                                       // Remote BT device address
TaskHandle_t          TaskLoopPtr;


extern "C" void app_main()                                                                // Application called from ESP-IDF
{
    pinMode(TESTPIN, OUTPUT);
    digitalWrite(TESTPIN, 0);
  
    esp_err_t ret{nvs_flash_init()};                                                      // Initialize NVS it is used to store PHY calibration data
    if (ret == ESP_ERR_NVS_NO_FREE_PAGES || ret == ESP_ERR_NVS_NEW_VERSION_FOUND) 
    {
        ESP_ERROR_CHECK(nvs_flash_erase());
        ret = nvs_flash_init();
    }
    ESP_ERROR_CHECK(ret);

    bt_init();                                                                            // Initialize BT and UART
    bt_gap_init();
}

void bt_init()            // Initialize BT
{
    esp_err_t ret;
  
    ESP_ERROR_CHECK(esp_bt_controller_mem_release(ESP_BT_MODE_BLE));                                            // Release memory from BLE mode (which we don't need)
    esp_bt_controller_config_t bt_cfg = BT_CONTROLLER_INIT_CONFIG_DEFAULT();

    if (ret = esp_bt_controller_init(&bt_cfg)) 
        return (void)ESP_LOGE(TAG, "%s initialize controller failed: %s", __func__, esp_err_to_name(ret));

    if (ret = esp_bt_controller_enable(ESP_BT_MODE_CLASSIC_BT))                                                 // was ESP_BT_MODE_CLASSIC_BT, ESP_BT_MODE_BTDM 
        return (void)ESP_LOGE(TAG, "%s enable controller failed: %s", __func__, esp_err_to_name(ret));

//    esp_bt_sleep_disable();

    if (ret = esp_bluedroid_init()) 
        return (void)ESP_LOGE(TAG, "%s initialize bluedroid failed: %s", __func__, esp_err_to_name(ret));

    if (ret = esp_bluedroid_enable()) 
        return (void)ESP_LOGE(TAG, "%s enable bluedroid failed: %s", __func__, esp_err_to_name(ret));
}

void bt_gap_init()                // Initialize BT GAP
{
    esp_bt_sp_param_t param_type = ESP_BT_SP_IOCAP_MODE;                      // Set default parameters for Secure Simple Pairing
    esp_bt_io_cap_t iocap = ESP_BT_IO_CAP_IO;
    esp_bt_gap_set_security_param(param_type, &iocap, sizeof(uint8_t));

    esp_bt_pin_type_t pin_type = ESP_BT_PIN_TYPE_VARIABLE;                    // Set default parameters for Legacy Pairing, Use variable pin, input pin code when pairing
    esp_bt_pin_code_t pin_code;
    esp_bt_gap_set_pin(pin_type, 0, pin_code);

    esp_bt_dev_set_device_name(bt_dev_name);

    uint8_t const* adr{esp_bt_dev_get_address()};                             // Get own BT device address

    if (!adr) 
    {
        ESP_LOGE(TAG, "%s can't retrieve own address", __func__);
        return;
    }
    memcpy(own_bda, adr, sizeof(esp_bd_addr_t));
    char bda_str[18];
    ESP_LOGI(TAG, "Own address: %s", bda2str(own_bda, bda_str, 18));

    esp_bt_gap_set_scan_mode(ESP_BT_SCAN_MODE_CONNECTABLE_DISCOVERABLE);      // Set discoverable and connectable mode, wait to be connected
    esp_bt_gap_register_callback(bt_app_gap_cb);                              // Register GAP callback function
    esp_bt_gap_start_discovery(ESP_BT_INQ_MODE_GENERAL_INQUIRY, random_interval(inquiry_duration_min, inquiry_duration_max), 0);    // Start to discover nearby Bluetooth devices
}

void bt_spp_init()                          // Initialize BT SPP
{
    esp_err_t ret;
    
    ESP_LOGI(TAG, "SPP init");

    for (auto i{0u}; i < sizeof(esp_bd_addr_t); ++i)
        if (own_bda[i] < remote_bda[i])
        {
            role = SLAVE;
            ESP_LOGI(TAG, "Role is slave");
            if (ret = esp_spp_register_callback(bt_spp_slave_cb))
                return (void)ESP_LOGE(TAG, "%s spp register failed: %s", __func__, esp_err_to_name(ret));
            break;
        }
        else if (own_bda[i] > remote_bda[i])
        {
            role = MASTER;
            ESP_LOGI(TAG, "Role is master");
            if (ret = esp_spp_register_callback(bt_spp_master_cb))
                return (void)ESP_LOGE(TAG, "%s spp register failed: %s", __func__, esp_err_to_name(ret));
            break;
        }

    if (ret = esp_spp_init(ESP_SPP_MODE_CB))
        return (void)ESP_LOGE(TAG, "%s spp init failed: %s", __func__, esp_err_to_name(ret));
}

static uint32_t random_interval(uint32_t min, uint32_t max)       // Get random value between min and max, random only works when RF subsystem is enabled
{
    return min + (static_cast<float>(max - min) * esp_random()) / std::numeric_limits<uint32_t>::max();
}

static bool is_valid_bda(esp_bd_addr_t const& bda)              // Check if BT device address is valid, BT device address, return true/false  BT device address valid/invalid
{
    return std::any_of(std::begin(bda), std::end(bda), [](uint8_t v) { return v != 0; });
}

static char* bda2str(esp_bd_addr_t bda, char* str, size_t size) // Convert BT device address to string, BT device address, Buffer to write into, Maximum size of string, Pointer to buffer which contains string
{
    if (bda == NULL || str == NULL || size < 18)
        return NULL;

    uint8_t* p{bda};
    sprintf(str, "%02x:%02x:%02x:%02x:%02x:%02x", p[0], p[1], p[2], p[3], p[4], p[5]);

    return str;
}

static bool get_name_from_eir(uint8_t* eir, uint8_t* bdname, uint8_t* bdname_len) // Get BT device name from extended inquiry response,Pointer to extended inquiry response, Pointer to buffer for BT device name,Pointer to length of BT device name
{
    uint8_t rmt_bdname_len{0};

    if (!eir)
        return false;

    uint8_t* rmt_bdname{esp_bt_gap_resolve_eir_data(eir, ESP_BT_EIR_TYPE_CMPL_LOCAL_NAME, &rmt_bdname_len)};
    if (!rmt_bdname)
        rmt_bdname = esp_bt_gap_resolve_eir_data(eir, ESP_BT_EIR_TYPE_SHORT_LOCAL_NAME, &rmt_bdname_len);

    if (rmt_bdname) 
    {
        if (rmt_bdname_len > ESP_BT_GAP_MAX_BDNAME_LEN)
            rmt_bdname_len = ESP_BT_GAP_MAX_BDNAME_LEN;

        if (bdname) 
        {
            memcpy(bdname, rmt_bdname, rmt_bdname_len);
            bdname[rmt_bdname_len] = '\0';
        }
        if (bdname_len)
            *bdname_len = rmt_bdname_len;

        return true;
    }
    return false;
}


static bool is_remote_esp_device(esp_bt_gap_cb_param_t* param) 
{
    uint8_t bdname[ESP_BT_GAP_MAX_BDNAME_LEN + 1];                          // TODO Not sure if this doesn't blow up the stack? We have 3584 bytes which is a lot... but still?
    uint8_t bdname_len{0};
    char bda_str[18];
    esp_bt_gap_dev_prop_t* p;                                               // Bluetooth Device Property Descriptor
          
    ESP_LOGI(TAG, "Device found: %s", bda2str(param->disc_res.bda, bda_str, 18));

    for (int i{0u}; i < param->disc_res.num_prop; i++) 
    {
        p = param->disc_res.prop + i;
        switch (p->type) 
        {
            case ESP_BT_GAP_DEV_PROP_COD:                                 // Class of Device, value type is uint32_t
            {
                ESP_LOGI(TAG, "ESP_BT_GAP_DEV_PROP_COD");
                uint32_t cod{*(uint32_t*)(p->val)};
                ESP_LOGI(TAG, "--Class of Device: 0x%x", cod);
                break;
            }
            case ESP_BT_GAP_DEV_PROP_RSSI: 
            {
                ESP_LOGI(TAG, "ESP_BT_GAP_DEV_PROP_RSSI");         // Received Signal strength Indication, value type is int8_t, ranging from -128 to 127
                int32_t rssi{*(int8_t*)(p->val)};
                ESP_LOGI(TAG, "--RSSI: %d", rssi);
                break;
            }
            case ESP_BT_GAP_DEV_PROP_EIR: // Extended Inquiry Response
            {
                uint8_t eir[ESP_BT_GAP_EIR_DATA_LEN];
                ESP_LOGI(TAG, "ESP_BT_GAP_DEV_PROP_EIR");
                memcpy(eir, (uint8_t*)(p->val), p->len);
                get_name_from_eir(eir, bdname, &bdname_len);
                if (bdname_len > ESP_BT_GAP_MAX_BDNAME_LEN)
                bdname_len = ESP_BT_GAP_MAX_BDNAME_LEN;
                bdname[bdname_len] = '\0';
                ESP_LOGI(TAG, "Device name: %s", bdname);
                break;
            }
            case ESP_BT_GAP_DEV_PROP_BDNAME:                              // Bluetooth device name, value type is int8_t []
            {
                ESP_LOGI(TAG, "ESP_BT_GAP_DEV_PROP_BDNAME");
                bdname_len = (p->len > ESP_BT_GAP_MAX_BDNAME_LEN) ? ESP_BT_GAP_MAX_BDNAME_LEN : (uint8_t)p->len;
                memcpy(bdname, (uint8_t*)(p->val), bdname_len);
                bdname[bdname_len] = '\0';
                ESP_LOGI(TAG, "Device name: %s", bdname);
                break;
            }
        }
    }
    return bdname_len && !strcmp((char*)bdname, bt_dev_name);
}

static void bt_app_gap_cb(esp_bt_gap_cb_event_t event, esp_bt_gap_cb_param_t* param)  // BT GAP callback, event BT GAP callback events, param A2DP state callback parameters
{
    switch (event) 
    {
        case ESP_BT_GAP_DISC_STATE_CHANGED_EVT:                                       // discovery state changed event
            ESP_LOGI(TAG, "ESP_BT_GAP_DISC_STATE_CHANGED_EVT");
            if (param->disc_st_chg.state == ESP_BT_GAP_DISCOVERY_STOPPED && !is_valid_bda(remote_bda))  // Restart discovery if we haven't found remote esp
                esp_bt_gap_start_discovery(ESP_BT_INQ_MODE_GENERAL_INQUIRY, random_interval(inquiry_duration_min, inquiry_duration_max), 0);
            break;
            
        case ESP_BT_GAP_DISC_RES_EVT:                                                 // device discovery result event
            ESP_LOGI(TAG, "ESP_BT_GAP_DISC_RES_EVT");
            if (is_remote_esp_device(param))  // Found remote esp
            {
                memcpy(remote_bda, param->disc_res.bda, sizeof(esp_bd_addr_t));
                esp_bt_gap_cancel_discovery();
                bt_spp_init();
            }
            break;
            
        case ESP_BT_GAP_AUTH_CMPL_EVT: 
        {
            ESP_LOGI(TAG, "ESP_BT_GAP_AUTH_CMPL_EVT");
            if (param->auth_cmpl.stat == ESP_BT_STATUS_SUCCESS) 
            {
                ESP_LOGI(TAG, "authentication success: %s", param->auth_cmpl.device_name);
                esp_log_buffer_hex(TAG, param->auth_cmpl.bda, ESP_BD_ADDR_LEN);
            } 
            else 
            {
                ESP_LOGE(TAG, "authentication failed, status:%d", param->auth_cmpl.stat);
            }
            break;
        }
        case ESP_BT_GAP_PIN_REQ_EVT:                                          // Legacy Pairing Pin code request
        {
            ESP_LOGI(TAG, "ESP_BT_GAP_PIN_REQ_EVT");
            ESP_LOGI(TAG, "ESP_BT_GAP_PIN_REQ_EVT min_16_digit:%d", param->pin_req.min_16_digit);
            if (param->pin_req.min_16_digit) 
            {
                ESP_LOGI(TAG, "Input pin code: 0000 0000 0000 0000");
                esp_bt_pin_code_t pin_code{0};
                esp_bt_gap_pin_reply(param->pin_req.bda, true, 16, pin_code);
            } 
            else 
            {
                ESP_LOGI(TAG, "Input pin code: 1234");
                esp_bt_pin_code_t pin_code;
                pin_code[0] = '1';
                pin_code[1] = '2';
                pin_code[2] = '3';
                pin_code[3] = '4';
                esp_bt_gap_pin_reply(param->pin_req.bda, true, 4, pin_code);
            }
            break;
        }
        case ESP_BT_GAP_CFM_REQ_EVT:                                          // Simple Pairing User Confirmation request
            ESP_LOGI(TRAG, "ESP_BT_GAP_CFM_REQ_EVT");
            esp_bt_gap_ssp_confirm_reply(param->cfm_req.bda, true);
            break;

        case ESP_BT_GAP_RMT_SRVCS_EVT:                                        // get remote services event
            ESP_LOGI(TAG, "ESP_BT_GAP_RMT_SRVCS_EVT");
            break;
    
        case ESP_BT_GAP_RMT_SRVC_REC_EVT:                                     // get remote service record event
            ESP_LOGI(TAG, "ESP_BT_GAP_RMT_SRVC_REC_EVT");
            break;

        case ESP_BT_GAP_KEY_NOTIF_EVT:                                        // Simple Pairing Passkey Notification
            ESP_LOGI(TAG, "ESP_BT_GAP_KEY_NOTIF_EVT");
            break;

        case ESP_BT_GAP_KEY_REQ_EVT:                                          // Simple Pairing Passkey request
            ESP_LOGI(TAG, "ESP_BT_GAP_KEY_REQ_EVT");
            break;

        case ESP_BT_GAP_READ_RSSI_DELTA_EVT:                                  // read rssi event
            ESP_LOGI(TAG, "ESP_BT_GAP_READ_RSSI_DELTA_EVT");
            break;

        case ESP_BT_GAP_EVT_MAX:
            ESP_LOGI(TAG, "ESP_BT_GAP_EVT_MAX");
            break;
    }
}

static void bt_spp_master_cb(esp_spp_cb_event_t event, esp_spp_cb_param_t* param)       // spp master callback
{
    switch (event) 
    {
        case ESP_SPP_DATA_IND_EVT:                                                                    // When SPP connection received data, the event comes, only for ESP_SPP_MODE_CB
            ESP_LOGD(TAG, "ESP_SPP_DATA_IND_EVT");
            digitalWrite(TESTPIN, 0);                                                 // turn test off
            sendbuf++;                                                                  // bump send counter - used to transmit bufs  
            break;
        
        case ESP_SPP_INIT_EVT:                                                                        // When SPP is inited, the event comes
            ESP_LOGI(TAG, "ESP_SPP_INIT_EVT");
            esp_spp_start_discovery(remote_bda);
            break;

        case ESP_SPP_DISCOVERY_COMP_EVT:                                                              // When SDP discovery complete, the event comes
            ESP_LOGI(TAG, "ESP_SPP_DISCOVERY_COMP_EVT status=%d scn_num=%d", param->disc_comp.status, param->disc_comp.scn_num);
            if (param->disc_comp.status == ESP_SPP_SUCCESS)                                           // Discovery successful -> connect
                esp_spp_connect(ESP_SPP_SEC_AUTHENTICATE, ESP_SPP_ROLE_MASTER, param->disc_comp.scn[0], remote_bda);
            else
                esp_spp_start_discovery(remote_bda);          // Else restart discovery
            break;

        case ESP_SPP_CL_INIT_EVT:                                                                     // When SPP client initiated a connection, the event comes
            ESP_LOGI(bt_spp_master_tag, "ESP_SPP_CL_INIT_EVT");
            break;
            
        case ESP_SPP_OPEN_EVT:                                                                        // When SPP Client connection open, the event comes
            ESP_LOGI(TAG, "esp_bt_controller_is_sleeping %d", esp_bt_controller_is_sleeping());
            ESP_LOGI(TAG, "ESP_SPP_OPEN_EVT");
            xTaskCreate(TaskLoop,(const char *)"Loop", 2048, NULL, 3, &TaskLoopPtr);
            BTHandle = param->open.handle;
            Connect = 1;
            wrbufen = 1;
            break;

        case ESP_SPP_WRITE_EVT:                                                                       // When SPP write operation completes, the event comes, only for ESP_SPP_MODE_CB
            ESP_LOGD(TAG, "ESP_SPP_WRITE_EVT");
            wrbufen = 1;
            digitalWrite(TESTPIN, 1);                                                               // turn testpin on
            break;

        case ESP_SPP_SRV_OPEN_EVT:                                                                    // When SPP Server connection open, the event comes
            ESP_LOGD(TAG, "ESP_SPP_SRV_OPEN_EVT");
            break;
            
        case ESP_SPP_CLOSE_EVT:                                                                       // When SPP connection closed, the event comes
            ESP_LOGI(TAG, "ESP_SPP_CLOSE_EVT");
            esp_restart();                                          // could be an issue
            break;

        case ESP_SPP_START_EVT:                                                                       // When SPP server started, the event comes
            ESP_LOGI(TAG, "ESP_SPP_START_EVT");
            break;

        case ESP_SPP_CONG_EVT:                                                                        // When SPP connection congestion status changed, the event comes, only for ESP_SPP_MODE_CB
            ESP_LOGI(TAG, "ESP_SPP_CONG_EVT");
            break;
    }
}

static void bt_spp_slave_cb(esp_spp_cb_event_t event, esp_spp_cb_param_t* param)        // slave callback
{
    switch (event) 
    {
        case ESP_SPP_DATA_IND_EVT:                                                      // When SPP connection received data, the event comes, only for ESP_SPP_MODE_CB
            ESP_LOGD(bt_spp_slave_tag, "ESP_SPP_DATA_IND_EVT");
            digitalWrite(TESTPIN, 1);                                                 // turn testpin
            sendbuf++;
            break;
            
        case ESP_SPP_INIT_EVT:                                                                        // When SPP is inited, the event comes
            ESP_LOGI(TAG, "ESP_SPP_INIT_EVT");
            esp_spp_start_srv(ESP_SPP_SEC_AUTHENTICATE, ESP_SPP_ROLE_SLAVE, 0, bt_spp_server_name);
            break;

        case ESP_SPP_START_EVT:                                                                       // When SPP server started, the event comes
            ESP_LOGI(TAG, "ESP_SPP_START_EVT");
            break;

        case ESP_SPP_SRV_OPEN_EVT:                                                                    // When SPP Server connection open, the event comes
            ESP_LOGI(TAG, "ESP_SPP_SRV_OPEN_EVT");
            xTaskCreate(TaskLoop,(const char *)"Loop", 2048, NULL, 3, &TaskLoopPtr);
            BTHandle = param->open.handle;
            Connect = 1;
            wrbufen = 1;
            break;

        case ESP_SPP_WRITE_EVT:                                                                       // When SPP write operation completes, the event comes, only for ESP_SPP_MODE_CB
            ESP_LOGD(TAG, "ESP_SPP_WRITE_EVT");
            wrbufen = 1;
            digitalWrite(TESTPIN, 0);                                                               // turn testpin off
            break;
            
        case ESP_SPP_CLOSE_EVT:                                                                       // When SPP connection closed, the event comes
            ESP_LOGI(TAG, "ESP_SPP_CLOSE_EVT");
            esp_restart();                                          // could be an issue
            break;
            
        case ESP_SPP_DISCOVERY_COMP_EVT:                                                              // When SDP discovery complete, the event comes
            ESP_LOGI(TAG, "ESP_SPP_DISCOVERY_COMP_EVT");
            break;

        case ESP_SPP_OPEN_EVT:                                                                        // When SPP Client connection open, the event comes
            ESP_LOGI(TAG, "ESP_SPP_OPEN_EVT");
            break;

        case ESP_SPP_CL_INIT_EVT:                                                                     // When SPP client initiated a connection, the event comes
            ESP_LOGI(TAG, "ESP_SPP_CL_INIT_EVT");
            break;

        case ESP_SPP_CONG_EVT:                                                                        // When SPP connection congestion status changed, the event comes, only for ESP_SPP_MODE_CB
            ESP_LOGI(TAG, "ESP_SPP_CONG_EVT");
            break;
    }
}

void  TaskLoop(void *pvParameters)
{
    while(FOREVER)
    {
        if ((role==SLAVE) && sendbuf && wrbufen)                                   
        {
            if (esp_spp_write(BTHandle, MSGDATALEN, &txbuf[0]) == ESP_OK)            // Write data to SPP
            {
                wrbufen = 0;
                sendbuf--;
            }
        }
        
        if ((role==MASTER) && wrbufen)                                   
        {
            if (esp_spp_write(BTHandle, MSGDATALEN, &txbuf[0]) == ESP_OK)            // Write data to SPP
            {
                wrbufen = 0;
                sendbuf--;
                delay(1000);
            }
        }
    }
}

Attachments
sdkconfig.h
(14.62 KiB) Downloaded 516 times
persistence.JPG
persistence.JPG (2.27 MiB) Viewed 2594 times
Smallest.JPG
Smallest.JPG (1.93 MiB) Viewed 2594 times

Who is online

Users browsing this forum: Baidu [Spider], Google [Bot] and 176 guests