Softdevice Assert at PC=0x15810 (S132 7.2.0) / RTC clock drift when using timeslot

[m.wagner]

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.

• What exact assertion fails when at PC=0x15810?
• Does the Softdevice shut down TIMER0 before doing this test or after an assertion fails?
• Are timing assertions made by the softdevice based on RTC0?
• Is there a reason why TIMER0 in the mesh stack is running in 24-bit mode as opposed to 32-bit mode?

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.

[Einar Thorsrud]

Hi,

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 is handled automatically by the SoftDevice. And in any case RTC drift should not be relevant here, as there is just a single low frequency clock source in the nRF, so even if there was a significant drift, the app and SoftDevice would be drifting "together".

Looking at your timeslot length calculation, it seems like you add the worst case drift value to the duration. Is that intentional? Should it not be subtracted?

[m.wagner]

Hi Einar,

Besides the issue with the discrepancies between RTC0 time and TIMER4 time, I noticed that TIMER0 is shut down while control has not yet returned to the softdevice.

Just to detail the setup: The issue seems to always occur at the same point in software. While a timeslot is granted, I have a timer running at highest IRQ priority, triggering a radio interrupt via software (NVIC_SetPendingIRQ(RADIO_IRQn)). This is used for frequency hopping and implemented like this for easier handling of the radio control state machine in our proprietary receiver.

The softdevice seems to assert after this interrupt has fired. So the cause of the assert that you have given would make sense. BUT at the point the assertion occurs, the timeslot has not ended!  It was still ongoing. I added a few checks into the above IRQ handler and noticed that at the point where the assert would occur, the timeslot *should* have already ended, but for some reason TIMER0 which should be in charge of ending and cleaning up the timeslot was shutdown. I.e. the CC and INTENSET registers are cleared and when I try to manually capture the current timer value using the debuger (setting TASKS_CAPTURE[n] to 1), nothing happens. I do have no code or PPI whatsoever that would shut down TIMER0 in my software and it is only used for controlling timeslot duration - and sometimes capturing its value. So it has to be shut down by the softdevice at some point.

Could you imagine when and why TIMER0 could get shutdown by the softdevice?

Also, asking again; does the assert 0x15810 also fail if the timeslot during which the Radio IRQ is invoked went on for too long?

Thanks for your help.

[m.wagner]

Hi Einar,

Thanks for your response. I just re-calculated the drifting again and realised that the discrepancy I mentioned above should be well within the margins for drift that I (or the nRF Mesh SDH team...) have accounted for.

So, for example in my current measurement, 327'716 ticks elapsed on RTC0 while 9'999'746 us were measured with TIMER0.

t_diff = rtc_ticks * 1000000 / 32768 - timer0_us 
       = 327716 * 1000000 / 32768 - 9999746 
       = 1352

With the requested timeslot duration of 10'000'000us, and the formula to calculate the end time, we get a maximum drift of...

t_drift = end_margin + overhead + ((t_length * (lfclk_ppm + hfclk_ppm)) / 1000000)
        = 100 + 20 + ((10000000 * (500 + 40)) / 1000000)
        = 5520

So the above 1352us are well within the 5520us.

What seems to be the issue is that for some reason the TIMER0 IRQ that should clean up and end the timeslot is never invoked.

Software event tracing showed that before the crash occurs, the radio signal handler is only ever invoked when triggered with the method described above. For clarification, I drew up what seems to happen. (sorry for the scribbled text, hope it's readable)

So at the point the SD asserts, in the example I'm looking at now, 1019us elapsed between when the TIMER0 IRQ handler should have been invoked and the measurement I made in the TIMER4 IRQ handler.

What is weird is that the TIMER0 IRQ handler is never invoked and at the point the softdevice asserts, the drift of RTC0 and TIMER0 seems to be well within the maximum allowed range.

[Einar Thorsrud]

Hi,

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?

[m.wagner]

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...

[Einar Thorsrud]

Hi,

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.

[m.wagner]

Hi Einar,

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:

case NRF_EVT_RADIO_SESSION_IDLE:
    /* 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)
    {
        ASSERT_NRF_ERROR_CODE(sd_radio_session_close(), TS_CORE_ERR_SESSION_CLOSE);
    }
    break;

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.