throughput output

[Martijn Jonkers]

Hi,

I have the following ouput using the throughput example:

[local] sent 660264 bytes (644 KB) in 4540 ms at 1190912 bps (145 kBps)
[peer] received 660264 bytes (644 KB) in 2706 GATT writes at 1135105 bps (138 kBps)

Altered output format a bit to give me the same for local and peer.

But I was wondering why there is a significant difference between transfer by local and reception by peer. Shouldn't this be about the same and not 7 kBps difference? What is transferred is received on the other end, so the same throughput, right?

[Håkon Alseth]

Hi,

 

You're right, the timing anchor is stored before receiving the first "payload" packet:

https://github.com/nrfconnect/sdk-nrf/blob/v1.8.0/subsys/bluetooth/services/throughput.c#L61-L67

 

The connection interval is a factor as well. I tested quickly by updating "clock_cycles" on the first entry of the "else", and lowered the connection interval; it showed a more equal result, but still differed a bit (1327 kBit/s vs. 1313 kBit/s at my end). Longer interval shows higher difference.

 

Kind regards,

Håkon

[Martijn Jonkers]

I played a bit with this and I do not really get what is going on. I also set the 'clock_cycles' on the fist entry of else:

	if (len == 1) {
		/* reset metrics */
		kb = 0;
		met_data->write_count = 0;
		met_data->write_len = 0;
		met_data->write_rate = 0;
		clock_cycles = 0;
	} else {
		if(met_data->write_count == 0) {
			clock_cycles = k_cycle_get_32();
		}
		met_data->write_count++;
		met_data->write_len += len;
		met_data->write_rate =
		    ((uint64_t)met_data->write_len << 3) * 1000000000 / delta;
	}

and set the connection interval to 3200 units and I do not understand this result. Why would the reception rate be higher than the transmission rate?

[local] sent 660264 bytes (644 KB) in 7254 ms at 745472 bps (91 kBps)
[peer] received 660264 bytes (644 KB) in 2706 GATT writes at 1401786 bps (171 kBps)

When I set the connection interval to 6 units. Now I get this as a result, which is more as expected. but still not the same.

[local] sent 660264 bytes (644 KB) in 5170 ms at 1045504 bps (127 kBps)
[peer] received 660264 bytes (644 KB) in 2706 GATT writes at 1018568 bps (124 kBps)

[Håkon Alseth]

Hi,

 

Martijn Jonkers said:

another question: I notice the overall throughput goes down when I set a connection interval of 6 units. Is there a connection overhead for the connection interval? It looks like as if more data is transferred, even between data packets.

With DLE, you want a larger connection interval, as this feature basically streams data within the same connection interval. You can see this from the table in the link you sent as well, that throughput is better with larger connection interval.

Martijn Jonkers said:

I noticed it too, as you say, 'delta' is incorrect the first time with my implementation. But delta is only used for calculating 'met_data->write_rate' and that value is overwritten each time data comes in. So the final write_rate should be as expected. right?

If we're talking about "peer" print, this depends on the timing between receiving the "len == 1" scenario vs. when the data comes in.

Martijn Jonkers said:

Because the clock_cycles is set on first reception with my implementation, this skips the 500ms delay on the master and 4 sec connection interval. So, the data rate is measured from first packet to last, without any connection interval delays. correct?

I did notice in the original implementation the timing is started on the peer when the metrics are reset. But the central adds a 500ms delay after resetting the metrics to let any ble procedures complete. This 500ms is also added to the time it takes to receive data. But on the master this 500ms is skipped, beecause the start time is determined after the delay. This would always result in a lower reception rate compared to tranmission rate, right? reception time is always 500ms longer than transfer time.

For the "[local]" print, that is correct. On the peer side, it will by default, add that time between the events, due to the timing anchor.

If you revert your changes, are you able to get the correct timing on the [local] side?

 

Kind regards,

Håkon

[Martijn Jonkers]

Håkon Alseth said:

With DLE, you want a larger connection interval, as this feature basically streams data within the same connection interval. You can see this from the table in the link you sent as well, that throughput is better with larger connection interval.

Okay, learned something new here. I thought the connection interval is only relevant in between actual data transmissions to maintain the connection when northing is communicated.

Håkon Alseth said:

For the "[local]" print, that is correct. On the peer side, it will by default, add that time between the events, due to the timing anchor.

If you revert your changes, are you able to get the correct timing on the [local] side?

I have '[local]' on the peer and master. I assume the '[local]' on the peer is the same as the '[peer]' output on the master?

