BLE Mesh Latency Measurements not Matching Public Nordic Testing Data

[Cam Martell]

I am using 2 nRF528400DK boards. Each board has a unique BLE Mesh sample loaded. The samples were made by modifying the default mesh sample provided by zephyr. One sample acts as a BLE Mesh publisher and the other sample acts as a BLE Mesh subscriber. They each use a custom model, and after being provisioned into the same network via the NRF Mesh app, the publisher sends period basic BLE Mesh messages to the subscriber and the subscriber, after receiving a message, sends the same BLE Mesh message back to the publisher. All messages are unicast, and the samples work as expected without any issues.

For testing, I included a timer on the publisher device. The time is started before publishing a BLE Mesh message and a round-trip latency time is calculated after receiving a response back from the subscriber device. The goal of my testing is to evaluate the Nordic BLE Mesh solution against the publicly posted Nordic BLE Mesh testing blog: https://devzone.nordicsemi.com/nordic/nordic-blog/b/blog/posts/large-scale-bluetooth-mesh-testing#mcetoc_1gsjs1houb

The test results from this blog claim a round-trip latency of around 30ms. I would expect to see similar numbers. However, the timer measurements I see are 60ms - 70ms which is over twice as long. Am I misunderstanding the blog, or is my implementation of round-trip latency measuring off in some way? Were some enhancements made to the testing done by Nordic for this blog that improved latency measurements?

The relevant code for my samples can be found here:

Publisher:

/* main.c - Application main entry point */

/*
 * Copyright (c) 2017 Intel Corporation
 *
 * SPDX-License-Identifier: Apache-2.0
 */

 #include <zephyr/sys/printk.h>

 #include <zephyr/settings/settings.h>
 
 #include <zephyr/bluetooth/bluetooth.h>
 #include <zephyr/bluetooth/mesh.h>
 
 #include "board.h"
 
 #include <stdlib.h> // Include for strtol
 #include <zephyr/drivers/gpio.h>
 #include <zephyr/drivers/hwinfo.h>

 #include <zephyr/bluetooth/mesh/cfg_cli.h>
 
 /** Custom Pub Model ID */
 #define CUSTOM_MODEL_ID	0x0010
 /** Custom Pub Model Op Code Size */
 #define CUSTOM_OP_CODE_SIZE	3
 /** Custom Pub Model Payload Op Code */
 #define CUSTOM_OP	BT_MESH_MODEL_OP_3(0x01, CONFIG_BT_COMPANY_ID)

//  #define MSG_BUFFER_SIZE 3
#define MSG_BUFFER_SIZE 16
 
 static uint8_t hex_to_nibble(char c)
 {
	 if (c >= '0' && c <= '9') {
		 return c - '0';
	 } else if (c >= 'A' && c <= 'F') {
		 return c - 'A' + 10;
	 } else if (c >= 'a' && c <= 'f') {
		 return c - 'a' + 10;
	 } else {
		 return 0; // Invalid character
	 }
 }
 
 void hex_str_to_byte_array(const char *hex_str, uint8_t *byte_array, size_t byte_array_size)
 {
	 for (size_t i = 0; i < byte_array_size; i++) {
		 byte_array[i] = (hex_to_nibble(hex_str[2 * i]) << 4) | hex_to_nibble(hex_str[2 * i + 1]);
	 }
 }
 
 static uint8_t net_key[16];
 static uint8_t dev_key[16];
 static uint8_t app_key[16];
 
 static const uint16_t net_idx = 0x0000;
 static const uint16_t app_idx = 0x0000;
 static const uint32_t iv_index = 0x00000000;
 static uint16_t packet_ID;
 static uint16_t last_packet_ID;
 static uint8_t flags;

static uint16_t subscriber_count = 1;
static uint16_t subscriber_start_addr = 0x0009;
static uint16_t subscriber_current_pub_addr;
static uint32_t subscriber_response_count[1];

static struct k_timer pub_ack_timer;
static uint64_t pub_start_time_ms;
static uint32_t elapsed_time_ms;
static uint64_t total_elapsed_time_ms;
static uint32_t successful_ack_count;
static uint32_t total_packets_sent;
 
