NRF Zephyr Timing SoC implementation - possible bug

[davege]

Hello,

I'm playing with the timing subsystem in order to measure some execution time with higher granularity than the RTC tick on nRF52840 (using PCA10056 DK).

I'm specifically using the Nordic SoC implementation (NOT the architecture default for all Cortex-M using DWT):

...
CONFIG_TIMING_FUNCTIONS=y
CONFIG_CORTEX_M_DWT=n
...

This means that the backend is using this file https://github.com/zephyrproject-rtos/zephyr/blob/main/soc/arm/nordic_nrf/timing.c

The TIMER instance is initialised with 16MHZ frequency and 32-bit resolution.

When getting the cycle count over a period, the developer needs to use this function:

uint64_t soc_timing_cycles_get(volatile timing_t *const start,
			       volatile timing_t *const end)
{
#if defined(CONFIG_SOC_SERIES_NRF51X)
#define COUNTER_SPAN BIT(16)
	if (*end >= *start) {
		return (*end - *start);
	} else {
		return COUNTER_SPAN + *end - *start;
	}
#else
	return (*end - *start);
#endif
}

Now, I believe that there are cases where the natural 64-bit unsigned modulo arithmetic is not working properly here, since start and end are 32-bit values (just casted), and as such an explicit handling of the overflow (e.g. start == (UINT32_MAX - t1) and end == t2) is needed.

I discovered this by using a routines measuring an average of execution over time, as the problem is occurring only in the specific overflow cases.

This is my quick and dirty solution:

....
uint32_t delta = ((uint32_t)*end) - ((uint32_t)*start);
return delta;

Can you please confirm me if this does make sense to you or the problem is somewhere else?

In case I can just open a PR on Zephyr itself, as this is part of that codebase...

Thanks!

D

[Simon]

since start and end are 32-bit values (just casted),

 I do not understand this.

The start and end values are pointers of type timing_t, which is a typedef of uint64_t:

https://github.com/nrfconnect/sdk-zephyr/blob/0944459b5b622048a08ad1f8cf8a044c135fd0d3/include/timing/types.h#L10 

I discovered this by using a routines measuring an average of execution over time, as the problem is occurring only in the specific overflow cases.

Since you do see unwanted behaviour, could you make a Zephyr (upstream) issue and explain your issue there? 

Then it will be looked at by Zephyr developers

[davege]

Hi,

Simon said:

since start and end are 32-bit values (just casted),

 I do not understand this.

The start and end values are pointers of type timing_t, which is a typedef of uint64_t:

https://github.com/nrfconnect/sdk-zephyr/blob/0944459b5b622048a08ad1f8cf8a044c135fd0d3/include/timing/types.h#L10 

With this I mean that start and end are detected using the soc_timing_counter_get function:

timing_t soc_timing_counter_get(void)
{
	NRF_TIMER2->TASKS_CAPTURE[0] = 1;
	return NRF_TIMER2->CC[0] * ((SystemCoreClock) / CYCLES_PER_SEC);
}

By nature, these are just 32-bit values (as the TIMER has resolution 32bits) multiplied by 4 and then returned into a uint64_t container.

If you try to detect average execution delta over time, you of course expect to end up in the situation I described, where:

• start = large number, but coming first in time
• end  = small number, but coming last in time

What I think is happening is that overflow is not on UINT64_MAX boundary, but on a smaller value, as the max value you can have using soc_timing_counter_get is:

UINT32_MAX * 4 (which is << UINT64_MAX)

So I believe normal modulo arithmetic cannot apply here, and special handling of the overflow would be needed rather than just subtracting:

*end - *start

Hope this clarifies it, let me know if this is not clear still.

I'd like to get an opinion here before opening a PR and waste someone time...

Thanks!

D

[Simon]

Hello Davege,

I'm going on vacation for a long time now, so I won't be able to look into this unfortunately.

Would you be able to open a Zephyr issue? It will be seen by the people working on this driver (including many Nordic engineers), and you can get feedback whether your proposed solution is a valid one before opening a PR.

Best regards,

Simon

[davege]

Hello Simon,

hope you had good holidays.

Unfortunately, no one on Zephyr side picked up the issue I created, would you be able to have a look since it's Nordic specific code?

I'd be curious to know your comments.
Thanks!

Best,

D

[Simon]

I just got back from holiday, and I will look into this the next days.

Best regards,

Simon

[Simon]

Could you share a link to the Zephyr issue you created?

[davege]

Hi Simon,

of course: https://github.com/zephyrproject-rtos/zephyr/issues/37390

D