I reverted my changes. From what I understand, I will not get a correct timing on the peer. This is due to the 500ms delay introduced in the master. The peer has no knowledge of this delay after metrics reset. Is this a correct observation?

[Håkon Alseth]

Hi,

 

Martijn Jonkers said:

I have '[local]' on the peer and master. I assume the '[local]' on the peer is the same as the '[peer]' output on the master?

Yes, you are correct.

Martijn Jonkers said:

I reverted my changes. From what I understand, I will not get a correct timing on the peer. This is due to the 500ms delay introduced in the master. The peer has no knowledge of this delay after metrics reset. Is this a correct observation?

Yes. There's also the timing towards your connection interval, meaning; where you start pushing data in your application, compared to when the actual connection interval starts.

 

Kind regards,

Håkon

[Martijn Jonkers]

void transfer_complete(struct bt_conn *conn, void *user_data)
{
	k_sem_give(&throughput_sem);
}

int test_run(const struct shell *shell,
	     const struct bt_le_conn_param *conn_param,
	     const struct bt_conn_le_phy_param *phy,
	     const struct bt_conn_le_data_len_param *data_len)
{
	int err;
	uint64_t stamp;
	int64_t delta;
	uint32_t data = 0;
	uint32_t prog = 0;
	uint32_t delay_ms;

	/* a dummy data buffer */
	static char dummy[256];

	if (!default_conn) {
		shell_error(shell, "Device is disconnected %s",
			    "Connect to the peer device before running test");
		return -EFAULT;
	}

	if (!test_ready) {
		shell_error(shell, "Device is not ready."
			"Please wait for the service discovery and MTU exchange end");
		return 0;
	}

	shell_fprintf(SHELL, SHELL_VT100_COLOR_WHITE, "\n==== Starting throughput test ====\n");

	err = connection_configuration_set(shell, conn_param, phy, data_len);
	if (err) {
		return err;
	}

	/* send dummy data to wait for connection event */
	err = bt_gatt_write_without_response_cb(throughput.conn,
			throughput.char_handle, dummy, 1, false, transfer_complete, NULL);
	if (err) {
		shell_error(shell, "transfer failed");
		return err;
	} else {
		k_sem_take(&throughput_sem, THROUGHPUT_CONFIG_TIMEOUT);
	}

	/* we get here just after connection event */

	/* determine time until next connection event */
	delay_ms = (uint32_t)(conn_param->interval_max * 1.25);

	/* Wait for bext connection event. subtract 2 to continue just before the event */
	k_sleep(K_MSEC(delay_ms-2));

	/* reset peer metrics */
	err = bt_throughput_write(&throughput, dummy, 1);
	if (err) {
		shell_error(shell, "Reset peer metrics failed.");
		return err;
	}

	/* get cycle stamp */
	stamp = k_uptime_ticks();

	/* transfer a bunch of bytes */
	while (prog < IMG_SIZE) {
		err = bt_throughput_write(&throughput, dummy, 244);
		if (err) {
			shell_error(shell, "GATT write failed (err %d)", err);
			break;
		}

		/* print progress graphics */
		printk("%c", img[(prog % IMG_SIZE) / IMG_X][(prog % IMG_SIZE) % IMG_X]);
		data += 244;
		prog++;
	}

	// send 1 packet extra and wait for this to complete transfer
	// do not send 1 byte, because that will reset metrics on peer.
	err = bt_gatt_write_without_response_cb(throughput.conn,
			throughput.char_handle, dummy, 244, false, transfer_complete, NULL);
	if (err) {
		shell_error(shell, "transfer failed");
		return err;
	} else {
		k_sem_take(&throughput_sem, THROUGHPUT_CONFIG_TIMEOUT);
	}
	data += 244;

	// determine time it took to transfer IMG_SIZE * 244 bytes
	delta = k_uptime_ticks() - stamp;
	delta = k_ticks_to_ms_near32(delta);

	shell_fprintf(SHELL, SHELL_VT100_COLOR_WHITE, "Done\n");
	shell_fprintf(SHELL, SHELL_VT100_COLOR_YELLOW, "[local] sent %u bytes (%u KB) in %lld ms at %llu bps (%llu kbps)\n",
	       data, data / 1024, delta, ((uint64_t)data * 8 / delta) * 1024, ((uint64_t)data * 8 / delta));

	/* read back char from peer */
	err = bt_throughput_read(&throughput);
	if (err) {
		shell_error(shell, "GATT read failed (err %d)", err);
		return err;
	}
	
	/* Make sure that all BLE procedures are finished. */
	k_sleep(K_MSEC(500));
	k_sem_take(&throughput_sem, THROUGHPUT_CONFIG_TIMEOUT);

	// print average throughput
	uint64_t average_throughput = ((((uint64_t)data * 8 / delta) * 1024) + peer_metrics.write_rate) / 2;
	shell_fprintf(SHELL, SHELL_VT100_COLOR_YELLOW, "[throughput] average %llu bps (%llu kbps)\n", average_throughput , average_throughput/1024);

	instruction_print();

	return 0;
}

