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]

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