Surprisingly high packet loss over wired network using the nRF5340 DK and J1 SWF connector

[jalgroy]

Hi,

We're doing some testing of mesh protocols and their latencies using the nRF5340 DK. We want to isolate the wireless communication from interference as much as possible, and have set up a wired coaxial network which we connect the DK to using the J1 SWF connector. From the nRF5340 user guide: "When connecting the testprobe, the internal switch in the SWF connector will disconnect the onboard antenna and connect the RF signal from the nRF5340SoC to the test probe."

We are however observing a very similar rate of packet loss in both open air and through the coaxial network. Our assumption was be that the packet loss in open-air testing primarily comes from wireless interference, but that would suggest we should see a significant improvement in packet loss when testing in a coax network, which we do not.

Either our assumptions about where packet loss comes from are wrong, or we are wrong in our assumption about how isolated the wired connection is. If someone could enlighten us it would be greatly appreciated.

For reference, a description of our test setup for one-way single-hop latency of Bluetooth Mesh, and results for both open-air and isolated:

We're using two nRF5340 Dev Kits with Zephyr, using Bluetooth Mesh from the Zephyr Bluetooth stack. To measure one-way latency, we have a wired GPIO connection from the transmitter to the receiver, which is used to trigger an interrupt at the receiver at the time of transmission. This interrupt starts a timer that stops once the Bluetooth Mesh message is received. We record the latency and repeat for 10 000 messages.

See the CDFs for the latency in both open air and isolated testing. Note the log scale on the y-axis. The sudden jump from ~4ms to ~24ms is due to a (configurable) 20ms interval between retransmissions in bluetooth mesh, and the position of this jump on the y-axis indicates the probability of packet loss on the first transmission. Note the similarity of open air and isolated testing.

[Hung Bui]

Hi Jal, 

Could you give more information about the firmware you run on the transmitter and the receiver ? 
Would the receive does any BLE advertising ? any proxy feature ? or transmitting/relaying any mesh data ? 

Please correct me if I'm wrong, from the graph the rate of packets that need to be retransmitted (>20ms) is a few percent ? Could you provide a chart or something with more detailed info other than the graph ? 

I suspect that the packet drop rate was related to the period when the receive was not in receiving mode and that would explain why you see the same rate between open air and isolated testing as it's not related to the actual radio communication. 

[jalgroy]

Hi and thanks for the reply.

The receiver not being in receive mode has crossed my mind, but I don't see why the receiver would be transmitting. I have the following bluetooth options in my prj.conf:

CONFIG_BT=y
CONFIG_BT_DEBUG_LOG=n
CONFIG_BT_OBSERVER=y
CONFIG_BT_BROADCASTER=y
CONFIG_BT_CTLR_TX_PWR_MINUS_20=y

CONFIG_BT_MESH=y
CONFIG_BT_MESH_RELAY=y
CONFIG_BT_MESH_BEACON_ENABLED=n
CONFIG_BT_MESH_GATT_PROXY=n
CONFIG_BT_MESH_FRIEND=n
CONFIG_BT_MESH_LOW_POWER=n
CONFIG_BT_MESH_DEFAULT_TTL=4
CONFIG_BT_MESH_NETWORK_TRANSMIT_COUNT=2
CONFIG_BT_MESH_NETWORK_TRANSMIT_INTERVAL=20
CONFIG_BT_MESH_RELAY_RETRANSMIT_COUNT=3
CONFIG_BT_MESH_RELAY_RETRANSMIT_INTERVAL=20
CONFIG_BT_MESH_SUBNET_COUNT=1
CONFIG_BT_MESH_APP_KEY_COUNT=1
CONFIG_BT_MESH_PB_ADV=n
CONFIG_BT_MESH_CFG_CLI=y
CONFIG_BT_MESH_TX_SEG_MAX=16
CONFIG_BT_MESH_RX_SEG_MAX=16
CONFIG_BT_MESH_TX_SEG_MSG_COUNT=8
CONFIG_BT_MESH_ADV_BUF_COUNT=64
CONFIG_BT_MESH_LOOPBACK_BUFS=20
CONFIG_BT_MESH_MSG_CACHE_SIZE=32

As you can see, beacon and gatt proxy is disabled. I have not explicitly configured BLE advertising so I'm assuming that's not happening either. The receiver has relay enabled, however all the packets are unicast and addressed to the receiver, so they should not be relayed. Are there any other reasons the receiver might be transmitting? I'll add the main.c code below in case there is an obvious mistake.