static int custom_ack_recv(const struct bt_mesh_model *model,
						   struct bt_mesh_msg_ctx *ctx,
						   struct net_buf_simple *buf)
{
	pub_gpio2_set(true);

	// Calculate the elapsed time
    elapsed_time_ms = k_uptime_get() - pub_start_time_ms;

	// Validate that the payload length is at least 2 bytes
	if (buf->len < 2) {
		printk("Invalid payload length: %u\n", buf->len);
		return -EINVAL;
	}

	// Extract the 2-byte packet ID
	uint16_t received_ID = net_buf_simple_pull_le16(buf);

	// Check if the received packet ID matches the last packet ID sent
	if (received_ID != last_packet_ID) {
		printk("!!!Received packet ID does not match the last packet ID sent!!!\n\n\n");
		return -EINVAL;
	}

	// Update the rolling average
    total_elapsed_time_ms += elapsed_time_ms; // Add the new elapsed time to the total
    successful_ack_count++;                              // Increment the acknowledgment count
    uint32_t rolling_avg_ms = total_elapsed_time_ms / successful_ack_count; // Calculate the rolling average

	// Calculate the success rate
    uint32_t success_rate = 0;
    if (total_packets_sent > 0) {
        success_rate = (successful_ack_count * 100) / total_packets_sent;
    }

	// Track the response for the specific subscriber
    uint16_t subscriber_index = ctx->addr - subscriber_start_addr;
    if (subscriber_index < subscriber_count) {
        subscriber_response_count[subscriber_index]++;
    }

	printk("\n\n");

	return 0; // Return success
}
 
static int publish_update(const struct bt_mesh_model *model);

static struct bt_mesh_cfg_cli cfg_cli = {
};

static void attention_on(const struct bt_mesh_model *mod)
{
	board_led_0_blink();
}

static void attention_off(const struct bt_mesh_model *mod)
{
	board_led_0_blink();
}

static const struct bt_mesh_health_srv_cb health_cb = {
	.attn_on = attention_on,
	.attn_off = attention_off,
};

static struct bt_mesh_health_srv health_srv = {
	.cb = &health_cb,
};
 
BT_MESH_HEALTH_PUB_DEFINE(health_pub, 0);
 
static const struct bt_mesh_model models[] = {
    BT_MESH_MODEL_CFG_SRV,
	BT_MESH_MODEL_CFG_CLI(&cfg_cli),
    BT_MESH_MODEL_HEALTH_SRV(&health_srv, &health_pub),
};

static const struct bt_mesh_model_op custom_model_ops[] = {
    { CUSTOM_OP, 0, custom_ack_recv },
    BT_MESH_MODEL_OP_END,
};

BT_MESH_MODEL_PUB_DEFINE(vendor_model_pub, publish_update, MSG_BUFFER_SIZE);
 
static struct bt_mesh_model vnd_models[] = {
    BT_MESH_MODEL_VND(
        CONFIG_BT_COMPANY_ID, // Vendor-specific company ID
        CUSTOM_MODEL_ID,      // Vendor-specific model ID
        custom_model_ops,        // Operation table
        &vendor_model_pub,                 // No user data needed
		NULL
    ),
};
 
static const struct bt_mesh_elem elements[] = {
	BT_MESH_ELEM(0, models, vnd_models),
};
 
static const struct bt_mesh_comp comp = {
	.cid = BT_COMP_ID_LF,
	.elem = elements,
	.elem_count = ARRAY_SIZE(elements),
};

static int publish_update(const struct bt_mesh_model *model)
{
	if (!model || !model->pub) {
		return -EINVAL;
	}

	/* Reset the message buffer */
    net_buf_simple_reset(model->pub->msg);

    /* Initialize the message buffer with the opcode */
    bt_mesh_model_msg_init(model->pub->msg, CUSTOM_OP);

    /* Add payload to the message */
    net_buf_simple_add_le16(vnd_models[0].pub->msg, packet_ID++); // Add a 16-bit value in little-endian format
	last_packet_ID++;

	/* Set the publication address to the current subscriber */
    model->pub->addr = subscriber_current_pub_addr;

	/* Record the start time */
    pub_start_time_ms = k_uptime_get();

	total_packets_sent++;

	/* Move to the next subscriber */
    subscriber_current_pub_addr++;
    if (subscriber_current_pub_addr >= subscriber_start_addr + subscriber_count) {
        subscriber_current_pub_addr = subscriber_start_addr; // Wrap around to the first subscriber
    }

	return 0;
}

