Execution time of bt_nus_send

[Adm]

Hi,

This is the follow up on this question, I'm not sure how it was closed.

I'm getting different execution times (not transmission time, like mentioned in the answer here) for `bt_nus_send` function, although in the above mentioned post it is said that the function is not blocking. So, I'm wondering why sometimes the function takes a couple of milliseconds to execute if it is not blocking.

In most cases it is stable, and around ~100 microseconds, but I think when there is a problem with connection, I get a couple of milliseconds. If the function only queues data in the SoftDevice controller's FIFO for transmission in the next connection event, I expect similar execution times each time the function is called.

What could be the cause of the problem?

[Karl Ylvisaker]

Hello,

This is the follow up on this question, I'm not sure how it was closed.

It seems the ticket was closed because my comment was marked as a 'verified answer', which usually indicates that the issue in the original ticket has been resolved by the comment.

I'm getting different execution times (not transmission time, like mentioned in the answer here) for `bt_nus_send` function, although in the above mentioned post it is said that the function is not blocking. So, I'm wondering why sometimes the function takes a couple of milliseconds to execute if it is not blocking.

Could you elaborate on how you have measured the execution time? Which priority were this measurement being performed with?

In most cases it is stable, and around ~100 microseconds, but I think when there is a problem with connection, I get a couple of milliseconds. If the function only queues data in the SoftDevice controller's FIFO for transmission in the next connection event, I expect similar execution times each time the function is called.

Yes, I too do not expect connection state to matter to the execution time of the function call, which is why I think we will need to look into how the execution time is measured before we delve deeper into this.

Best regards,
Karl

[Adm]

For measuring of execution time, I am using TIMER — Timer/counter, and just calling nrfx_timer_capture before and after bt_nus_send call.

[Adm]

Hi Karl, do you maybe have some updates on this one?

[Karl Ylvisaker]

Hello again,

Thank you for your extreme patience with this.

Adm said:

For measuring of execution time, I am using TIMER — Timer/counter, and just calling nrfx_timer_capture before and after bt_nus_send call.

That sounds correct, as long as you are not being interrupted by a higher priority event while in the by_nus_send call.
To make absolutely sure that this is not the case you can call irq_lock / irq_unlock before making the call - as described in this ticket - for debugging sake.

Other than that I also looked into the bt_gatt_notify function which will be called behind the scenes, but I can see no blocking behavior there either.

Could you try the timer approach with the IRQ's disabled for the duration, to see if it changes the behavior?

Best regards,
Karl

[Adm]

I've tried that, but I'm getting similar results. Here's the part of the code irq_lock/irq_unlock:

meas_utils_begin();
unsigned int key = irq_lock();
int ret = bt_nus_send(ble_connection,(const uint8_t*)buff + offset, tx_size);
irq_unlock(key);
meas_utils_end();

And here are the results:

Without irq_lock/irq_unlock (values in microseconds)

[00:00:18.067,871] <inf> utils: Measurement 1: 962
[00:00:18.067,901] <inf> utils: Measurement 2: 951
[00:00:18.067,901] <inf> utils: Measurement 3: 1008
[00:00:18.067,901] <inf> utils: Measurement 4: 951
[00:00:18.067,901] <inf> utils: Measurement 5: 2990
[00:00:18.067,932] <inf> utils: Measurement 6: 938
[00:00:18.067,932] <inf> utils: Measurement 7: 495
[00:00:18.067,932] <inf> utils: Measurement 8: 905
[00:00:18.067,932] <inf> utils: Measurement 9: 909
[00:00:18.067,932] <inf> utils: Measurement 10: 948
[00:00:18.067,962] <inf> utils: Measurement 11: 2648
[00:00:18.067,962] <inf> utils: Measurement 12: 980
[00:00:18.067,962] <inf> utils: Measurement 13: 1007
[00:00:18.067,962] <inf> utils: Measurement 14: 953
[00:00:18.067,993] <inf> utils: Measurement 15: 1009
[00:00:18.067,993] <inf> utils: Measurement 16: 951
[00:00:18.067,993] <inf> utils: Measurement 17: 2431
[00:00:18.067,993] <inf> utils: Measurement 18: 901
[00:00:18.067,993] <inf> utils: Measurement 19: 947
[00:00:18.068,023] <inf> utils: Measurement 20: 944
[00:00:18.068,023] <inf> utils: MAX: 2990
[00:00:18.068,023] <inf> utils: MIN: 495
[00:00:18.068,023] <inf> utils: AVG: 1191

With irq_lock/irq_unlock (values in microseconds)

[00:00:20.152,954] <inf> utils: Measurement 1: 947
[00:00:20.152,954] <inf> utils: Measurement 2: 2964
[00:00:20.152,954] <inf> utils: Measurement 3: 980
[00:00:20.152,954] <inf> utils: Measurement 4: 1015
[00:00:20.152,954] <inf> utils: Measurement 5: 5138
[00:00:20.152,984] <inf> utils: Measurement 6: 937
[00:00:20.153,015] <inf> utils: Measurement 7: 946
[00:00:20.153,015] <inf> utils: Measurement 8: 943
[00:00:20.153,015] <inf> utils: Measurement 9: 966
[00:00:20.153,015] <inf> utils: Measurement 10: 979
[00:00:20.153,015] <inf> utils: Measurement 11: 3014
[00:00:20.153,045] <inf> utils: Measurement 12: 948
[00:00:20.153,045] <inf> utils: Measurement 13: 948
[00:00:20.153,045] <inf> utils: Measurement 14: 945
[00:00:20.153,045] <inf> utils: Measurement 15: 497
[00:00:20.153,076] <inf> utils: Measurement 16: 910
[00:00:20.153,076] <inf> utils: Measurement 17: 2635
[00:00:20.153,076] <inf> utils: Measurement 18: 981
[00:00:20.153,076] <inf> utils: Measurement 19: 980
[00:00:20.153,076] <inf> utils: Measurement 20: 975
[00:00:20.153,106] <inf> utils: MAX: 5138
[00:00:20.153,106] <inf> utils: MIN: 497
[00:00:20.153,106] <inf> utils: AVG: 1432