Please correct me if I'm wrong, from the graph the rate of packets that need to be retransmitted (>20ms) is a few percent ? Could you provide a chart or something with more detailed info other than the graph ?

Yes, about 3% of the packets need to be retransmitted. Not sure exactly what you're looking for, I can provide the raw list of latencies measured if that is helpful.

main.c:

#include <stdlib.h>
#include <string.h>
#include <stdint.h>

#include <sys/printk.h>
#include <random/rand32.h>

#include <settings/settings.h>

#include <bluetooth/bluetooth.h>
#include <bluetooth/mesh.h>

#include <shell/shell.h>

#include <logging/log.h>

#include "gpio.h"

#ifndef NODE_ADDR
#define NODE_ADDR 0x0002
#endif

#define MOD_LF 0x0000

#define DEST_ADDR 0x0001

#define LATENCY_OPCODE BT_MESH_MODEL_OP_3(0x00, BT_COMP_ID_LF)

LOG_MODULE_REGISTER(main, LOG_LEVEL_INF);

/* Define nrfx timer */
static uint32_t tx_time = 0;

static const uint8_t net_key[16] = {
    0x01, 0x23, 0x45, 0x67, 0x89, 0xab, 0xcd, 0xef,
    0x01, 0x23, 0x45, 0x67, 0x89, 0xab, 0xcd, 0xef,
};
static const uint8_t dev_key[16] = {
    0x01, 0x23, 0x45, 0x67, 0x89, 0xab, 0xcd, 0xef,
    0x01, 0x23, 0x45, 0x67, 0x89, 0xab, 0xcd, 0xef,
};
static const uint8_t app_key[16] = {
    0x01, 0x23, 0x45, 0x67, 0x89, 0xab, 0xcd, 0xef,
    0x01, 0x23, 0x45, 0x67, 0x89, 0xab, 0xcd, 0xef,
};
static const uint16_t net_idx;
static const uint16_t app_idx;
static const uint32_t iv_index;
static uint8_t flags;
static uint16_t addr = NODE_ADDR;

static struct bt_mesh_model root_models[] = {
    BT_MESH_MODEL_CFG_SRV,
};

static void vnd_latency_callback(struct bt_mesh_model *model,
                     struct bt_mesh_msg_ctx *ctx,
                     struct net_buf_simple *buf)
{
    /* Record time immediately */ 
    uint32_t recv_time = k_cycle_get_32();

    if (ctx->addr == NODE_ADDR)
    {
        /* Our own message, ignore */
        return;
    }

    LOG_INF("Received %d byte message.", buf->len);

    uint32_t diff = recv_time - tx_time;
    if (recv_time < tx_time)
    {
        /* Correct overflow */
        diff = (UINT32_MAX - tx_time) + recv_time;
    }
    /* Convert to microseconds */
    uint32_t latency = k_cyc_to_us_floor32(diff);
    printk("latency: %d\n", latency);

    LOG_INF("src 0x%04x\n", ctx->addr);
}

static const struct bt_mesh_model_op vnd_ops[] = {
    { LATENCY_OPCODE, 0, vnd_latency_callback },
    BT_MESH_MODEL_OP_END,
};

static struct bt_mesh_model vnd_models[] = {
    BT_MESH_MODEL_VND(BT_COMP_ID_LF, MOD_LF, vnd_ops, NULL, NULL),
};

static struct bt_mesh_elem elements[] = {
    BT_MESH_ELEM(0, root_models, vnd_models),
};

static const struct bt_mesh_comp comp = {
    .cid = BT_COMP_ID_LF,
    .elem = elements,
    .elem_count = ARRAY_SIZE(elements),
};

static void configure(void)
{
    LOG_INF("Configuring...\n");

    /* Add Application Key */
    bt_mesh_cfg_app_key_add(net_idx, addr, net_idx, app_idx, app_key, NULL);

    /* Bind to vendor model */
    bt_mesh_cfg_mod_app_bind_vnd(net_idx, addr, addr, app_idx,
                     MOD_LF, BT_COMP_ID_LF, NULL);

    /* Add model subscription */
    bt_mesh_cfg_mod_sub_add_vnd(net_idx, addr, addr, DEST_ADDR,
                    MOD_LF, BT_COMP_ID_LF, NULL);

    LOG_INF("Configuration complete\n");

}

