NUS Central Write To Peripheral RX Characteristic Very Slow

[DB_ECD]

Hello!

I am currently running into throughput problems while using the Nordic Uart Service (NUS).

I am building a project for a peripheral and wanted to test the possible throughput by using the central_uart example. I modified this example slightly in order to add updates for BLE connection parameters as well as Data Length. I have callbacks for these connection parameters in both my peripheral project as well as in the central project and also added the needed CONFIG_XXX parameters to the respective prj.conf files. After connection, both devices show the following log, so I assume this has worked correctly:

<inf> BLE: MTU exchange successful
<inf> BLE: New MTU: 244 bytes
<inf> BLE: Data length updated. Length 251/251 bytes, time 2120/2120 us
<inf> BLE: Connection parameters updated. interval 320, latency 0, timeout 400

I chose these parameters after trying the BLE Throughput example. With this Throughput example, the config listed as above and 1M PHY, I have a data rate of 783 kbps, which is great.

However, if I try to send BLE messages of 244 bytes with my Central/Peripheral setup, I encounter the following problem:

Calling bt_nus_client_send() on the client side, which in turn calls bt_gatt_write() and  waits for the passed callback function, there is a large delay of ~800msecs between the call of the write function and the execution of the callback function. This slows down the data rate to an unusable 330 bytes/sec..

On the peripheral side I just have my bt_nus_cb receive callback, where I only copy the received data. This should not be a performance limiting factor in my mind.

I know that the Throughput example uses bt_gatt_write_withous_response() while the nus_client uses bt_gatt_write() which, if I'm correct, has an acknowledge in the link layer included. But I don't think that this would cause this huge delay...

So my question is: am I missing something here? Do you have any suggestions as to what I need to change in order to increase the data rate? The throughput example shows me that it should be possible, so I guess with the NUS service it should be possible as well..?

Any help is appreciated!

[Susheel Nuguru]

Haven't tried those configurations myself, but you can try SystemView and get a better idea on the context where that ~800ms delay (wait) is happening. After getting the context of that delay, we would have more info to calibrate on reducing that delay. SystemView is free to try on Nordic products, so please give it a try.

[DB_ECD]

Thank you for your reply. However, SystemView crashes immediately every time it is supposed to capture the data. I tried it for some time now, sorry to say that this seems like wasted time to me.

Still, it seems to me that the 800ms delay that I am encountering is way too high to be normal behaviour. Is there no general idea what could be the cause/solution of/for this?

[DB_ECD]

Hello again,

I changed some things around that I'd like to let you know:

• within the central_uart.c main() function, bt_nus_client_send() is called
• this function in turn (within nus_client.c) calls bt_gatt_write() (which than again should promt the callback that causes the above mentioned delay)
• I now changed the bt_gatt_write() to bt_gatt_write_without_response(), as this is used withing the Throughput example.

Now, within the main() of central_uart.c I call the bt_nus_client_send() in a loop like so:

int main(void)
{
    // ...
    // INITIALIZATIONS
    // ...

	for (int i = 0; i < 10; i++) 
	{
		uint8_t pucBuf[UART_BUF_SIZE] = 
		{
			// DUMMY DATA; e.g.:
			0x00, 0x01, 0x02, 0x03
		};

		LOG_DBG("Sending data block no %d", i + 1);

		err = bt_nus_client_send(&nus_client, pucBuf, sizeof(pucBuf));
		if (err) 
		{
			LOG_WRN("Failed to send data over BLE connection"
				"(err %d)", err);
		}
	}
}

with the changed bt_nus_client_send() in nus_client.c

int bt_nus_client_send(struct bt_nus_client *nus_c, const uint8_t *data,
		       uint16_t len)
{
	int err;

	if (!nus_c->conn) {
		return -ENOTCONN;
	}
    
    // COMMENT THIS OUT IN ORDER TO RUN THIS SEND FUNCTION MULTIPLE TIMES
	// LOG_INF("Trying to set atomic bit for NUS_C_RX_WRITE_PENDING");
	// if (atomic_test_and_set_bit(&nus_c->state, NUS_C_RX_WRITE_PENDING)) {
	// 	return -EALREADY;
	// }
	// LOG_INF("Atomic Bit set for NUS_C_RX_WRITE_PENDING, value: %d", atomic_test_bit(&nus_c->state, NUS_C_RX_WRITE_PENDING));

	nus_c->rx_write_params.func = on_sent;
	nus_c->rx_write_params.handle = nus_c->handles.rx;
	nus_c->rx_write_params.offset = 0;
	nus_c->rx_write_params.data = data;
	nus_c->rx_write_params.length = len;

    // INITIALLY THIS BLOCK IS CALLED
	// err = bt_gatt_write(nus_c->conn, &nus_c->rx_write_params);
	// if (err) {
	// 	atomic_clear_bit(&nus_c->state, NUS_C_RX_WRITE_PENDING);
	// }

    // --> CHANGED THIS TO TEST THROUGHPUT INCREASE
	err = bt_gatt_write_without_response(nus_c->conn, nus_c->handles.rx, data, len, false);


	return err;
}

