K_TIMER() - HARD_FAULT - Data Access Violation - nrf9160

[ReneDelgado]

Hi,

Currently we working on a project that uses:

• nRF9160
•  Zyphre OS
•  Segger Embedded Studio for  Arm (Nordic Edition) V5.10d
•  SDK v1.4

We need to handle multiple timeouts, to handle our processes, but we have a problem that we think occurs when our K_TIMERS expire. We are looking for restrictions on using multiple timers but we do not find any, the functions we are using are the following:

1. k_timer_init(timer, NULL, NULL);
2. k_timer_start(timer, K_MSEC(timeout), K_NO_WAIT);

And this is the error:

• Is this a known bug?
• Does anyone know of any restrictions that can cause this?
• What could we be doing wrong?

Thanks a lot.

[Håkon Alseth]

Hi,

 

In the assert message, you have two addresses that points out:

And:

 

What is located at these addresses? You can do a lookup using "arm-none-eabi-addr2line -e build-folder/zephyr/zephyr.elf 0xADDR". If you have re-compiled or done any changes to application, these addresses will move.

Note that all k_timer instances are running in interrupt context, so you should be very careful of what you're calling in those callbacks. It is recommended to push tasks to a workqueue or similar instead.

 

Kind regards,

Håkon

[ReneDelgado]

Hi Håkon, thanks for your prompt answer, this is the result from the address mentioned:

PS C:\...\build_nrf9160dk_nrf9160ns\zephyr> arm-none-eabi-addr2line -e zephyr.elf 0x217e7
C:/.../ncs/v1.4.0/zephyr/include/sys/dlist.h:325

PS C:\...\build_nrf9160dk_nrf9160ns\zephyr> arm-none-eabi-addr2line -e zephyr.elf 0x00021834
C:/.../ncs/v1.4.0/zephyr/include/spinlock.h:92

Regarding your note, I don't understand.

Our context:

We are calling k_timer_init(timer, NULL, NULL); & k_timer_start(timer, K_MSEC(timeout), K_NO_WAIT);  from a thread context without functions for callback, we set NULL in the k_timer_ini() function. We are not running nothing in any callback, We just verify if the timer has ended.

• Could you expand your note a little more?
• Which callbacks are you referring to?

Kind regards,

René D.

[Håkon Alseth]

Hi René,

 

From the logic that you posted, you're doing something similar to this sequence:

https://docs.zephyrproject.org/latest/reference/kernel/timing/timers.html#reading-timer-status 

Looking at the assert information, the second one is interesting:

https://github.com/nrfconnect/sdk-zephyr/blob/master/include/spinlock.h#L92

This means that you have a nested (recursive) locking sequence somewhere, as per the documentation:

https://docs.zephyrproject.org/apidoc/latest/spinlock_8h_aac60da4347f5b29ff8c4e5f24c99b3bf.html 

   

Is there anything specific in the thread you're calling this from that might call k_spin_lock()? Could you share a snippet or similar?

 

Kind regards,

Håkon

[ReneDelgado]

Hello Håkon,

Sorry for the delay, I have the most popular virus from this year.

Yes regarding to our sequence is like you mentioned, but regarding to spinlock.h#L92 we do not calling this function explicit neither we are using recursive functions. As note, we are using mutex as the documentation suggest.

Also note that if I enable the segger system view this cracks earlier.

CONFIG_SEGGER_SYSTEMVIEW=y

CONFIG_USE_SEGGER_RTT=y

CONFIG_TRACING=y

If you  want I  can send you an  email with a basic sample of the code.

Thanks,

René D.

[Håkon Alseth]

Hi René

 

 

ReneDelgado said:

Sorry for the delay, I have the most popular virus from this year.

 I'm sorry to hear. I hope you and your closest are OK.

 

ReneDelgado said:

Yes regarding to our sequence is like you mentioned, but regarding to spinlock.h#L92 we do not calling this function explicit neither we are using recursive functions. As note, we are using mutex as the documentation suggest.

Also note that if I enable the segger system view this cracks earlier.

Aha. this is an issue I've also spent some time digging into.

When you're using RTT and no logger thread (ie. no context switch for logging), you can run into this scenario when printing in interrupts:

https://github.com/zephyrproject-rtos/zephyr/issues/11393

 

Are you printing from the k_timer callback? if yes, can you check if the issue still occurs if you use LOG=y and LOG_IMMEDIATE=n?

 

Kind regards,

Håkon

[ReneDelgado]

Hello Håkon,

I removed all the printk() and all printf() functions, an now we are using our own debug functions.

And now, we are using LOG=y and LOG IMMEDIATE=n, with that changes, we do not have hard faults now.

But, now we are in and infinity loop in timeout.c. It seems that the timers never ends.

Have you any idea to how solve this behavior?

Thanks,

René D.

[Håkon Alseth]

Hi René,

 

Glad to hear that you handled the fault.

Could you share the code in countdown_ms() so I can have a look? 

 

Kind regards,

Håkon

[ReneDelgado]

Hi Håkon,

Sure, at this repository you can found the files that we are using, if is necessary give you access to more files just tell us.

As note, We noticed that the hard fault still occurs in some cases, it occurs less mainly while we debug step by step.

Also was added kconfig and prj.conf in case that it can help in something.

Kind regards,

René D.

[Håkon Alseth]

Hi,

 

ReneDelgado said:

We noticed that the hard fault still occurs in some cases, it occurs less mainly while we debug step by step.

Is the source of the fault the same? Or does it occur in another function?

 

Thank you for the sources and headers.

The only scenario I'm able to replicate a behavior that looks a bit like yours is if I call countdown_ms() in a loop, ie. repeatedly starting the same timer instance. How often is countdown_ms called on your side?

 

Kind regards,

Håkon