High current when using BLE NUS

[rmakl]

Hi,

I am starting to finalize a development stage and was looking at the current consumption of my device. I noticed, that when something connects to it and is starting to use the NUS service, current consumption skyrockets to 7mA and stays there, even after disconnecting every BLE connection.
This happens either:

• I connect using Norduc UART Android App
• I connect using nRF connect, then click on the TX Characteristic notification enable
• I connect using a custom Android App that uses BLE NUS
• Right after I make connection with the device (non-NUS) and my m_conn_handle becomes valid and I try to send data with ble_nus_data_send();

Here is an extract of an RTT log:

 0> <info> pwr_mgmt: CPU Usage: 0%
 0> <info> pwr_mgmt: CPU Usage: 0%
 0> <info> pwr_mgmt: CPU Usage: 0%
 0> <info> pwr_mgmt: CPU Usage: 0%
 0> <info> pwr_mgmt: CPU Usage: 0%
 0> <info> pwr_mgmt: CPU Usage: 0%
 0> <info> pwr_mgmt: CPU Usage: 0%
 0> <info> pwr_mgmt: CPU Usage: 0%
 0> <info> pwr_mgmt: CPU Usage: 0%
 0> <info> pwr_mgmt: CPU Usage: 0%
 0> <info> pwr_mgmt: CPU Usage: 0%
 0> <info> pwr_mgmt: CPU Usage: 0%
 0> <info> pwr_mgmt: CPU Usage: 0%
 0> <info> pwr_mgmt: CPU Usage: 0%
 0> <info> pwr_mgmt: CPU Usage: 0%
 0> <info> pwr_mgmt: CPU Usage: 0%
 0> <info> pwr_mgmt: CPU Usage: 0%
 0> <info> pwr_mgmt: CPU Usage: 0%
 0> <info> pwr_mgmt: CPU Usage: 0%
 0> <debug> nrf_ble_gatt: Requesting to update ATT MTU to 158 bytes on connection 0x0.
 0> <debug> nrf_ble_gatt: ATT MTU updated to 158 bytes on connection 0x0 (response).
 0> <info> pwr_mgmt: CPU Usage: 0%
 0> <debug> nrf_ble_gatt: Peer on connection 0x0 requested a data length of 123 bytes.
 0> <debug> nrf_ble_gatt: Updating data length to 27 on connection 0x0.
 0> <debug> nrf_ble_gatt: Data length updated to 27 on connection 0x0.
 0> <debug> nrf_ble_gatt: max_rx_octets: 27
 0> <debug> nrf_ble_gatt: max_tx_octets: 27
 0> <debug> nrf_ble_gatt: max_rx_time: 1096
 0> <debug> nrf_ble_gatt: max_tx_time: 1096
 0> <info> app: BLE NUS connected
 0> <info> pwr_mgmt: CPU Usage: 4%
 0> <info> pwr_mgmt: CPU Usage: 38%
 0> <info> pwr_mgmt: CPU Usage: 39%
 0> <info> pwr_mgmt: CPU Usage: 38%
 0> <info> pwr_mgmt: CPU Usage: 38%
 0> <info> pwr_mgmt: CPU Usage: 38%
 0> <info> pwr_mgmt: CPU Usage: 38%
 0> <info> pwr_mgmt: CPU Usage: 38%
 0> <info> pwr_mgmt: CPU Usage: 38%
 0> <info> pwr_mgmt: CPU Usage: 38%
 0> <info> pwr_mgmt: CPU Usage: 38%
 0> <info> pwr_mgmt: CPU Usage: 38%

As you can see, CPU load is increased after NUS activity, but no other tasks are carried at that time.

What seems to be the problem?

I'm using:

• s140_nrf52_7.0.1_softdevice.hex
• nRF5_SDK_for_Thread_and_Zigbee_v4.1.0_32ce5f8

Best Regards,

Roland

[Einar Thorsrud]

Hi Rolan,

