sd_ecb_block_encrypt() execution time

[Max Sikström]

We have a custom protocol with strict deadlines in the radio stack between receiving a packet, decrypting it, processing encrypting an ack and send the ack.

For that reason, we have strict deadlines on sd_ecb_block_encrypt(), and it seems to work for every case, except now one.

In this case, we are running:

- nrf52840

- Softdevice s140 v7.2.0

- nrf5-sdk 17.0.2

- FreeRTOS 10.0.0, the version shipped with nrf5-sdk

Our setup runs all radio code from the radio interrupt in an allocated radio slot, and thus on priority 0. Except the calls to softdevice, in which we trigger an SWI and drops to interrupt priority 5 for that call, and has the deadline specified on a TIMER0 compare. If we miss the deadline, then we log and retries later. Otherwise, we don't have any other interrupts during that period

I have measured that the call to sd_ecb_block_encrypt() and a block copy takes 15.8us in every case we have without running FreeRTOS, or when using that version of FreeRTOS while connected to a debugger, but in running state. But when disconnecting the debugger and reset the CPU, many of those calls starts 26.8us each, in a rate so we miss the deadline when sending bigger packets.

Also have a version where we upgraded FreeRTOS to a later version, and the issue seems to be gone.

We are not running any concurrent bluetooth, or having any other code using the encyrption.

To measure it, I'm using a saleae logic analyzer and pull a pin low just before the call, and high afterwards, to be able to measure timings without debugger/trace. I can't really find a pattern for it, but it seems to affect when running multiple in a row. Note: In the plot low signal means call to sd_ecb_block_encrypt()

I would have preferred to provide more steps to reproduce for this issue, but by the nature of not being able to track any pattern or being able to look at it with a debugger make it lot harder. But feeling uncomfortable without knowing the reason for this issue, since we don't know when it will appear or how to get around it. And thus lost in what to test

So what could make sd_ecb_block_encrypt() increase in execution time when not having debugger connected?

[Susheel Nuguru]

Max,

I am having a bit of a hard time trying to create a simplistic project to test solely this ecb encrypt function. Instead of me trying to spend so much time on trying to configure my project to get to your, can you please attach your project here. Sorry for making you wait while I attempted to make a simplistic project to test this. But I am not able to use sd_ecb_block_encrypt outside peer manager and I do not want to test the latencies of sd_ecb_block_encrypt under peer manager umbrella as there might be many other things happening under the hood.

[Max Sikström]

No worries. This is really a vague problem statement, and the fact I can't really reproduce it either in more than some scenarios that seems unrelated makes it a bit harder.

The issue is that it happens in one setup we have with out full system, but not others, means that the project we have to reproduce it with is our entire system, including our IP. So sending the entire project over is not really possible.

I can make an attempt to scale it down again, but that unfortunately has to wait until next week due to some other more urgent issues here.

[Susheel Nuguru]

Max Sikström said:

I can make an attempt to scale it down again, but that unfortunately has to wait until next week due to some other more urgent issues here.

I understand. Thanks for considering to attempt to make a simplistic project. It will make both of our debugging path a bit easier.

[Max Sikström]

Hi,

I have managed to simplify it a lot. I don't now the best way to send it so it persists in this ticket for other people to read in the future. But I have for now created a github repository containing the project.

Since it involves setup of softdevice, and a few other components, it is multiple files.

It can be found here:

https://github.com/pengi/freertos-nrf-encrypt-timings

And the trace without debugger connected can be seen as:

But as soon as I connect with gdb, I get this result, no settings is changed on the oscilloscope:

And it is for me really deterministic.

I am running on a PCA10056 v1.1.0

Ask if I should check any CPU variants or revisions that I missed. But I guess this is where that can be read out:

FICR.DEVICEADDRTYPE              = ffffffff
    DEVICEADDRTYPE                 .......1 - Random
FICR.DEVICEADDR[0]               = 5acc59e0
    DEVICEADDR                     5acc59e0 - 5acc59e0
FICR.DEVICEADDR[1]               = 78b66b84
    DEVICEADDR                     78b66b84 - 78b66b84
FICR.INFO_PART                   = 00052840
    PART                           00052840 - N52840
FICR.INFO_VARIANT                = 41414430
    VARIANT                        41414430 - AAD0
FICR.INFO_PACKAGE                = 00002004
    PACKAGE                        00002004 - QI
FICR.INFO_RAM                    = 00000100
    RAM                            00000100 - K256
FICR.INFO_FLASH                  = 00000400
    FLASH                          00000400 - K1024

[Emil Lenngren]

Are you running your interrupt code from RAM or from flash? Usually after an interrupt triggers, if code from flash starts to run, something like 10 us are needed for starting up the flash. When the debugger is connected, flash is always on so this time is eliminated.

[Max Sikström]

That's a good theory, I'm not entirely sure that's the case though. Since it's not the latency for the interrupt to start that is the issue, but execution time of the function sd_ecb_block_encrypt() itself. All GPIO pins are controlled from within the interrupt, and all 20 executions of sd_ecb_block_encrypt() behaves the same.

It would be if sd_ecb_block_encrypt() itself puts the CPU and flash to sleep during execution. But then, I would think all executions would be equally fast without debugger. But they are faster in our full system not running FreeRTOS.

But is it possible to force the flash to be always on from software during the execution of that interrupt? If so, that would be something easy to test.