Thank you for confirming. I edited the example so it will give me a more representative output. What I did was the following:

- send a packet and wait for it to be actually transferred

- wait until the next connection event

- reset timing metrics on slave and master

- transfer a lot of data

- wait for last packet to be actually transferred

- stop timing

- print results

This gives me the following results: alll tests are with 251 data length. and the average is the average between slave and master.

phy 2M, 40 unit conn interval (50 ms), expected 1327 kbps

[local] sent 660508 bytes (645 KB) in 3981 ms at 1358848 bps (1327 kbps)
[peer] received 660508 bytes (645 KB) in 2707 GATT writes at 1327976 bps (1296 kbps)
[throughput] average 1343412 bps (1311 kbps)

phy 1M, 40 unit conn interval (50 ms), expected 702 kbps

[local] sent 660508 bytes (645 KB) in 7124 ms at 758784 bps (741 kbps)
[peer] received 660508 bytes (645 KB) in 2707 GATT writes at 741947 bps (724 kbps)
[throughput] average 750365 bps (732 kbps)

phy 2M, 320 units conn interval (400 ms), expected 1376 kbps

[local] sent 660508 bytes (645 KB) in 3788 ms at 1427456 bps (1394 kbps)
[peer] received 660508 bytes (645 KB) in 2707 GATT writes at 1395546 bps (1362 kbps)
[throughput] average 1411501 bps (1378 kbps)

phy 1M, 320 units conn interval (400 ms), expected 771 kbps

[local] sent 660508 bytes (645 KB) in 6727 ms at 803840 bps (785 kbps)
[peer] received 660508 bytes (645 KB) in 2707 GATT writes at 785690 bps (767 kbps)
[throughput] average 794765 bps (776 kbps)

These results almost match with what I expect and are very consistent. Can you maybe verify my method is correct?

I am using the original throughput service implementation from the nrf connect sdk.

[Håkon Alseth]

Hi,

 

You are definitely on the right track here. Adding a callback function to signalize the last packet on-air will provide a more accurate timing anchor.

As you are waiting for the callback on the 1 byte starting payload, you can technically take away the k_sleep delay, and it seems that you're sending this command twice?

 

Kind regards,

Håkon 

[Martijn Jonkers]

Håkon Alseth said:

As you are waiting for the callback on the 1 byte starting payload, you can technically take away the k_sleep delay, and it seems that you're sending this command twice?

That was my first implementation, but it did not work. The next payload is send during the next connection event when I do not add the connection interval delay -2 ms. So, when the callback fired, the connection event already passed. That is why I added a connection interval of time delay, minus 2 ms. This will continue the execution right before the next connection event. Even when I set it to 1 ms instead of 2 ms, the next connection is event is missed very often.

did I mis something? because I expected it would work like you described.

[Håkon Alseth]

Hi,

 

I ran it successful without the delay in the beginning on ncs v1.8.0 atleast, with similar results as you have.

Here's my .diff (git apply file.diff):

diff --git a/samples/bluetooth/throughput/src/main.c b/samples/bluetooth/throughput/src/main.c
index 92a1d1bee..688871481 100644
--- a/samples/bluetooth/throughput/src/main.c
+++ b/samples/bluetooth/throughput/src/main.c
@@ -503,6 +503,11 @@ static int connection_configuration_set(const struct shell *shell,
 	return 0;
 }
 