static void configure_publish_params(void)
{
    vendor_model_pub.addr = subscriber_start_addr; // Set the publish start address
    vendor_model_pub.key = app_idx;    // Set the application key index
    vendor_model_pub.ttl = BT_MESH_TTL_DEFAULT; // Set the TTL
	vendor_model_pub.period = BT_MESH_PUB_PERIOD_SEC(3);
}
 
 static const uint8_t dev_uuid[16] = { 0xee, 0xee };

 static const struct bt_mesh_prov prov = {
	 .uuid = dev_uuid,
 }; 
 
 static void bt_ready(int err)
 {
	if (err) {
		printk("Bluetooth init failed (err %d)\n", err);
		return;
	}

	printk("Bluetooth initialized\n");

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

	if (IS_ENABLED(CONFIG_SETTINGS)) {
		settings_load();
	}

	/* Enable provisioning */
	bt_mesh_prov_enable(BT_MESH_PROV_ADV | BT_MESH_PROV_GATT);

	printk("Mesh initialized\n");

	/* Configure publication parameters */
    configure_publish_params();

    /* Check if the device is already provisioned */
    if (bt_mesh_is_provisioned()) {
        printk("Device is already provisioned. Starting periodic publishing...\n");

		/* Prepare the publication message */
		net_buf_simple_reset(vnd_models[0].pub->msg);
		net_buf_simple_add_le16(vnd_models[0].pub->msg, packet_ID++); // Add a 16-bit value in little-endian format
		last_packet_ID++;

        /* Start periodic publication */
        err = bt_mesh_model_publish(&vnd_models[0]);
        if (err) {
            printk("Failed to start periodic publication (err %d)\n", err);
        } else {
            printk("Periodic publication started\n");
        }
    } else {
        printk("Device is not provisioned. Waiting for provisioning...\n");
    }
 }
 
 int main(void)
 {
	// Initialize publish info
	packet_ID = 0x0001;
	last_packet_ID = 0x0000;
	subscriber_current_pub_addr = subscriber_start_addr;
	for (int i = 0; i < subscriber_count; i++) {
		subscriber_response_count[i] = 0;
	}

	// Initialize the timer
    k_timer_init(&pub_ack_timer, NULL, NULL);
	total_elapsed_time_ms = 0;
	successful_ack_count = 0;
	total_packets_sent = 0;

	int err = 0;
 
	 printk("Initializing...\n");

	 /* Initialize LEDs */
	err = leds_init();
	if (err) {
		printk("LEDs init failed (err: %d)\n", err);
		return 0;
	}
 
	 /* Initialize the Bluetooth Subsystem */
	 err = bt_enable(bt_ready);
	 if (err) {
		 printk("Bluetooth init failed (err %d)\n", err);
		 return 0;
	 }
 
	 return 0;
 }
 

Subscriber:

/* main.c - Application main entry point */