I do not immediately see how the NUS service implementation itself could cause this. The large increase in CPU usage is very interesting, though.  Have you been able to see which part of your code is being run during this time? Perhaps just testing without optimization and pausing execution from a debugger could give some interesting observations on where time is being spent? If that does not provide any clues, can you share your code so that I can take a look?

Einar

[rmakl]

Hi Einar,

I think I narrowed down the problem to this code section:

/**
 * @brief 
 * 
 * @param p_context 
 */
void sensor_list_timeout_evt_handler(void *p_context)
{
	ret_code_t err_code;
	uint16_t length = 0;
	char str[512];
	size_t ptr = 0;

	if (m_conn_handle == BLE_CONN_HANDLE_INVALID || m_nus_connected == false) {
		return;
	}

	str[0] = '#';
	ptr = 1;
	for (int i = 0; i < ARRAY_SIZE(m_sim_datapoints); i++) {
		if (i > 0) {
			str[ptr] = ';';
			ptr++;
		}

		ptr += sprintf(&str[ptr], "%s,%d,%2.2f",
			m_sim_datapoints[i].name,
			m_sim_datapoints[i].enabled == true ? 1 : 0,
			m_sim_datapoints[i].values[m_sim_datapoints[i].index]);
	}

	length = ptr;
	str[ptr] = '\0';
	//NRF_LOG_INFO("sensor list: %s", str);

	err_code = ble_nus_data_send(&m_nus, str, &length, m_conn_handle);
	if ((err_code != NRF_ERROR_INVALID_STATE) &&
		(err_code != NRF_ERROR_RESOURCES) &&
		(err_code != NRF_ERROR_NOT_FOUND))
	{
		//APP_ERROR_CHECK(err_code);
	}

	/*
	length = 5;
	err_code = ble_nus_data_send(&m_nus, "Hello", &length, m_conn_handle);
	if ((err_code != NRF_ERROR_INVALID_STATE) &&
		(err_code != NRF_ERROR_RESOURCES) &&
		(err_code != NRF_ERROR_NOT_FOUND))
	{
		//APP_ERROR_CHECK(err_code);
	}
	*/
}

This function is called periodically by an app_timer every 1000ms, from the start of the app. If I send only "Hello", it works fine and consumption is not increased. If I send the originally intended content, it sends successfully, but consumption skyrockets.

Is it something to do with:

 0> <debug> nrf_ble_gatt: Peer on connection 0x0 requested a data length of 123 bytes.
 0> <debug> nrf_ble_gatt: Updating data length to 27 on connection 0x0.
 0> <debug> nrf_ble_gatt: Data length updated to 27 on connection 0x0.
 0> <debug> nrf_ble_gatt: max_rx_octets: 27
 0> <debug> nrf_ble_gatt: max_tx_octets: 27
 0> <debug> nrf_ble_gatt: max_rx_time: 1096
 0> <debug> nrf_ble_gatt: max_tx_time: 1096

? Should these transfer sizes be increased to fit my needs?

[Einar Thorsrud]

Hi,

I see you commented out the error check after calling ble_nus_data_send(). Why is that? Did you get an error there? If so, which error code?

[rmakl]

Hi,

That one, I totally forgot about. I commented out a few weeks ago, because I tried to send data before NUS connection is made. That's why I added later the m_nus_connected flag to check.
Now, I de-commented and debugged the code, but no error is reported by APP_ERROR_CHECK. The elevated current persists.

[rmakl]

I edited made some modifications:

#define NRF_SDH_BLE_GAP_DATA_LENGTH 251

and

/**
 * @brief 
 * 
 * @param p_context 
 */