+void transfer_complete(struct bt_conn *conn, void *user_data)
+{
+	k_sem_give(&throughput_sem);
+}
+
 int test_run(const struct shell *shell,
 	     const struct bt_le_conn_param *conn_param,
 	     const struct bt_conn_le_phy_param *phy,
@@ -513,6 +518,7 @@ int test_run(const struct shell *shell,
 	int64_t delta;
 	uint32_t data = 0;
 	uint32_t prog = 0;
+	uint32_t delay_ms;
 
 	/* a dummy data buffer */
 	static char dummy[256];
@@ -529,26 +535,27 @@ int test_run(const struct shell *shell,
 		return 0;
 	}
 
-	shell_print(shell, "\n==== Starting throughput test ====");
+	shell_print(shell,"\n==== Starting throughput test ====\n");
 
 	err = connection_configuration_set(shell, conn_param, phy, data_len);
 	if (err) {
 		return err;
 	}
 
-	/* reset peer metrics */
-	err = bt_throughput_write(&throughput, dummy, 1);
+	/* send dummy data to wait for connection event */
+	err = bt_gatt_write_without_response_cb(throughput.conn,
+			throughput.char_handle, dummy, 1, false, transfer_complete, NULL);
 	if (err) {
-		shell_error(shell, "Reset peer metrics failed.");
+		shell_error(shell, "transfer failed");
 		return err;
+	} else {
+		k_sem_take(&throughput_sem, THROUGHPUT_CONFIG_TIMEOUT);
 	}
 
-	/* Make sure that all BLE procedures are finished. */
-	k_sleep(K_MSEC(500));
-
 	/* get cycle stamp */
-	stamp = k_uptime_get_32();
+	stamp = k_uptime_ticks();
 
+	/* transfer a bunch of bytes */
 	while (prog < IMG_SIZE) {
 		err = bt_throughput_write(&throughput, dummy, 244);
 		if (err) {
@@ -556,17 +563,31 @@ int test_run(const struct shell *shell,
 			break;
 		}
 
-		/* print graphics */
-		printk("%c", img[prog / IMG_X][prog % IMG_X]);
+		/* print progress graphics */
+		printk("%c", img[(prog % IMG_SIZE) / IMG_X][(prog % IMG_SIZE) % IMG_X]);
 		data += 244;
 		prog++;
 	}
 
-	delta = k_uptime_delta(&stamp);
+	// send 1 packet extra and wait for this to complete transfer
+	// do not send 1 byte, because that will reset metrics on peer.
+	err = bt_gatt_write_without_response_cb(throughput.conn,
+			throughput.char_handle, dummy, 244, false, transfer_complete, NULL);
+	if (err) {
+		shell_error(shell, "transfer failed");
+		return err;
+	} else {
+		k_sem_take(&throughput_sem, THROUGHPUT_CONFIG_TIMEOUT);
+	}
+	data += 244;
+
+	// determine time it took to transfer IMG_SIZE * 244 bytes
+	delta = k_uptime_ticks() - stamp;
+	delta = k_ticks_to_ms_near32(delta);
 
-	printk("\nDone\n");
-	printk("[local] sent %u bytes (%u KB) in %lld ms at %llu kbps\n",
-	       data, data / 1024, delta, ((uint64_t)data * 8 / delta));
+	shell_print(shell,"Done\n");
+	shell_print(shell,"[local] sent %u bytes (%u KB) in %lld ms at %llu bps (%llu kbps)\n",
+	       data, data / 1024, delta, ((uint64_t)data * 8 / delta) * 1024, ((uint64_t)data * 8 / delta));
 
 	/* read back char from peer */
 	err = bt_throughput_read(&throughput);
@@ -574,9 +595,15 @@ int test_run(const struct shell *shell,
 		shell_error(shell, "GATT read failed (err %d)", err);
 		return err;
 	}
-
+	
+	/* Make sure that all BLE procedures are finished. */
+	//k_sleep(K_MSEC(500));
 	k_sem_take(&throughput_sem, THROUGHPUT_CONFIG_TIMEOUT);
 
+	// print average throughput
+	//uint64_t average_throughput = ((((uint64_t)data * 8 / delta) * 1024) + peer_metrics.write_rate) / 2;
+	//shell_printf("[throughput] average %llu bps (%llu kbps)\n", average_throughput , average_throughput/1024);
+
 	instruction_print();
 
 	return 0;

 

Kind regards,

Håkon

[Martijn Jonkers]

I tried again, as you said. but he does not transfer data right after the 'transfer_complete' callback. It waits for the next connection event. Could the selected target have anything to do with this? I am using a nrf52 DK for now. It is supposed to work on a nrf52833 later on.

I changed it to save the timing start on the first transfer callback (the metrics reset command). And do not wait for transfer to complete, just send the data right after. That also works for me. No delay needed and consistent timing.

[Håkon Alseth]

Hi,

 

I ran it on ncs v1.8.0, nrf52840, and didn't have to have the 500 ms delay in the beginning, but that might have been pure luck on my side? Anyway, it does not matter as long as you reset the metric after the delay.

  

Kind regards,

Håkon

[Martijn Jonkers]

thank you for the help. We got it working the way we want.