DTM sample's dtm_wait() exposes a race condition in nrfx_timer_enable()

[variant]

We incorporated the basic functionality of the NCS 2.0's DTM sample app inside an larger application with other threads running.

In our case, for what maps to the dtm_wait(), we experienced a race condition in nrfx_timer_enable() leading to an assert in that routine. Here is the relevant code in the DTM sample and the nrfx timer routines:

void dtm_wait(void)
{
    int err;
    nrfx_timer_enable(&dtm_inst.wait_timer);
    err = k_sem_take(&dtm_inst.wait_sem, K_FOREVER);
  etc.
}

static void wait_timer_handler(nrf_timer_event_t event_type, void *context)
{
    nrfx_timer_disable(&dtm_inst.wait_timer);
    nrfx_timer_clear(&dtm_inst.wait_timer);
    k_sem_give(&dtm_inst.wait_sem);
}

void nrfx_timer_enable(nrfx_timer_t const * p_instance)
{
    NRFX_ASSERT(m_cb[p_instance->instance_id].state == NRFX_DRV_STATE_INITIALIZED);
    nrf_timer_task_trigger(p_instance->p_reg, NRF_TIMER_TASK_START);
    m_cb[p_instance->instance_id].state = NRFX_DRV_STATE_POWERED_ON;
    NRFX_LOG_INFO("Enabled instance: %d.", p_instance->instance_id);
}

void nrfx_timer_disable(nrfx_timer_t const * p_instance)
{
    NRFX_ASSERT(m_cb[p_instance->instance_id].state != NRFX_DRV_STATE_UNINITIALIZED);
    nrf_timer_task_trigger(p_instance->p_reg, NRF_TIMER_TASK_SHUTDOWN);
    m_cb[p_instance->instance_id].state = NRFX_DRV_STATE_INITIALIZED;
    NRFX_LOG_INFO("Disabled instance: %d.", p_instance->instance_id);
}

You can see the potential race condition by supposing the following sequence occurs in the DTM sample app code.

1. dtm_wait() / nrfx_timer_enable() has just completed the call to nrf_timer_task_trigger() (lines 4 and 19), and then the thread of that execution gets preempted.
2. While the thread of dtm_wait() is preempted, the nrfx_timer expires and calls wait_timer_handler().
3. The wait_time_handler() disables the timer by calling nrfx_timer_disable() (line 11), which sets the timer state to NRFX_DRV_STATE_INITIALIZED (line 28).
4. The thread of dtm_wait() resumes at setting the timer state to NRFX_DRV_STATE_POWERED_ON (line 20).
5. The dtm_wait() takes the semaphore (line 5), which was already given since the timer handler already expired (line 13).
6. At the next call to dtm_wait()/nrfx_timer_enable(), we fail the assert (line 18) because the state is wrong since step 3 and step 4 are not the expected order.

We fixed the race condition by putting an irq_lock() in dtm_wait() around the call to nrfx_time_enable().

It seems that the race condition could be fixed alternatively by swapping the timer trigger and the state change in your routine, as follows (lines 4 and 5 swapped):

void nrfx_timer_enable(nrfx_timer_t const * p_instance)
{
    NRFX_ASSERT(m_cb[p_instance->instance_id].state == NRFX_DRV_STATE_INITIALIZED);
    m_cb[p_instance->instance_id].state = NRFX_DRV_STATE_POWERED_ON;
    nrf_timer_task_trigger(p_instance->p_reg, NRF_TIMER_TASK_START);
    NRFX_LOG_INFO("Enabled instance: %d.", p_instance->instance_id);
}

Is that change appropriate for you to make in the NCS?  If not, should there be a note somewhere for nrfx_timer_enable() that the caller should ensure the call is protected?

Thank you in advance.

[Håkon Alseth]

Hi,

 

Thank you for reporting this back to us. I'll make an internal report on this matter.

 

We fixed the race condition by putting an irq_lock() in dtm_wait() around the call to nrfx_time_enable().

Good to hear that you have a working fix. Another approach can be to schedule the ISR to main priority.

 

Kind regards,

Håkon

[variant]

Thanks for the reply, Håkon.

ISRs have their own priority compared to threads.  So please explain what you mean by "schedule the ISR to main priority"

Thanks.

[Håkon Alseth]

Hi Mike,

 

"main priority" was a bit poor choice of words from my side, "thread priority" would be better.

One could for instance offload the ISR to a workqueue:

https://docs.zephyrproject.org/3.0.0/reference/kernel/threads/workqueue.html#submitting-a-work-item

Other approaches can be to use k_poll: https://docs.zephyrproject.org/3.0.0/reference/kernel/other/polling.html

 

It all depends on what fits best. The most common implementation is to use a workq to offload ISR execution.

 

Kind regards,

Håkon

[variant]

Hi Hakon, was there any outcome of the internal report created for this ticket?  In particular, I was wondering about my suggestion to swap lines 4 and 5 in nrfx_timer_enable().

[Håkon Alseth]

Hi Mike,

 

variant said:

was there any outcome of the internal report created for this ticket?  In particular, I was wondering about my suggestion to swap lines 4 and 5 in nrfx_timer_enable().

Unfortunately, the task has not yet been looked into by the team, so I cannot answer your question directly.

That being said, if you have tested both scenarios to be working as intended in your application, you are free to choose whichever fits you the best.

 

Kind regards,

Håkon

[variant]

Thanks for the reply, Håkon.  I prefer the lines 4 and 5 swap.  The only drawback is that we would have to patch the NCS code, which we and I think most people prefer not to do.  I'll go ahead and verify this ticket as answered.  Thanks again.