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)

[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.