Timer::after() occasionally never returns with embassy-time driver

[stevehayles]

TL;DR: Do NOT use async-executor or edge-executor V <= 0.4.1 because the queues they use (crossbeam-queue and concurrent-queue) do NOT work with multi-prio threads and lead to priority inversion).

Until (or if) the problem in async-executor is confirmed and fixed, consider using:

• embassy-executor
• edge-executor from GIT
• The executor from the futures crate

See this for more details.

====================================

Bug description

embassy-time timers (Timer::after()) occasionally never return when using the Embassy time driver provided in esp-idf-svc. This occurs more frequently with short delays (e.g., 50–100 ms) and with multiple tasks using Timer::after() calls

• Would you like to work on a fix? Yes

To Reproduce

1. Enable the embassy-time-driver feature in esp-idf-svc.
2. Use any executor (e.g., edge-executor) with the Embassy time driver.
3. Spawn several tasks that repeatedly await short timers:

async fn ticker() { loop { Timer::after(Duration::from_millis(100)).await; // log or toggle GPIO } }

4. After some period of time (minutes to hours depending on load), the loop stops printing/toggling.
5. No panic occurs — the task simply hangs waiting for a timer that never fires.

Environment

• Crate (esp-idf-svc) version: 0.51.x
• ESP-IDF version: v5.3 / v5.5
• Target device (MCU): esp32
• OS: Windows 11 build-host (also reproducible on Linux)

[ivmarkov]

Hmmm, that would be pretty bad if it happens!
Do you have a repro that I can use?

[ivmarkov]

As in, a ready-to-build example?

[stevehayles]

It's happening in a fairly complex codebase and only after a period of some time (10's of minutes) so I don't have a minimum reproduceable example just yet. I am wondering if there is there a possibility of a deadlock in the timer EspDriver -> schedule_wake() function.

I am still trying to reason this through but isn't the mutex acquired by the normal task context and also from the esp_timer hardware context when the hardware timer fires ? Could it just be an unlikely event that becomes more of a risk with more calls to Timer::after with shorter delays ? I am just working on a version that removes the mutex and uses a critical section.

I will also try and create a simple repro that exhibits the issue

[stevehayles]

Further to the previous comments: I haven’t yet reduced the application to a minimal repro, as the failure mode takes time and each iteration is slow. However, I have updated the EspDriver implementation to use a blocking_mutex::Mutex<blocking_mutex::raw::CriticalSectionRawMutex> from embassy_sync, and with that change the application has now been running for 18 hours without any issues.

I appreciate that this is not a definitive bug report, and I’m currently trying to determine whether the improvement is causal or just coincidental. I’ll provide more information as soon as I can.

[ivmarkov]

I am still trying to reason this through but isn't the mutex acquired by the normal task context and also from the esp_timer hardware context when the hardware timer fires ?

The embassy-time driver in esp-idf-svc is not based on a hardware timer, but on a higher-level API called the ESP-IDF Timer Service.

This Timer service dispatches either from a task (= thread) or from an ISR context (but only if the support for dispatching from an ISR context is enabled compile-time, from sdkconfig.defaults).

Regardless whether dispatching from an ISR context is enabled, the embassy-time driver always asks the Timer service to dispatch from a thread.

So the TL;DR is: it should not really matter whether you use the esp-idf-svc-provided Mutex, or the Mutex from embassy-sync.

Not to mention that the CriticalSectionRawMutex that you are using is STILL NOT a critical section-based mutex (in the semantics of "let's disable all interrupts" baremetal style of programming) but is a regular ESP-IDF/FreeRTOS mutex.

So if there is indeed a bug, the fact that it does work with your mutex is I think - unfortunately - a pure coincidence.

[fko-kuptec]

This sounds a lot like my bug report to async-io-mini, where also Timers don't get woken in special circumstances. But that would require that both the embassy_time::Timer and async_io_mini::Timer share the same implementation issue.

TLDR for the issue in async-io-mini: If the timer queue is already full and a new timer is scheduled, some other timer is woken too early. The timer implementation does not recognize that it needs to reschedule that timer, which results in that timer starving.

[ivmarkov]

@fko-kuptec Just to say sorry that I have not reacted (yet) on your PR in async-io-mini. Too many things going on, and in the meantime I was trying to see if we have a cleaner solution, where we no longer need to do these hacks. No such luck yet. The real problem is that the async_io::Timer thing implements the future trait onto itself, while embassy-time does it by its Timer type returning a future when you call after at and so on. Quite a mismatch...

[ivmarkov]

This sounds a lot like my bug report to async-io-mini, where also Timers don't get woken in special circumstances. But that would require that both the embassy_time::Timer and async_io_mini::Timer share the same implementation issue.

TLDR for the issue in async-io-mini: If the timer queue is already full and a new timer is scheduled, some other timer is woken too early. The timer implementation does not recognize that it needs to reschedule that timer, which results in that timer starving.

Indeed and I agree that's the problem in async-io-mini.

I have my doubts though that the problem in the esp-iidf-hal is the same. Would be good to have a repro though...

[fko-kuptec]

@ivmarkov

Just to say sorry that I have not reacted (yet) on your PR in async-io-mini. Too many things going on, and in the meantime I was trying to see if we have a cleaner solution, where we no longer need to do these hacks. No such luck yet.

No worries, I am staying with my temporary fix in the meantime. 😃

I have my doubts though that the problem in the esp-iidf-hal is the same. Would be good to have a repro though...

The similarities in the symptoms just seemed striking to me. I didn't take a look at the source code of the embassy_time::Timer implementation to validate my suspicion. In my case, a reproduction was also not that easy to do. Starting way too many timers in parallel might help?

[ivmarkov]

The similarities in the symptoms just seemed striking to me. I didn't take a look at the source code of the embassy_time::Timer implementation to validate my suspicion. In my case, a reproduction was also not that easy to do. Starting way too many timers in parallel might help?

It might, yes. @stevehayles said he is trying to come up with a repro...

[fko-kuptec]

@stevehayles Because you specifically mentioned edge-executor: Does the issue persist another executor than edge-executor or async-executor? Because quite some time ago I ran into the following issue with running on an ESP32S3 with PSRAM enabled. Maybe that's not the case for you. I just wanted to mention it.

[stevehayles]

Thanks @fko-kuptec , I had read your issue on the edge-executor repo, and I haven't got as far as swapping out the executor. I am using my own priority executor which layers on to of the edge local executor but I have gone back to the edge-executor and the problem remains.

One very repeatable but non deterministic bit of feedback is that the problem manifests way earlier (which a minute or two as opposed to maybe 10's of minues) if I do a Ctrl-R warm reboot of the device rather than starting from cold or flashing new firmware. It feels like a very difficult bug to track down....