Higher connection interval with lower throughput

[Ziyao Zhou]

Hi

I am using NCS 2.8 and running one pair of peripheral and central devices using nRF52832.

At first, the default interval is 50 ms, and I can get the throughput around 200 kbps, which is correct.

After updating the connection interval to 625 units, the througphut became lower, around 5kbps. I have even checked the maximum interval 3200 units, the throughput is quite low, with 2 packets sent in one interval inducing 0.98kbps. Seems that every interval only send two packets (my payload is 244 bytes).

[TP] t=28060 ms, bytes=488, tp=0.976 kbps

[TP] t=32060 ms, bytes=488, tp=0.976 kbps

[TP] t=36060 ms, bytes=488, tp=0.976 kbps

[TP] t=40059 ms, bytes=488, tp=0.976 kbps

[TP] t=44059 ms, bytes=488, tp=0.976 kbps

[TP] t=48059 ms, bytes=488, tp=0.976 kbps

[TP] t=52058 ms, bytes=488, tp=0.976 kbps

[TP] t=56058 ms, bytes=488, tp=0.976 kbps

My project config has considered the "high througput config" like this in both peripheral and central:

CONFIG_BT_BUF_ACL_RX_SIZE=502
CONFIG_BT_ATT_PREPARE_COUNT=2
CONFIG_BT_ATT_TX_COUNT=10
CONFIG_BT_L2CAP_TX_MTU=498
CONFIG_BT_L2CAP_DYNAMIC_CHANNEL=y
CONFIG_BT_CONN_TX_MAX=10
CONFIG_BT_BUF_ACL_TX_COUNT=10
CONFIG_BT_BUF_ACL_TX_SIZE=502
 
CONFIG_BT_CTLR_DATA_LENGTH_MAX=251
CONFIG_BT_CTLR_PHY_2M=y
CONFIG_BT_CTLR_SDC_MAX_CONN_EVENT_LEN_DEFAULT_OVERRIDE=y
CONFIG_BT_CTLR_SDC_MAX_CONN_EVENT_LEN_DEFAULT=4000000

But I still cannot get stable througput, why the packets number in the interval has been fixed? Could you give me some advice on that?

My code are:

5417.peripheral.zip

4331.central.zip

[Hung Bui]

Hi Zhou Ziyao, 

I think I know what could be wrong here. 
So you queue a packet every 9ms. 
The problem is that the BLE stack send all the packets buffered really quickly about 1.4ms each packet. 
So by the first 10ms for example already up to 7 packets can be sent. This can empty out all the buffered packets that you queue. 
When the buffer is empty the connection event will be completed. No more packet will be sent after that. 
You need to queue faster than sending or you need to have larger buffer. 
For example when you queue every 1 sec you can send 19 packets in a 50ms interval: 

To have larger buffer, you will need to increase CONFIG_BT_CTLR_SDC_RX_PACKET_COUNT and 

CONFIG_BT_CTLR_SDC_TX_PACKET_COUNT .
Try to set 

CONFIG_BT_CTLR_SDC_TX_PACKET_COUNT=10 on the peripheral 

and 

CONFIG_BT_CTLR_SDC_RX_PACKET_COUNT=10 on the central. 

You will see 9-10 packets queued for each connection event: 
Before (3): 

After (9):



Note that if you still keep the sending rate at 9ms each, you will still run out of buffer and result in what you see above, after 9 packets sent, it just stopped and wait for the next connection event. 

[Ziyao Zhou]

Hi

Thank you for your advice! 

By the way, may I ask if I don not use "queue a packet every 9ms", is there any way to control the throughput around 200kbps? The TX ans RX is close to each other so I can not reduce the TXP or increase distance. I have to test the pair at a certain throughput level.

I have tried that delete the ksleep to ask the peripheral sending continuously, however,  I still can only get low througput around 10 kbps. (I have added CONFIG_BT_CTLR_SDC_TX/RX_PACKET_COUNT)

Thank you!

[Hung Bui]

Hi,
Please capture a sniffer trace. 
You can see in my screenshot, the only modification I made was change the delay to 1ms and I can see 19 packets in a 50ms interval. So there must be something wrong. 

You can control how much you send by counting what you queue. 
What is your application and why you want to keep the throughput at 200kbps ? 

[Ziyao Zhou]

Hi,

My current code is

