nRF5340 power consumption on bt_le_adv_stop()

[TBing]

Hi Nordic Semi

I have implemented a basic BLE peripheral on a nRF5340 using the nRF Connect SDK 1.7.0.0.

The product we are developing have strict power consumption requirements.

I thus want to limit the BLE advertising period and upon expiration only allow bonded devices to connect.

The advertise expiration, I have implemented by means of a timer (K_TIMER_DEFINE(..)).

Upon expiration of this timer I call bt_le_adv_stop().

During advertisement I see a power use in the range of 4 mA.

When I call bt_le_adv_stop() the power use increate to 7 mA.

I can limit this to 5.5. mA, by calling pm_power_state_force((struct pm_state_info){PM_STATE_SUSPEND_TO_IDLE,0,0}); But the power use remains higher that while advertising.

Can you assist me in normalizing the power use after calling bt_le_adv_stop() ?

Regards Tonny

[helsing]

Hi Tonny,

Try disabling serial communication by adding CONFIG_SERIAL=n to prj.conf. Do you still get the same current?

What is the current consumption before you start advertising?

Would you be able to share a code snippet? We will try to reproduce this.

Regards,

Håkon

[TBing]

Hi Håkon

CONFIG_SERIAL was already set to n.

I have isolated the BLE related code in the code below.

The example advertises for 15 sec. and then calls bt_le_adv_stop();

When debugging this code I can see what happens: calling bt_le_adv_stop() cause the MCU to restart.

Try setting a breakpoint in main and in onAdvertiseTimeout.

When I debug the sample, the breakpoint in main is hit after bt_le_adv_stop() is called.

Regards Tonny

#include <zephyr/types.h>
#include <stddef.h>
#include <string.h>
#include <errno.h>
#include <sys/printk.h>
#include <sys/byteorder.h>
#include <zephyr.h>
#include <drivers/gpio.h>
#include <soc.h>

#include <bluetooth/bluetooth.h>
#include <bluetooth/hci.h>
#include <bluetooth/conn.h>
#include <bluetooth/uuid.h>
#include <bluetooth/gatt.h>
#include <bluetooth/gatt_dm.h>
#include <settings/settings.h>
#include <pm/pm.h>

//### PREDECLARATIONS
ssize_t onBleWrite(struct bt_conn *conn, const struct bt_gatt_attr *attr,
					 const void *buf, uint16_t len, uint16_t offset,
					 uint8_t flags);

static void onCccCfgchanged(const struct bt_gatt_attr *attr, uint16_t value);

static void onAdvertiseTimeout(struct k_timer *timer);

//### GLOBALS AND MACROS
#define DEVICE_NAME             CONFIG_BT_DEVICE_NAME
#define DEVICE_NAME_LEN         (sizeof(DEVICE_NAME) - 1)

static bool pipeClientRegistered = false;

static struct bt_uuid_128 serviceUuid = BT_UUID_INIT_128(
	BT_UUID_128_ENCODE(0x12345678, 0x1234, 0x6789, 0xACA8, 0x123456789ABC));

static const struct bt_uuid_128 pipeCharacteristicUuid = BT_UUID_INIT_128(
	BT_UUID_128_ENCODE(0x12345678, 0x1234, 0x6789, 0xACA8, 0x123456789ABC));

static struct bt_gatt_attr serviceAttributes[] = {
    BT_GATT_PRIMARY_SERVICE(&serviceUuid),
    BT_GATT_CHARACTERISTIC(&pipeCharacteristicUuid.uuid,
        BT_GATT_CHRC_NOTIFY | BT_GATT_CHRC_WRITE_WITHOUT_RESP,
        BT_GATT_PERM_READ | BT_GATT_PERM_WRITE, NULL, onBleWrite, NULL),
    BT_GATT_CCC(onCccCfgchanged, BT_GATT_PERM_READ | BT_GATT_PERM_WRITE),
};