static const uint8_t dev_uuid[16] = { 0xdd, 0xdd };

static const struct bt_mesh_prov prov = {
    .uuid = dev_uuid,
};

static void bt_ready(int err)
{
    if (err) {
        LOG_INF("Bluetooth init failed (err %d)\n", err);
        return;
    }

    LOG_INF("Bluetooth initialized\n");

    err = bt_mesh_init(&prov, &comp);
    if (err) {
        LOG_INF("Initializing mesh failed (err %d)\n", err);
        return;
    }

    LOG_INF("Mesh initialized\n");

    if (IS_ENABLED(CONFIG_BT_SETTINGS)) {
        LOG_INF("Loading stored settings\n");
        settings_load();
    }

    err = bt_mesh_provision(net_key, net_idx, flags, iv_index, addr,
                dev_key);
    if (err == -EALREADY) {
        LOG_INF("Using stored settings\n");
    } else if (err) {
        LOG_INF("Provisioning failed (err %d)\n", err);
        return;
    } else {
        LOG_INF("Provisioning completed\n");
        configure();
    }
}

static int cmd_send(const struct shell *shell, size_t argc, char **argv)
{
    int length = 1;
    if (argc > 1)
    {
        length = atoi(argv[1]);
        if (length == 0)
        {
            length = 1;
        }
    }

    NET_BUF_SIMPLE_DEFINE(msg, 3 + length + 4);
    struct bt_mesh_msg_ctx ctx = {
        .net_idx = net_idx,
        .app_idx = app_idx,
        .addr = DEST_ADDR,
        .send_ttl = BT_MESH_TTL_DEFAULT,
    };
    
    bt_mesh_model_msg_init(&msg, LATENCY_OPCODE);
    net_buf_simple_add(&msg, length);

    LOG_INF("Sending %d byte message with OpCode 0x%06x\n", msg.len, LATENCY_OPCODE);
    
    GPIO_set_tx(true);
    if (bt_mesh_model_send(&vnd_models[0], &ctx, &msg, NULL, NULL)) {
        LOG_INF("Unable to send latency test message\n");
    }

    k_msleep(10);
    GPIO_set_tx(false);
    
    return 0;
}

void gpio_callback(void)
{
    tx_time = k_cycle_get_32();
}

SHELL_CMD_REGISTER(send, NULL, "Send test packet", cmd_send);

void main(void)
{
    int err;

    LOG_INF("Initializing...\n");

    GPIO_init(gpio_callback);
    
    LOG_INF("Unicast address: 0x%04x\n", addr);
    
    /* Initialize the Bluetooth Subsystem */
    err = bt_enable(bt_ready);
    if (err) {
        LOG_ERR("Bluetooth init failed (err %d)\n", err);
    }
    k_msleep(2000);
}

[Hung Bui]

Hi Jal, 

I was looking for some statistic numbers for example the number of packets with latency longer than 20ms, 40ms and so on. Just so it's easier to get the % of retransmission packet. 

In the main.c file you sent, was it for the receiver ? 

Was the packet you send from the transmitter has the unicast address of the receive or it's the address that the receive subscribed to (0x0001 ? )

If it's not the unicast address of the receive, the receiver would relay the message (you have CONFIG_BT_MESH_RELAY = y). This will reduce the time the receive can listen. Could you try testing with CONFIG_BT_MESH_RELAY = n ? 

[jalgroy]

Some numbers from the test with 10 000 packets:

- 97.1% of packets are below 5 ms

- 2.9% of packets above 20ms

- 0.1% of packets above 40ms

- No packets above 60ms.

The main.c was for the receiver, but the transmitter is the same except that NODE_ADDR and DEST_ADDR is switched around. So I'm sending to 0x0002, which is the unicast address of the receiver.

I ran a new test (1000 packets) with CONFIG_BT_MESH_RELAY=n and had similar results:

- 96.7% below 5ms

- 3.3% above 20ms

- 0.1% above 40ms

[Hung Bui]

Hi Jal, 

I have discussed with the mesh team internally and found that the statistics you found matched with our measurement in house. 

We are trying to optimize the softdevice controller on the nRF53 to improve mesh performance. We are expecting to have better performance in the next release of the NCS SDK v1.6 

Our suggestion is to continue development on v1.5 and update to v1.6 when we have it ready.