/*
 * Copyright (c) 2022 Nordic Semiconductor ASA
 *
 * SPDX-License-Identifier: LicenseRef-Nordic-5-Clause
 */

#include <zephyr/kernel.h>
#include <zephyr/device.h>
#include <zephyr/types.h>
#include <zephyr/drivers/gpio.h>
#include <zephyr/usb/usb_device.h>
#include <zephyr/bluetooth/bluetooth.h>
#include <zephyr/bluetooth/uuid.h>
#include <zephyr/bluetooth/gatt.h>
#include <zephyr/bluetooth/hci.h>

#include <zephyr/shell/shell.h>

#include <bluetooth/services/nus.h>

#include <dk_buttons_and_leds.h>
#include <zephyr/bluetooth/conn.h>


#include <nrfx_gpiote.h>
#if defined(DPPI_PRESENT)
#include <nrfx_dppi.h>
#else
#include <nrfx_ppi.h>
#endif

#include <zephyr/settings/settings.h>

#include <stdio.h>

#include <zephyr/logging/log.h>

#include "time_sync.h"

#define LOG_MODULE_NAME peripheral_uart
LOG_MODULE_REGISTER(LOG_MODULE_NAME);

#define STACKSIZE CONFIG_BT_NUS_THREAD_STACK_SIZE
#define PRIORITY 7

#define DEVICE_NAME CONFIG_BT_DEVICE_NAME
#define DEVICE_NAME_LEN	(sizeof(DEVICE_NAME) - 1)

#define UART_BUF_SIZE CONFIG_BT_NUS_UART_BUFFER_SIZE
#define UART_WAIT_FOR_BUF_DELAY K_MSEC(50)
#define UART_WAIT_FOR_RX CONFIG_BT_NUS_UART_RX_WAIT_TIME

static K_SEM_DEFINE(ble_init_ok, 0, 1);

static struct bt_conn *current_conn;
static struct bt_conn *auth_conn;

static bool m_gpio_trigger_enabled;
static bool m_send_sync_pkt;

static const struct bt_data ad[] = {
	BT_DATA_BYTES(BT_DATA_FLAGS, (BT_LE_AD_GENERAL | BT_LE_AD_NO_BREDR)),
	BT_DATA(BT_DATA_NAME_COMPLETE, DEVICE_NAME, DEVICE_NAME_LEN),
};

static const struct bt_data sd[] = {
	BT_DATA_BYTES(BT_DATA_UUID128_ALL, BT_UUID_NUS_VAL),
};

static const char cmd_str[] = "Things base and vile, holding no quantity,  Love can transpose to form and dignity.  Love looks not with the eyes,  but with the mind. Things base and vile, holding no quantity,  Love can transpose to form and dignity. Love looks not with thezz";

static const nrfx_gpiote_t gpiote_inst = NRFX_GPIOTE_INSTANCE(NRF_DT_GPIOTE_INST(DT_ALIAS(syncpin), gpios));
static const struct gpio_dt_spec syncpin = GPIO_DT_SPEC_GET(DT_ALIAS(syncpin), gpios);
static const struct gpio_dt_spec txpin = GPIO_DT_SPEC_GET(DT_ALIAS(txpin), gpios);

static nrfx_gpiote_pin_t syncpin_absval;

#if defined(DPPI_PRESENT)
static uint8_t dppi_channel_syncpin;
#endif

static void button_changed(uint32_t button_state, uint32_t has_changed);

static void connected(struct bt_conn *conn, uint8_t err)
{
	char addr[BT_ADDR_LE_STR_LEN];

	if (err) {
		LOG_ERR("Connection failed (err %u)", err);
		return;
	}

	bt_addr_le_to_str(bt_conn_get_dst(conn), addr, sizeof(addr));
	LOG_INF("Connected %s", addr);

	current_conn = bt_conn_ref(conn);

	 const struct bt_le_conn_param param = {
        .interval_min = 3200,   /* 6 * 1.25ms = 7.5ms */
        .interval_max = 3200,
        .latency      = 0,
        .timeout      = 3200   /* 42 * 10ms = 420ms */
    };

    int rc = bt_conn_le_param_update(conn, &param);
    if (rc) {
        LOG_WRN("bt_conn_le_param_update failed (err %d)", rc);
    } else {
        LOG_INF("Conn param update requested!");
    }
}

