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,

 

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.