static struct bt_gatt_service bleService = BT_GATT_SERVICE(serviceAttributes);

// Manufacturer specific data
static uint8_t msd[] = {
	0xA0, 0x02,
	0xB0 /* Some data ... */
};

// Advertise packet
static const struct bt_data advertiseData[] = {
	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),
	BT_DATA(BT_DATA_MANUFACTURER_DATA, msd, sizeof(msd))
};

//### UTILS

static const char *phy2str(uint8_t phy)
{
	switch (phy) {
	case 0: return "No packets";
	case BT_GAP_LE_PHY_1M: return "LE 1M";
	case BT_GAP_LE_PHY_2M: return "LE 2M";
	case BT_GAP_LE_PHY_CODED: return "LE Coded";
	default: return "Unknown";
	}
}

K_TIMER_DEFINE(advertiseTimer, onAdvertiseTimeout, NULL);

//### CONNECTION STATUS CALLBACKS
static void onConnected(struct bt_conn *conn, uint8_t err)
{
	if (err) {
		printk("Connection failed (err 0x%02x)\n", err);
		return;
	}
}

static void onDisconnected(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));
	printk("Disconnected from %s (reason 0x%02x)\n", addr, reason);
}

static void onSecurityChanged(struct bt_conn *conn, bt_security_t level,
			     enum bt_security_err err)
{
	char addr[BT_ADDR_LE_STR_LEN];

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

	if (!err) {
		printk("Security changed: %s level %u\n", addr, level);
	} else {
		printk("Security failed: %s level %u err %d\n", addr, level,
			err);
	}
}

//### CONNECTION PARAMERTER NEGOTIATION CALLBACKS

static bool onBleParameterRequest(struct bt_conn *conn, struct bt_le_conn_param *param)
{
	printk("Connection parameters update request received.\n");
	printk("Minimum interval: %d, Maximum interval: %d\n",
	       param->interval_min, param->interval_max);
	printk("Latency: %d, Timeout: %d\n", param->latency, param->timeout);

	return true;
}

static void onBleParamtereupdated(struct bt_conn *conn, uint16_t interval,
			     uint16_t latency, uint16_t timeout)
{
	printk("Connection parameters updated.\n"
	       " interval: %d, latency: %d, timeout: %d\n",
	       interval, latency, timeout);
}

static void onBlePhyUpdated(struct bt_conn *conn,
			   struct bt_conn_le_phy_info *param)
{
	printk("LE PHY updated: TX PHY %s, RX PHY %s\n",
	       phy2str(param->tx_phy), phy2str(param->rx_phy));
}

static void onBleDataLengthUpdated(struct bt_conn *conn,
				   struct bt_conn_le_data_len_info *info)
{
	printk("LE data len updated: TX (len: %d time: %d)"
	       " RX (len: %d time: %d)\n", info->tx_max_len,
	       info->tx_max_time, info->rx_max_len, info->rx_max_time);
}

static struct bt_conn_cb connectionCallbacks = {
	.connected = onConnected,
	.disconnected = onDisconnected,
	.security_changed = onSecurityChanged,
	.le_param_req = onBleParameterRequest,
	.le_param_updated = onBleParamtereupdated,
	.le_phy_updated = onBlePhyUpdated,
	.le_data_len_updated = onBleDataLengthUpdated};

//### CONNECTION AUTHORISATION CALLBACKS

static void onAuthorizationCancel(struct bt_conn *conn)
{
	char addr[BT_ADDR_LE_STR_LEN];

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

	printk("Pairing cancelled: %s\n", addr);
}

static void onPairingConfirm(struct bt_conn *conn)
{
	char addr[BT_ADDR_LE_STR_LEN];

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

	bt_conn_auth_pairing_confirm(conn);

	printk("Pairing confirmed: %s\n", addr);
}