static void disconnected(struct bt_conn *conn, uint8_t reason)
{
	char addr[BT_ADDR_LE_STR_LEN];

	bt_addr_le_to_str(bt_conn_get_dst(conn), addr, sizeof(addr));

	LOG_INF("Disconnected: %s (reason %u)", addr, reason);

	if (auth_conn) {
		bt_conn_unref(auth_conn);
		auth_conn = NULL;
	}

	if (current_conn) {
		bt_conn_unref(current_conn);
		current_conn = NULL;
	}
}

static void conn_param_updated(struct bt_conn *conn,
                               uint16_t interval,
                               uint16_t latency,
                               uint16_t timeout)
{
    /* interval 单位 1.25ms，timeout 单位 10ms */
    printk("Conn params updated: interval=%u.%02u ms, latency=%u, timeout=%u ms\n",
           (interval * 125) / 100,           /* 整数部分 */
           (interval * 125) % 100,           /* 小数部分，保留两位 */
           latency,
           timeout * 10);
}

BT_CONN_CB_DEFINE(conn_callbacks) = {
	.connected    = connected,
	.disconnected = disconnected,
	.le_param_updated = conn_param_updated,

};

static void bt_receive_cb(struct bt_conn *conn, const uint8_t *const data,
			  uint16_t len)
{
	char addr[BT_ADDR_LE_STR_LEN] = {0};

	bt_addr_le_to_str(bt_conn_get_dst(conn), addr, ARRAY_SIZE(addr));

	LOG_INF("Received %d bytes from: %s", len, addr);
}

static struct bt_nus_cb nus_cb = {
	.received = bt_receive_cb,
};

void error(void)
{
	dk_set_leds_state(DK_ALL_LEDS_MSK, DK_NO_LEDS_MSK);

	while (true) {
		/* Spin for ever */
		k_sleep(K_MSEC(1000));
	}
}

static void configure_gpio(void)
{
	int err;

	err = dk_buttons_init(button_changed);
	if (err) {
		LOG_ERR("Cannot init buttons (err: %d)", err);
	}

	err = dk_leds_init();
	if (err) {
		LOG_ERR("Cannot init LEDs (err: %d)", err);
	}
}

static void ts_gpio_trigger_enable(void)
{
	uint64_t time_now_ticks;
	uint32_t time_now_msec;
	uint32_t time_target;
	int err;

	if (m_gpio_trigger_enabled) {
		return;
	}

	// Round up to nearest second to next 1000 ms to start toggling.
	// If the receiver has received a valid sync packet within this time, the GPIO toggling polarity will be the same.

	time_now_ticks = ts_timestamp_get_ticks_u64();
	time_now_msec = TIME_SYNC_TIMESTAMP_TO_USEC(time_now_ticks) / 1000;

	time_target = TIME_SYNC_MSEC_TO_TICK(time_now_msec) + (1000 * 2);
	time_target = (time_target / 1000) * 1000;

#if defined(DPPI_PRESENT)
	err = ts_set_trigger(time_target, dppi_channel_syncpin);
	__ASSERT_NO_MSG(err == 0);
#else
	err = ts_set_trigger(time_target, nrfx_gpiote_out_task_address_get(&gpiote_inst, syncpin_absval));
	__ASSERT_NO_MSG(err == 0);
#endif

	nrfx_gpiote_set_task_trigger(&gpiote_inst, syncpin_absval);

	m_gpio_trigger_enabled = true;
}

static void ts_gpio_trigger_disable(void)
{
	m_gpio_trigger_enabled = false;
}

static void ts_event_handler(const ts_evt_t* evt)
{
	switch (evt->type)
	{
		case TS_EVT_SYNCHRONIZED:
			ts_gpio_trigger_enable();
			LOG_INF("TS_EVT_SYNCHRONIZED");
			break;
		case TS_EVT_DESYNCHRONIZED:
			ts_gpio_trigger_disable();
			LOG_INF("TS_EVT_DESYNCHRONIZED");
			break;
		case TS_EVT_TRIGGERED:
			if (m_gpio_trigger_enabled)
			{
				uint32_t tick_target;
				int err;

				/* Small increments here are more sensitive to drift.
				 * That is, an update from the timing transmitter that causes a jump larger than the
				 * chosen increment, risk having a trigger target_tick that is in the past.
				 */
				tick_target = evt->params.triggered.tick_target + 2;

#if defined(DPPI_PRESENT)
				err = ts_set_trigger(tick_target, dppi_channel_syncpin);
				__ASSERT_NO_MSG(err == 0);
#else
				err = ts_set_trigger(tick_target, nrfx_gpiote_out_task_address_get(&gpiote_inst, syncpin_absval));
				__ASSERT_NO_MSG(err == 0);
#endif

			}
			else
			{
				// Ensure pin is low when triggering is stopped
				nrfx_gpiote_clr_task_trigger(&gpiote_inst, syncpin_absval);
			}
			break;
		default:
			__ASSERT_NO_MSG(false);
			break;
	}
}