/*
 * Copyright (c) 2017 Intel Corporation
 *
 * SPDX-License-Identifier: Apache-2.0
 */

 #include <zephyr/sys/printk.h>

 #include <zephyr/settings/settings.h>
 
 #include <zephyr/bluetooth/bluetooth.h>
 #include <zephyr/bluetooth/mesh.h>
 
 #include "board.h"
 
 #include <stdlib.h> // Include for strtol
 #include <zephyr/drivers/gpio.h>
 #include <zephyr/drivers/hwinfo.h>

 #include <zephyr/bluetooth/mesh/cfg_cli.h>
 
 /** Custom Pub Model ID */
 #define CUSTOM_MODEL_ID	0x0010
 /** Custom Pub Model Op Code Size */
 #define CUSTOM_OP_CODE_SIZE	3
 /** Custom Pub Model Payload Op Code */
 #define CUSTOM_OP	BT_MESH_MODEL_OP_3(0x01, CONFIG_BT_COMPANY_ID)
 
 static uint8_t hex_to_nibble(char c)
 {
	 if (c >= '0' && c <= '9') {
		 return c - '0';
	 } else if (c >= 'A' && c <= 'F') {
		 return c - 'A' + 10;
	 } else if (c >= 'a' && c <= 'f') {
		 return c - 'a' + 10;
	 } else {
		 return 0; // Invalid character
	 }
 }
 
 void hex_str_to_byte_array(const char *hex_str, uint8_t *byte_array, size_t byte_array_size)
 {
	 for (size_t i = 0; i < byte_array_size; i++) {
		 byte_array[i] = (hex_to_nibble(hex_str[2 * i]) << 4) | hex_to_nibble(hex_str[2 * i + 1]);
	 }
 }
 
 static uint8_t net_key[16];
 static uint8_t dev_key[16];
 static uint8_t app_key[16];
 
 static const uint16_t net_idx = 0x0000;
 static const uint16_t app_idx = 0x0000;
 static const uint32_t iv_index = 0x00000000;
 static uint8_t flags;
 
 static int custom_hb_recv(const struct bt_mesh_model *model,
						   struct bt_mesh_msg_ctx *ctx,
						   struct net_buf_simple *buf)
 {
	 pub_gpio1_set(true);
	 
	 // Validate that the payload length is at least 2 bytes
	 if (buf->len < 2) {
		 printk("Invalid payload length: %u\n", buf->len);
		 return -EINVAL;
	 }
 
	 // Extract the 2-byte packet ID
	 uint16_t packet_id = net_buf_simple_pull_le16(buf);
 
	 // Prepare a response message
	 struct net_buf_simple *msg = NET_BUF_SIMPLE(16); // Adjust size as needed
	 bt_mesh_model_msg_init(msg, CUSTOM_OP);         // Use the same or a different opcode
	 net_buf_simple_add_le16(msg, packet_id);    // Example: Increment the packet ID
 
	 // Blink the LED to indicate ACK was sent
	 board_led_0_blink();
 
	 return 0; // Return success
 }
 
 static struct bt_mesh_cfg_cli cfg_cli = {
 };
 
 static void attention_on(const struct bt_mesh_model *mod)
 {
	 board_led_0_blink();
 }
 
 static void attention_off(const struct bt_mesh_model *mod)
 {
	 board_led_0_blink();
 }
 
 static const struct bt_mesh_health_srv_cb health_cb = {
	 .attn_on = attention_on,
	 .attn_off = attention_off,
 };
 
 static struct bt_mesh_health_srv health_srv = {
	 .cb = &health_cb,
 };
 
 BT_MESH_HEALTH_PUB_DEFINE(health_pub, 0);
 
 struct bt_mesh_model models[] = {
	 BT_MESH_MODEL_CFG_SRV,
	 BT_MESH_MODEL_CFG_CLI(&cfg_cli),
	 BT_MESH_MODEL_HEALTH_SRV(&health_srv, &health_pub),
 };
 
 static const struct bt_mesh_model_op custom_hb_ops[] = {
	 { CUSTOM_OP, 0, custom_hb_recv },
	 BT_MESH_MODEL_OP_END,
 };
 
 static struct bt_mesh_model vnd_models[] = {
	 BT_MESH_MODEL_VND(
		 CONFIG_BT_COMPANY_ID, // Vendor-specific company ID
		 CUSTOM_MODEL_ID,      // Vendor-specific model ID
		 custom_hb_ops,        // Operation table
		 NULL,                 // No user data neededy
		 NULL
	 ),
 };
 
 static const struct bt_mesh_elem elements[] = {
	 BT_MESH_ELEM(0, models, vnd_models),
 };
 
 static const struct bt_mesh_comp comp = {
	 .cid = BT_COMP_ID_LF,
	 .elem = elements,
	 .elem_count = ARRAY_SIZE(elements),
 };
 
 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) {
		printk("Bluetooth init failed (err %d)\n", err);
		return;
	}

	printk("Bluetooth initialized\n");

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

	if (IS_ENABLED(CONFIG_SETTINGS)) {
		settings_load();
	}

	/* This will be a no-op if settings_load() loaded provisioning info */
	bt_mesh_prov_enable(BT_MESH_PROV_ADV | BT_MESH_PROV_GATT);

	printk("Mesh initialized\n");
 }
 
 int main(void)
 {
	 int err = 0;
 
	 printk("Initializing...\n");

	 /* Initialize LEDs */
	err = leds_init();
	if (err) {
		printk("LEDs init failed (err: %d)\n", err);
		return 0;
	}
 
	 /* Initialize the Bluetooth Subsystem */
	 err = bt_enable(bt_ready);
	 if (err) {
		 printk("Bluetooth init failed (err %d)\n", err);
		 return 0;
	 }
 
	 return 0;
 }
 