void sensor_list_timeout_evt_handler(void *p_context)
{
	ret_code_t err_code;
	uint16_t length = 0;
	char str[512];
	size_t ptr = 0;

	if (m_conn_handle == BLE_CONN_HANDLE_INVALID || m_nus_connected == false) {
		return;
	}

	str[0] = '#';
	ptr = 1;
	for (int i = 0; i < ARRAY_SIZE(m_sim_datapoints); i++) {
		if (i > 0) {
			str[ptr] = ';';
			ptr++;
		}

		ptr += sprintf(&str[ptr], "%s,%d,%2.2f",
			m_sim_datapoints[i].name,
			m_sim_datapoints[i].enabled == true ? 1 : 0,
			m_sim_datapoints[i].values[m_sim_datapoints[i].index]);
	}

	length = ptr;
	str[ptr] = '\0';
	NRF_LOG_INFO("strlen: %d", length);

	err_code = ble_nus_data_send(&m_nus, str, &length, m_conn_handle);
	if ((err_code != NRF_ERROR_INVALID_STATE) &&
		(err_code != NRF_ERROR_RESOURCES) &&
		(err_code != NRF_ERROR_NOT_FOUND))
	{
		APP_ERROR_CHECK(err_code);
	}

	/*
	length = 5;
	err_code = ble_nus_data_send(&m_nus, "Hello", &length, m_conn_handle);
	if ((err_code != NRF_ERROR_INVALID_STATE) &&
		(err_code != NRF_ERROR_RESOURCES) &&
		(err_code != NRF_ERROR_NOT_FOUND))
	{
		//APP_ERROR_CHECK(err_code);
	}
	*/
}

I print out the string length.

Here is the RTT log:

<info> pwr_mgmt: CPU Usage: 0%
<info> pwr_mgmt: CPU Usage: 0%
<info> pwr_mgmt: CPU Usage: 0%
<info> pwr_mgmt: CPU Usage: 0%
<debug> nrf_ble_gatt: Requesting to update ATT MTU to 158 bytes on connection 0x0.
<debug> nrf_ble_gatt: Updating data length to 251 on connection 0x0.
<error> nrf_ble_gatt: sd_ble_gap_data_length_update() (request) on connection 0x0 returned NRF_ERROR_RESOURCES.
<error> nrf_ble_gatt: The requested TX/RX packet length is too long by 89/89 octets.
<debug> nrf_ble_gatt: ATT MTU updated to 158 bytes on connection 0x0 (response).
<info> pwr_mgmt: CPU Usage: 0%
<debug> nrf_ble_gatt: Peer on connection 0x0 requested a data length of 123 bytes.
<debug> nrf_ble_gatt: Updating data length to 123 on connection 0x0.
<debug> nrf_ble_gatt: Data length updated to 123 on connection 0x0.
<debug> nrf_ble_gatt: max_rx_octets: 123
<debug> nrf_ble_gatt: max_tx_octets: 123
<debug> nrf_ble_gatt: max_rx_time: 1096
<debug> nrf_ble_gatt: max_tx_time: 1096
<info> app: BLE NUS connected
<info> pwr_mgmt: CPU Usage: 0%
<info> app: strlen: 63
<info> pwr_mgmt: CPU Usage: 43%
<info> app: strlen: 63
<info> pwr_mgmt: CPU Usage: 58%
<info> app: strlen: 63
<info> pwr_mgmt: CPU Usage: 58%
<info> app: strlen: 63
<info> pwr_mgmt: CPU Usage: 57%
<info> app: strlen: 63
<info> pwr_mgmt: CPU Usage: 57%
<info> app: strlen: 63
<info> pwr_mgmt: CPU Usage: 57%
<info> app: strlen: 63
<info> pwr_mgmt: CPU Usage: 57%
<info> app: strlen: 63

So the stack negotiated a length of 123 and I want to send 63. Still, the problem persists.

[Einar Thorsrud]

I do not have an explanation for what you are seeing. A shot in the dark could be a potential buffer overflow or stack overflow that could cause the loop in the code snippet to keep iterating for a long time. But you should see other side effects then as well.

Are you able to reproduce this on a DK? If so, can you share the code with me so that I can test on my side?