static void button_changed(uint32_t button_state, uint32_t has_changed)
{
	uint32_t buttons = button_state & has_changed;
	int err;

	if (buttons & DK_BTN1_MSK) {
		if (m_send_sync_pkt) 		{
			m_send_sync_pkt = false;
			m_gpio_trigger_enabled = false;

			err = ts_tx_stop();
			__ASSERT_NO_MSG(err == 0);

			dk_set_led_off(DK_LED1);

			LOG_INF("Stopping sync beacon transmission!");
		}
		else {
			m_send_sync_pkt = true;

			err = ts_tx_start(TIME_SYNC_FREQ_AUTO);
			__ASSERT_NO_MSG(err == 0);

			dk_set_led_on(DK_LED1);

			ts_gpio_trigger_enable();

			LOG_INF("Starting sync beacon transmission!");
		}
	}
}

static void configure_sync_timer(void)
{
	int err;

	err = ts_init(ts_event_handler);
	__ASSERT_NO_MSG(err == 0);

	ts_rf_config_t rf_config = {
		.rf_chn = 80,
		.rf_addr = { 0xDE, 0xAD, 0xBE, 0xEF, 0x19 }
	};

	err = ts_enable(&rf_config);
	__ASSERT_NO_MSG(err == 0);
}

static nrfx_gpiote_pin_t pin_absval_get(const struct gpio_dt_spec *gpio_spec)
{
	if (gpio_spec->port == DEVICE_DT_GET(DT_NODELABEL(gpio0))) {
		return NRF_GPIO_PIN_MAP(0, gpio_spec->pin);
	}
#if DT_NODE_EXISTS(DT_NODELABEL(gpio1))
	if (gpio_spec->port == DEVICE_DT_GET(DT_NODELABEL(gpio1))) {
		return NRF_GPIO_PIN_MAP(1, gpio_spec->pin);
	}
#endif

	__ASSERT(false, "Port could not be determined");
	return 0;
}

static void configure_debug_gpio(void)
{
	nrfx_err_t nrfx_err;
	int err;


	nrfx_gpiote_output_config_t gpiote_cfg = {
		.drive = NRF_GPIO_PIN_S0S1,
		.input_connect = NRF_GPIO_PIN_INPUT_DISCONNECT,
		.pull = NRF_GPIO_PIN_NOPULL,
	};

	nrfx_gpiote_task_config_t task_cfg = {
		.polarity = NRF_GPIOTE_POLARITY_TOGGLE,
		.init_val = NRF_GPIOTE_INITIAL_VALUE_LOW,
	};

	syncpin_absval = pin_absval_get(&syncpin);

	err = gpio_pin_configure_dt(&syncpin, GPIO_OUTPUT_LOW | syncpin.dt_flags);
	__ASSERT_NO_MSG(err == 0);

	if (!nrfx_gpiote_init_check(&gpiote_inst)) {
		nrfx_err = nrfx_gpiote_init(&gpiote_inst, 5);
		__ASSERT_NO_MSG(nrfx_err == NRFX_SUCCESS);
	}

	nrfx_err = nrfx_gpiote_channel_alloc(&gpiote_inst, &task_cfg.task_ch);
	__ASSERT_NO_MSG(nrfx_err == NRFX_SUCCESS);

	nrfx_err = nrfx_gpiote_output_configure(&gpiote_inst, syncpin_absval, &gpiote_cfg, &task_cfg);
	__ASSERT_NO_MSG(nrfx_err == NRFX_SUCCESS);

	nrfx_gpiote_out_task_enable(&gpiote_inst, syncpin_absval);

#if defined(DPPI_PRESENT)
	nrfx_err = nrfx_dppi_channel_alloc(&dppi_channel_syncpin);
	__ASSERT_NO_MSG(nrfx_err == NRFX_SUCCESS);

	nrf_gpiote_subscribe_set(
		NRF_GPIOTE, nrfx_gpiote_out_task_get(syncpin_absval), dppi_channel_syncpin);

	nrf_dppi_channels_enable(NRF_DPPIC_NS, BIT(dppi_channel_syncpin));
#endif
}