[AHaug]

Hi,

Seems to me that you might be using a setup with acknowledge messages? I.e based on successful_ack_count in the publisher and   // Blink the LED to indicate ACK was sent
board_led_0_blink(); from the Subscriber? If so then it matches quite well with the section w.r.t "With Acknowledge messages".

Could you verify if this is the case or not? 

Kind regards,
Andreas

[Cam Martell]

Hi,

Yes I am using a setup with acknowledge messages. However, my understanding of the section w.r.t "With Acknowledge Messages" is that the timing diagram indicates round trip time. Is this incorrect? 

If you take a look at Figure 6: Mean Round Trip Time (RTT) latency (acknowledged messages)...

This figure shows timings of around 30 ms. for round trip latency for acknowledged messages.

Unless the testing done for the blog post was acknowledging messages at a lower layer than the application, I can not understand why the timing I am seeing is slightly more than double what the data on Figure 6 shows.

[AHaug]

Hi,

Cam Martell said:

Yes I am using a setup with acknowledge messages. However, my understanding of the section w.r.t "With Acknowledge Messages" is that the timing diagram indicates round trip time. Is this incorrect? 

You are correct, it shows mean RTT, although I don't quite agree that the conclusion it that it shows timings around 30 ms with acked messages since it's just the closest devices that are showcasing this amount of delay. But let's assume that you have configured everything identically within NCS 2.5.1 and have roughly the same ranges without any other wireless interference, then yes you should expect to see results around the same.

Does the inferences sections discussing the results match your observations? Does anything change if you tweak these parameters?

Kind regards,
Andreas

[Cam Martell]

Hi,

For my testing I am only using two devices. So, I don't think that many of the inference topics relating to relaying packets would make a difference in the RTT latency timing that I am seeing. However I did try playing with the retry numbers but I only see a noticeable difference in the reliability measurements and not so much for the RTT latency timing.

Are you able to provide insight into the sample project that was created for the testing done in this blog? I'd like to know if the acknowledged messages were handled at the application layer and if so, how that was accomplished.

Thank you for your help. My team is impressed with the numbers shown on the blog post but have yet to successfully reproduce with our small testing setup.

AHaug 

[AHaug]

Hi 

Cam Martell said:

For my testing I am only using two devices. So, I don't think that many of the inference topics relating to relaying packets would make a difference in the RTT latency timing that I am seeing.

I see I see! I wouldn't expect that to be the case either then since it's only two devices. 

The samples were made by modifying the default mesh sample provided by zephyr.

But another thing that I just noticed now is the Bluetooth controller used. You state that you're using samples from Zephyr. Do you also use the Zephyr Bluetooth controller? In the test we used the Nordic SoftDevice Controller (SDC). Could you re-validate your results using the SDC instead of the Zephyr controller? From the blog:

You can for instance use the light and light_switch samples from sdk/nrf/samples/bluetoooth/mesh

If you still see 60-70ms results after changing to the Nordic controller, please let us know, provide your projects configuration files, and we'll look closer into it!

Kind regards,
Andreas