app_timer2 assert in on_compare_evt after upgrade from SDK 16 to SDK 17

[eriknorth]

Hi,

After upgrading from SDK 16 to SDK 17 my device started to assert on app_timer2.c line 298:

ASSERT(app_timer_cnt_diff_compute(drv_rtc_counter_get(p_instance),
                                          drv_rtc_compare_get(p_instance, 0)) < APP_TIMER_SAFE_WINDOW);

This happens way more often when running without debugger/RTT.

I checked my app timer handlers and i could not notice that any of them would take too long time to finish. Have not measured tho.
Assert happens both while advertising and in connected state.
As soon as I switch back to SDK 16, everything is fine again.

Has something changed in sdk_config.h? Do I need to update some values?

Some details:

• device nrf52840
• running device as a peripheral
• s140 softdevice

/Erik

[Kenneth]

If you replace this line with SDKv16 then it works?

ASSERT(app_timer_cnt_diff_compute(drv_rtc_counter_get(p_instance),
                                          mp_active_timer->end_val & RTC_COUNTER_COUNTER_Msk) < APP_TIMER_SAFE_WINDOW);

How many app_timers are running, are they single shot or interval?

[eriknorth]

Hi Kenneth,

After replacing the the line 298 in SDKv17 version from SDKv16, it stopped asserting/crashing.

I am using two interval timers and one single shot timer.

If this is of any help, my project involves two parts - peripheral and central (also s140). And this issue is present only on peripheral.
Central seems to work fine after the upgrade.

/Erik

[Krzysztof Chruscinski]

Hi Erik,

can you provide your APP_TIMER_SAFE_WINDOW_MS and APP_TIMER_CONFIG_RTC_FREQUENCY values? 

Also can you log or somehow capture what are the values or NRF_RTC1->COUNTER and NRF_RTC1->CC[0] when assert occurs?

Krzysztof

[eriknorth]

Hi Krzysztof,

Sorry, for the delayed answer.

APP_TIMER_SAFE_WINDOW_MS = 300000
APP_TIMER_CONFIG_RTC_FREQUENCY = 0

NRF_RTC1->COUNTER = 1028836
NRF_RTC1->CC[0] = 1028837

/Erik

[eriknorth]

Hi again,

I just tried SDK 17.0.2 and I am still experiencing the issue. When I replace it with the line suggested by Kenneth, it starts to work.

I tried to change the APP_TIMER_CONFIG_RTC_FREQUENCY to 1 but that did not fix the issue.
If understand this correct then in my case when it calculates the difference between counter and CC, it gets -1 and that value is unsigned so it goes to UNIT32_MAX that is than masked with 24bits so that it would get a value in the range of RTC counter.

Is this how it should be, that this is an illegal value and should assert?
Do you have guesses why does my program end up in this scenario?

Thank you,
/Erik

[Krzysztof Chruscinski]

Can you try to enable debug logging in app_timer by setting APP_TIMER_CONFIG_LOG_LEVEL to 4 and  NRF_LOG_DEFAULT_LEVEL to 4 and provide logs when issue occurs?

[eriknorth]

Hi Krzysztof,

I was not able to make my app to work with log level 4 as there were a lot of dropped logs or with deferred log off, it was spending too much time printing the messages.

However, I started to investigate by removing timers one by one and I noticed that at some point it started to work. So... I have one repeated timer that runs with 1ms period + I am using libuarte with 

#define NRF_LIBUARTE_ASYNC_WITH_APP_TIMER 1

If they both are active, the timer will assert.
If only one of them is active, it will be fine.

I measured the time it spends in the 1ms timer handler and it was under 1 app timer tick (the diff between start and end was zero). So it cannot be that I am spending too much time in the handler.

It seems that this issue with app_timer2 might be somehow connected to libuarte when app_timer is used for its timeout handling.

/Erik

[Krzysztof Chruscinski]

Hi Erik,

I have one suspicion, can you also provide mp_active_timer->end_val when assert occurs? Together with CC and COUNTER.

Krzysztof

[eriknorth]

Hi Krzysztof,

Here are the values:

<info> app_timer: COUNTER 8928348
<info> app_timer: CC 8928349
<info> app_timer: end_val 8928348

It happens less when I run with debugger, so I have to wait a bit to get the assert and the log.

/Erik

[Krzysztof Chruscinski]

These values means that this is a false positive. When CC value is set it cannot be set for COUNTER+1 because it may not generate event (hw limitation). Because of that driver detects that situation and increases CC value and sets again. However, in your case the event was generated for 8928348 but because it was close, driver set CC to 8928349 and during that setting event occurred.

Anyway, it means that assert is too strict and does not cover for this case. I will look into fixing this assert. The SDK16 version was not covering timeouts longer than 24 bits thus it was changed. For now you can get back to assert from v16 as long as you are not using timeouts > 24 bits.

[eriknorth]

Hi Krzysztof,

Thanks for the explanation. Ok, then I will keep the patched app_timer2.c for now.

In future, I might consider switching to timer instead of app_timer for the async llibuarte to take some load off the app timer.

/Erik