static void configure_tx_gpio(void)
{
    int err;

    if (!device_is_ready(txpin.port)) {
        LOG_ERR("TX pin device not ready");
        return;
    }

    err = gpio_pin_configure_dt(&txpin, GPIO_OUTPUT_INACTIVE | txpin.dt_flags);
    if (err) {
        LOG_ERR("Failed to configure TX pin (err %d)", err);
        return;
    }

    LOG_INF("TX pin configured");
}


int main(void)
{
	int err = 0;

	configure_gpio();
	configure_debug_gpio();
    configure_tx_gpio();   // ★ 一定要加这个

	
	configure_sync_timer();

	err = bt_enable(NULL);
	if (err) {
		error();
	}

	LOG_INF("Bluetooth initialized");

	k_sem_give(&ble_init_ok);

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

	err = bt_nus_init(&nus_cb);
	if (err) {
		LOG_ERR("Failed to initialize UART service (err: %d)", err);
		return 0;
	}

	err = bt_le_adv_start(BT_LE_ADV_CONN, ad, ARRAY_SIZE(ad), sd,
				  ARRAY_SIZE(sd));
	if (err) {
		LOG_ERR("Advertising failed to start (err %d)", err);
		return 0;
	}


	while (1) {
    /* 每秒打印 TimeSync 当前时间 */
    // uint64_t t = ts_timestamp_get_ticks_u64();
    // uint32_t ms = TIME_SYNC_TIMESTAMP_TO_USEC(t) / 1000;
    // printk("Sync time: %u ms\n", ms);

    /* 每秒通过 NUS 向已连接 central 发送字符串 */
    if (current_conn) {
        int err = bt_nus_send(current_conn, cmd_str, strlen(cmd_str));
        if (err) {
            LOG_WRN("bt_nus_send failed (err %d)", err);
        } else {
            // LOG_INF("NUS sent\n");
			// gpio_pin_set_dt(&txpin, 1);
			// k_sleep(K_MSEC(100));
			// gpio_pin_set_dt(&txpin, 0);

        }
    }
 
	// k_sleep(K_MSEC(3000));	
}

}

#if CONFIG_SHELL

static int cmd_tx_toggle(const struct shell *sh, size_t argc, char **argv)
{
	int err;

	if (m_send_sync_pkt) {
		m_send_sync_pkt = false;
		m_gpio_trigger_enabled = false;

		err = ts_tx_stop();
		__ASSERT_NO_MSG(err == 0);

		dk_set_led_off(DK_LED1);

		shell_print(sh, "Stopping sync beacon transmission!");
	}
	else {
		m_send_sync_pkt = true;

		err = ts_tx_start(TIME_SYNC_FREQ_AUTO);
		__ASSERT_NO_MSG(err == 0);

		dk_set_led_on(DK_LED1);

		ts_gpio_trigger_enable();

		shell_print(sh, "Starting sync beacon transmission!");
	}

	return 0;
}

static int cmd_time_get(const struct shell *sh, size_t argc, char **argv)
{
	uint64_t timestamp_ticks;
	uint32_t timestamp_msec;

	timestamp_ticks = ts_timestamp_get_ticks_u64();
	timestamp_msec = TIME_SYNC_TIMESTAMP_TO_USEC(timestamp_ticks) / 1000;

	shell_print(sh, "%d msec", timestamp_msec);

	return 0;
}

SHELL_CMD_ARG_REGISTER(tx_toggle, NULL, "Time sync TX toggle",
			   cmd_tx_toggle, 0, 0);

SHELL_CMD_ARG_REGISTER(time_get, NULL, "Time sync time get",
			   cmd_time_get, 0, 0);
#endif /* CONFIG_SHELL*/

I make it send continuously an the trace file is here:

3200 continiously.pcapng

How could I control how much I send by counting what my queue? I want to do this because I want to check the synchronization effect at different connection interval. (with certain througput)

[Hung Bui]

Please test and do the debugging on your side we can't just look into your code without you do any debugging, sniffer trace etc.