static void onPairingComplete(struct bt_conn *conn, bool bonded)
{
	char addr[BT_ADDR_LE_STR_LEN];

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

	printk("Pairing completed: %s, bonded: %d\n", addr, bonded);
}

static void onPairingFailed(struct bt_conn *conn, enum bt_security_err reason)
{
	char addr[BT_ADDR_LE_STR_LEN];

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

	printk("Pairing failed conn: %s, reason %d\n", addr, reason);
}

static struct bt_conn_auth_cb connectionAuthorizationCallbacks = {
	.cancel = onAuthorizationCancel,
	.pairing_confirm = onPairingConfirm,
	.pairing_complete = onPairingComplete,
	.pairing_failed = onPairingFailed
};


static void onCccCfgchanged(const struct bt_gatt_attr *attr, uint16_t value)
{
    pipeClientRegistered = (value == BT_GATT_CCC_NOTIFY) ? true : false;

	printk("Notification status changed: %d\n", pipeClientRegistered);
}

ssize_t onBleWrite(struct bt_conn *conn, const struct bt_gatt_attr *attr,
					 const void *buf, uint16_t len, uint16_t offset,
					 uint8_t flags)
{
	printk("Received: %d bytes\n", len);

	// Loopback data
	bt_gatt_notify(conn, &serviceAttributes[1], buf, len);

	return len;
}

static void onAdvertiseTimeout(struct k_timer *timer)
{
	bt_le_adv_stop();

	// Stopping advertising leads to increased power consumption for some reason.
	// Forcing the MCU into power save helps on the problem but does not completely solve it.
	// See issue: https://github.com/zephyrproject-rtos/zephyr/issues/3192
	// pm_power_state_force((struct pm_state_info){PM_STATE_SUSPEND_TO_IDLE,0,0});
}

//### MAIN

void main(void)
{
	int err;

	printk("Starting GATT Discovery Manager example\n");

	err = bt_enable(NULL);
	if (err) {
		printk("BLE init failed with error code %d\n", err);
		return;
	}

	// Load application settings where bonding information is stored.
	// Regarding info log statement "bt_hci_core: No ID address. App must call settings_load,
	// see link: https://lists.zephyrproject.org/g/devel/topic/is_bluetooth_sample/28575293.
	if (IS_ENABLED(CONFIG_SETTINGS)) {
		printk("Loading settings\n");
		settings_load();
	}

	err = bt_gatt_service_register(&bleService);
	if (err) {
		printk("BLE service registration failed %d\n", err);
		return;
	}

	bt_conn_cb_register(&connectionCallbacks);
	if (err) {
		printk("Failed to register connection callbacks.\n");
		return;
	}

	err = bt_conn_auth_cb_register(&connectionAuthorizationCallbacks);
	if (err) {
		printk("Failed to register authorization callbacks.\n");
		return;
	}

	k_timer_start(&advertiseTimer, K_SECONDS(15), K_HOURS(15));

	err = bt_le_adv_start(BT_LE_ADV_CONN, advertiseData, ARRAY_SIZE(advertiseData),
			      NULL, 0);
	if (err) {
		printk("Advertising failed to start (err %d)\n", err);
		return;
	}

	printk("Advertising successfully started\n");
}

[TBing]

Hi Håkon

I found the answer.

bt_le_adv_stop() cannot be called from a k_timer handler that executes in timer irq context.

The Zephyr documentation states: Use a timer to initiate an asynchronous operation ..

A bit fluffy, but it gave a hint.

The solution was (as also specified in the documentation) to dispatch the timeout to a Worker Queue, and

have a handler call bt_le_adv_stop() from its worker context.

static void onAdvertiseTimeoutIrq(struct k_timer *timer)
{
	k_work_submit(&advertiseTimeoutWork);
}

static void onAdvertiseTimeoutWork(struct k_work *work)
{
	bt_le_adv_stop();
}

[helsing]

Hi Tonny, great to hear you figured it out.