Simple stuff basically, no delay or sleep or anything. However, in the LOG output I notice that the sending is happening in some kind of time chunks, as you can see here:

[00:00:11.731,994] <dbg> central_uart: main: Sending data block no 1
[00:00:11.732,635] <dbg> central_uart: main: Sending data block no 2
[00:00:11.733,276] <dbg> central_uart: main: Sending data block no 3
[00:00:11.733,947] <dbg> central_uart: main: Sending data block no 4
[00:00:11.984,008] <dbg> central_uart: main: Sending data block no 5
[00:00:11.985,565] <dbg> central_uart: main: Sending data block no 6
[00:00:11.987,213] <dbg> central_uart: main: Sending data block no 7
[00:00:11.987,854] <dbg> central_uart: main: Sending data block no 8
[00:00:12.384,002] <dbg> central_uart: main: Sending data block no 9
[00:00:12.385,559] <dbg> central_uart: main: Sending data block no 10

Between Blocks 4/5 and 8/9, there is again a delay of 250/400ms respectively.

Now I don't really understand why this is happening. Shouldn't bt_gatt_write_without_response() send out the data as fast as possible? What is the cause of the delay here?

[Hieu]

Hi DB_ECD,

DB_ECD said:

Thank you for your reply. However, SystemView crashes immediately every time it is supposed to capture the data. I tried it for some time now, sorry to say that this seems like wasted time to me.

Alright, but SystemView is quite valuable when trying to debug issues regarding threads and OS timing, so perhaps this need to be looked into someday.

But that qualifies for a dedicated case of its own. For this topic, we can try another approach.

I know that the Throughput example uses bt_gatt_write_withous_response() while the nus_client uses bt_gatt_write() which, if I'm correct, has an acknowledge in the link layer included. But I don't think that this would cause this huge delay...

Your log says the MTU size is 244, and the data you are trying to send is also 244.

3 bytes are necessary for the ATT Opcode and Handle, so you only have 241 bytes for each packet. Your 244 bytes then will be split into two packets.

Each of them when write with response will take one connection interval. This means that the worst case wait time is two connection intervals. Because your interval is 320ms, the worst case is 640ms. Does this sound right?

If not, we might want to take a sniffer log and examine the data.

DB_ECD said:

Simple stuff basically, no delay or sleep or anything. However, in the LOG output I notice that the sending is happening in some kind of time chunks, as you can see here:

...

Between Blocks 4/5 and 8/9, there is again a delay of 250/400ms respectively.

Now I don't really understand why this is happening. Shouldn't bt_gatt_write_without_response() send out the data as fast as possible? What is the cause of the delay here?

It could be that the connection event is being ended prematurely. We will need to look into the sniffer trace to see why though.

Can you get me a sniffer trace of all the cases that you want to analyze?

Hieu

[DB_ECD]

Hi Hieu,

Hieu said:

lright, but SystemView is quite valuable when trying to debug issues regarding threads and OS timing, so perhaps this need to be looked into someday.

It sounded good to me too and I was kind of bummed out it crashed every time. I'll look into that when I have a little bit more time.

Hieu said:

Your log says the MTU size is 244, and the data you are trying to send is also 244.

3 bytes are necessary for the ATT Opcode and Handle, so you only have 241 bytes for each packet. Your 244 bytes then will be split into two packets.

Each of them when write with response will take one connection interval. This means that the worst case wait time is two connection intervals. Because your interval is 320ms, the worst case is 640ms. Does this sound right?

Not quite right. I Set the MTU in the prj.conf file (both on central and peripheral) with CONFIG_BT_L2CAP_TX_MTU=247 while the Log you see in the original post is created using

uint16_t payload_mtu =
	bt_gatt_get_mtu(conn) - 3; // 3 bytes used for Attribute headers.
LOG_INF("New MTU: %d bytes", payload_mtu);

Therfore it should be possible to send 244 bytes in one packet, right? Also, the interval number in the Log is the value from conn.h:

/** Connection parameters for LE connections */
struct bt_le_conn_param {
	uint16_t interval_min;
	uint16_t interval_max;
	uint16_t latency;
	uint16_t timeout;
};

The actual time should be interval * 1.25ms = 320 * 1.25 = 400 ms. Is this correct? However, I just used these Connection Parameter values because they resultet in a good data rate in the Thoughput example. Is there a way to figure out optimum values based on packet length etc. (i.e. actual values from my project)?

Hieu said:

Can you get me a sniffer trace of all the cases that you want to analyze?

I'll do that tomorrow!