Embassy timer very slow

[phemmer]

I'm trying to use embassy with sub-millisecond timers, but it seems the overhead of scheduling the future (and thus minimum possible delay) is 1.4ms, which is a really long time. Is there any way to get higher precision async delays? I probably need something that can do at least 100us, but lower would be better/safer.

Here's a really simple test program I was using to measure on an ESP32-C6:

#![no_std]
#![no_main]

use esp_backtrace as _;
use embassy_time::{Timer, Instant};
use embassy_executor::Spawner;
use esp_hal::{clock::ClockControl, peripherals::Peripherals, prelude::*, embassy::{self}};
use esp_hal::timer::TimerGroup;
use esp_println::println;

#[main]
async fn main(spawner: Spawner) {
    let peripherals = Peripherals::take();
    let system = peripherals.SYSTEM.split();
    let clocks = ClockControl::max(system.clock_control).freeze();
    let timg0 = TimerGroup::new(peripherals.TIMG0, &clocks);

    embassy::init(&clocks, timg0);

    let first = Instant::now();
    let second = Instant::now();
    println!("first={} second={} diff={}", first, second, (second - first).as_micros());

    let first = Instant::now();
    Timer::after_nanos(0).await;
    let second = Instant::now();
    println!("first={} second={} diff={}", first, second, (second - first).as_micros());

    loop{}
}

Which produces:

first=56 ticks second=82 ticks diff=26
first=3987 ticks second=5472 ticks diff=1485

The first line shows the overhead of just calling Instant::now() twice, showing the overhead is minimal (26us). The second line shows that the Timer::after_nanos(0).await adds ~1400us.

[MabezDev]

That is indeed very slow, for instance the latency on serving an interrupt since #1310 (comment) is around 10us, so 1400us is huge. I imagine there is a bug here some where. Perhaps the timer isn't firing if it's past the target count, and instead waiting for the timer to loop back around?

[MabezDev]

I am surprised it takes 26us to call now twice, are you running with --release?

[jessebraham]

I just ran this example using the release profile and got the following results (ran multiple times, got the same results):

first=3 ticks second=5 ticks diff=2
first=3045 ticks second=3108 ticks diff=63

Using the dev profile I get similar results to OP:

first=107 ticks second=134 ticks diff=27
first=4275 ticks second=5739 ticks diff=1464

So I will say it's pretty likely that release is not being used in this case. I guess we should prioritize #1261.

Closing this as I think it's a non-issue, however if my analysis is incorrect please feel free to re-open the discussion or to create a new one.

[phemmer]

Yup, that's likely the issue. I don't currently have access to the device so I can't test, but seems certain. Thanks!

I see mention in #1261 about putting it in docs, but some additional thoughts:

1. Perhaps have a warning emitted as part of the build (if even possible)
2. Couple documentation spots that I would have seen: https://docs.esp-rs.org/book/tooling/espflash.html and https://docs.esp-rs.org/book/troubleshooting/index.html

Might also explicitly call how how bad the performance is. Even when I see warnings like "dev mode is slow", I imagine things like 1.5x slower, not 23x.

[jessebraham]

I think those are all great ideas, thanks. I'll bring these points up during our team meeting on Monday, and will make a push to address this next week. At least printing a warning at build time when using the dev profile should not be difficult I don't think.

[bjoernQ]

The warning (maybe phrased in a very scary way) would be really nice. We have that in esp-wifi but it's usually not seen by users because of the way how cargo handles warnings emitted by build scripts: https://doc.rust-lang.org/cargo/reference/build-scripts.html#cargo-warning

Having a robust solution to emit warnings would be a good thing.

Mabe something like this: https://play.rust-lang.org/?version=stable&mode=debug&edition=2015&gist=bbb23848b4b04193fa712539ab3fb17d

[jessebraham]

Is there something wrong with the warning function I implemented in esp-build?

[bjoernQ]

Oh, missed that! You are not using cargo::warning so cargo can't block it 😄 let's try it

[bjoernQ]

I can confirm that works! It's creating a new stream to the terminal somehow (via termcolor crate) and that way the output really goes to the terminal. That's interesting .... also piping the output of cargo doesn't stop the alert from appearing in the terminal😆

Probably not good in all situations but for this it seems to be exactly what we need!

So, my suggestion would be to just do it this way (and also use esp-build in esp-wifi in future)

[bjoernQ]

BTW just using e.g. eprintln! will only be visible when the build fails ... so really nice to have this option