Slower OpenThread PSKc calculation

[markus-becker-tridonic-com]

After updating

• from 2cfb11e to 6667dc3

• from zephyrproject-rtos/openthread@3c6191e to zephyrproject-rtos/openthread@497590a

and using the sample samples/net/openthread/ncp/ on a K64 board the time to generate a PSKc on the NCP/K64 with wpanctl commissioner gen-psk increased from slightly below 5s to slightly above 5s. Unfortunately the timeout value of the OpenThread tools is 5s: https://github.com/openthread/wpantund/blob/master/src/wpantund/NCPConstants.h#L23.

What might have slowed down in the updates between the SHAs mentioned above?

[carlescufi]

@rlubos is this a regression in performance in OpenThread itself? If so this is perhaps better suited for the upstream project.

[carlescufi]

@markus-becker-tridonic-com the K64F doesn't have a 15.4 radio, so are you using a shield or an external radio IC of some sort?

[dleach02]

@markus-becker-tridonic-com, can you add the following to your project config file for a test:

CONFIG_XOROSHIRO_RANDOM_GENERATOR=y

[markus-becker-tridonic-com]

@markus-becker-tridonic-com the K64F doesn't have a 15.4 radio, so are you using a shield or an external radio IC of some sort?

RF2XX as external radio IC.

[markus-becker-tridonic-com]

@markus-becker-tridonic-com, can you add the following to your project config file for a test:

CONFIG_XOROSHIRO_RANDOM_GENERATOR=y

CONFIG_XOROSHIRO_RANDOM_GENERATOR=n results in 5087ms.
CONFIG_XOROSHIRO_RANDOM_GENERATOR=y results in 5212ms.
With about 1ms variance between different runs.

[rlubos]

@carlescufi @markus-becker-tridonic-com
I've compared the two OT revisions, but changes in there are mostly cosmetic:
https://github.com/zephyrproject-rtos/openthread/blob/46194ba9053d71966ddbf7c159c0ff68f93d6497/src/core/meshcop/commissioner.cpp#L1061
https://github.com/zephyrproject-rtos/openthread/blob/46194ba9053d71966ddbf7c159c0ff68f93d6497/src/core/crypto/pbkdf2_cmac.cpp#L44
There's also mbedTLS involved, and I guess we spend most of the time there during PSKc generation, but we use the same revision in both cases.

I don't know what else could've changed in regards to that board/radio. I'd verify the execution time of the GeneratePskc() function, to see if there's really a regression in PSKc generation time, or is it some other issue (like CPU being busy processing higher priority thread before switching to OT).

[carlescufi]

@markus-becker-tridonic-com have you logged an issue with upstream OpenThread? Maybe it's as simple as increasing the timeout value in wpantund?

[markus-becker-tridonic-com]

turned out to be CONFIG_MBEDTLS_DEBUG=y was the culprit and adding approximately 500ms.