I'm trying to narrow down the cause of a Softdevice assertion happening in S132 7.2.0 at PC=0x15810.
We set up a proprietary RF project which utilises parts of the SDK for Mesh (specifically, the timeslot implementation and bearer_handler) because it provides a safe base to run high performance timeslot applications on. Unfortunately I do have one device which runs into a softdevice assertion at instruction 0x15810. I feel that it is a timing issue - maybe the device is operating at the outer limits of the clock accuracy, because while the issue appears sporadically on Development Kits or other devices, this specific device does trigger it quite often.
Any help is greatly appreciated.
EDIT: In the meantime I think I found the cause of the issue. Assuming that the timing assertions by the Softdevice are done using RTC0, there seems to be a rather large discrepancy between the RTC0 timing and TIMER0 timing. After 9'999'249us on TIMER0 pass, RTC0 has counted 10'000'732us, so they're almost 1ms apart!
The device in question is running the LFCLK from the RC oscillator and we do usually have BLE deactivated. I did assume that the softdevice takes care of adjusting for clock drift, but could it be that I have to somehow take care of this manually?
EDIT2: Note that - as we're using the nRF SDK for Mesh as a codebase - when calculating the available time on the timeslot, we should already account for clock drift per the following calculation:
(p_timeslot->length_us * (m_lfclk_ppm + HFCLOCK_PPM_WORST_CASE)) / 1000000;
EDIT3: I previously wrote that we "do usually have BLE deactivated". What I actually mean by this is that most of the time the device is neither connected nor is it currently advertising. So there is no BLE activity to schedule by the softdevice. Timeslots are always active, though.
The assert at 0x15810 is because the SoftDevice got an unexpected raio interrupt, which is typically because the application used the radio outside of the timeslot. Regarding LFCLK calibration that…
m.wagner said:Concerning drift: But the discrepancy appears between the HFCLK and LFCLK, no? TIMER0 runs off the HFCLK and is used to end the timeslot in time. The softdevice uses RTC0 which runs off…
The team has looked more into this but have not got to the bottom of it. They suggest that you can try to they increase TIMESLOT_END_SAFETY_MARGIN_US in steps of 100 us upto 1000 us.
There must be an explanation why the TIMER0 interrupt does not occur, but I cannot say what it is. You wrote that you have a high priority timer for frequency hopping (TIMER4?). Could this ISR be somehow running constantly, blocking processing the interrupt from TIMER0?
The TIMER4 interrupt is invoked periodically, (roughly every 3000us, timer started in RADIO IRQ handler), but all the handler does is clear the timer's compare event register, check for a radio address event and on the condition that no radio address event is set, trigger a radio interrupt via NVIC_SetPendingIRQ(RADIO_IRQn).
(I did insert some more code to debug this issue, namely storing timer and rtc captures in a variable)
I do assume the handler runs fast enough that its run-time should be well within the 100us margin that is accounted for in TIMER0. In the above example, 1019us passed between when TIMER0 IRQ should have been active and TIMER4 IRQ was active. At the time TIMER4 was served, TIMER0 was probably shut down.
I'll have to check with the logic analyzer to get more detailed outputs. As stated before, the issue seems to occur more often with some devices than others...
m.wagner said:As stated before, the issue seems to occur more often with some devices than others...
It is interesting that there is variation from device to device... This may be a stupid question, as you would not get the radio working without it, but could it be that you for some reason is not using the HFXO in the timeslot, but instead use the HFINT? That has a very large frequency tolerance (<±6 %). It is probably a long shot, but it could be worth double-checking.
No, it's definitely running on the HFXO.
In the meantime, I finally managed to look into it with a logic analyzer and could make an additional important finding: The issue occurs after the SoftDevice Event IRQ Handler has been invoked with NRF_EVT_RADIO_SESSION_IDLE.
This is a trace of the event. You see that around the time the TIMER0 interrupt should fire via the signal handler, instead the SoftDevice Event IRQ is invoked with NRF_EVT_RADIO_SESSION_IDLE.
Since this is unexpected and regular timeslot cleanup is omitted, my TIMER4 is still running on priority 0 and firing shortly after, triggering a RADIO IRQ via software.
The zoom in on the final part of the trace shows that the softdevice asserts immediately after said timer interrupt (confirming my previous assumptions):
To see what happens if the Interrupt causing the assertion is not running, I observe that... nothing happens. Nothing pertaining to timeslot activity is going on (see following trace):
Now I do not expect this event while a timeslot is ongoing - or better yet: the mesh team does not expect this event while a timeslot is ongoing. As I mentioned, the timeslot session is handled by a barely modified timeslot.c from nRF SDK for Mesh. The event handling:
/* As the SD events aren't handled atomically, we could potentially run into this scenario:
* - stop the timeslot -> SESSION_IDLE event pending, session_state is OPEN
* - start the timeslot again from the same context -> session_state is RUNNING
* - The SESSION_IDLE event is handled.
* Closing the radio session now leads to unexpected behavior, as the user restarted
* the timeslot already, expecting it to remain active.
if (m_current_timeslot.session_state == TS_SESSION_STATE_OPEN)
The variable m_current_timeslot.session_state is set to TS_SESSION_STATE_RUNNING at this point, though - so nothing happens.
A search of the DevZone also lead me to a user that seemingly had a similar issue with the actual nRF SDK for Mesh running:
SOFTDEVICE: ASSERTION FAILED while running mesh.
Unfortunately this was not followed up.
To me it looks like some sort of race condition occuring in the softdevice. I'm not entirely sure what to make of the NRF_EVT_RADIO_SESSION_IDLE event in any case.
In the meantime I was able to reproduce this issue with nRF SDK for Mesh 4.2.0 and a slightly modified beaconing example.
I attached a patch file which will apply the modifications I made.
Summary of my changes:
The debug pins used in this configuration are:
As you can see in the *.patch file attached, I ran the beaconing_nrf52832_xxAA_s132_7_0_1.emProject example in Segger Embedded Studio.
The device I tested with is a custommade/proprietary RF-Module with an nRF52832-QFAA, no LF crystal and a Murata XRCMD32M000FXP53R0 30ppm HF-XTAL.
Below you can see the corresponding trace I made with the logic analyser. As in the previous traces, around the point where the TIMER0->EVENTS_COMPARE should fire, the softdevice signal handler is invoked with event NRF_EVT_RADIO_SESSION_IDLE. The next time the radio interrupt is triggered or something alike (the mesh's scanner module is still running at this point), the example crashes with Softdevice assert: 88044.
Concerning the frequency of this occurence: On this particular device I tested with, it seems to usually occur within the first 10 minutes of run time or so. On nRF52 DK devices (also configured to use LF_SRC = RC!), it seems to happen less frequently. Maybe once every couple of hours or so... So far, I have not yet been able to properly trace this on an nRF52 DK yet.
It would be great, if you could investigate this issue in more detail, as the smooth functioning of this timeslot code is essential to our application.