diff --git a/components/timer/example/main/timer_example.cpp b/components/timer/example/main/timer_example.cpp index 072657d0b..43db02e78 100644 --- a/components/timer/example/main/timer_example.cpp +++ b/components/timer/example/main/timer_example.cpp @@ -1,6 +1,8 @@ #include +#include #include +#include #include #include @@ -51,6 +53,26 @@ extern "C" void app_main(void) { std::this_thread::sleep_for(num_seconds_to_run * 1s); } + // timer periodicity testing, with different durations + { + logger.info("Starting timer periodicity testing example"); + size_t iterations{0}; + auto timer_fn = [&iterations]() { + if (iterations % 50 == 0) { + fmt::print("[{:.3f}] #iterations = {}\n", elapsed(), iterations); + std::this_thread::sleep_for(12ms); // simulate a long callback + } + iterations++; + // we don't want to stop, so return false + return false; + }; + auto timer = espp::Timer({.name = "Timer 1", + .period = 10ms, + .callback = timer_fn, + .log_level = espp::Logger::Verbosity::WARN}); + std::this_thread::sleep_for(num_seconds_to_run * 1s); + } + // timer watchdog example { logger.info("Starting timer watchdog example"); @@ -67,7 +89,7 @@ extern "C" void app_main(void) { auto timer = espp::Timer({.name = "Timer 1", .period = 500ms, .callback = timer_fn, - .log_level = espp::Logger::Verbosity::DEBUG}); + .log_level = espp::Logger::Verbosity::INFO}); timer.start_watchdog(); // start the watchdog timer for this timer std::this_thread::sleep_for(500ms); std::error_code ec; @@ -101,7 +123,7 @@ extern "C" void app_main(void) { .delay = 500ms, .callback = timer_fn, .auto_start = false, // don't start the timer automatically, we'll call start() - .log_level = espp::Logger::Verbosity::DEBUG}); + .log_level = espp::Logger::Verbosity::INFO}); timer.start(); std::this_thread::sleep_for(2s); logger.info("Cancelling timer for 2 seconds"); @@ -132,7 +154,7 @@ extern "C" void app_main(void) { .period = 0ms, // one shot timer .delay = 500ms, .callback = timer_fn, - .log_level = espp::Logger::Verbosity::DEBUG}); + .log_level = espp::Logger::Verbosity::INFO}); //! [timer oneshot example] std::this_thread::sleep_for(num_seconds_to_run * 1s); } @@ -156,7 +178,7 @@ extern "C" void app_main(void) { .period = 500ms, .callback = timer_fn, .stack_size_bytes = 6192, - .log_level = espp::Logger::Verbosity::DEBUG}); + .log_level = espp::Logger::Verbosity::INFO}); //! [timer cancel itself example] std::this_thread::sleep_for(num_seconds_to_run * 1s); } @@ -177,7 +199,7 @@ extern "C" void app_main(void) { .delay = 500ms, .callback = timer_fn, .stack_size_bytes = 4096, - .log_level = espp::Logger::Verbosity::DEBUG}); + .log_level = espp::Logger::Verbosity::INFO}); std::this_thread::sleep_for(2s); timer.cancel(); // it will have already been cancelled by here, but this should be harmless timer.start(1s); // restart the timer with a 1 second delay @@ -200,7 +222,7 @@ extern "C" void app_main(void) { .period = 500ms, .callback = timer_fn, .stack_size_bytes = 4096, - .log_level = espp::Logger::Verbosity::DEBUG}); + .log_level = espp::Logger::Verbosity::INFO}); std::this_thread::sleep_for(2s); logger.info("Updating period to 100ms"); timer.set_period(100ms); @@ -224,11 +246,11 @@ extern "C" void app_main(void) { .task_config = { .name = "Advanced Config Timer", - .stack_size_bytes = 4096, + .stack_size_bytes = 4 * 1024, .priority = 10, .core_id = 1, }, - .log_level = espp::Logger::Verbosity::DEBUG}); + .log_level = espp::Logger::Verbosity::INFO}); //! [timer advanced config example] std::this_thread::sleep_for(num_seconds_to_run * 1s); } @@ -248,7 +270,7 @@ extern "C" void app_main(void) { auto high_resolution_timer = espp::HighResolutionTimer({.name = "High Resolution Timer", .callback = timer_fn, - .log_level = espp::Logger::Verbosity::DEBUG}); + .log_level = espp::Logger::Verbosity::INFO}); uint64_t period_us = 100; bool started = high_resolution_timer.start(period_us); logger.info("High resolution timer started: {}", started); @@ -294,7 +316,7 @@ extern "C" void app_main(void) { auto high_resolution_timer = espp::HighResolutionTimer({.name = "High Resolution Timer 1", .callback = timer_fn, - .log_level = espp::Logger::Verbosity::DEBUG}); + .log_level = espp::Logger::Verbosity::INFO}); uint64_t period_us = 100; bool started = high_resolution_timer.start(period_us); logger.info("High resolution timer 1 started: {}", started); @@ -309,7 +331,7 @@ extern "C" void app_main(void) { auto high_resolution_timer2 = espp::HighResolutionTimer({.name = "High Resolution Timer 2", .callback = timer2_fn, - .log_level = espp::Logger::Verbosity::DEBUG}); + .log_level = espp::Logger::Verbosity::INFO}); // configure the task watchdog static constexpr bool panic_on_watchdog_timeout = false; @@ -345,6 +367,406 @@ extern "C" void app_main(void) { //! [high resolution timer watchdog example] } + // =========================================================================== + // Timer test suite + // + // A set of self-checking tests that run at the end of the example and print + // PASS/FAIL for each, then an overall PASS/FAIL summary for the suite. These + // exercise the timer's periodicity (fixed-rate scheduling / no drift), delay, + // one-shot behavior, start()/is_running()/cancel(), self-cancel, and input + // validation. Timings use generous tolerances so the suite is not flaky. + // =========================================================================== + { + using namespace std::chrono; + logger.info(""); + logger.info("======== Running Timer test suite ========"); + int passed = 0; + int failed = 0; + auto check = [&](const std::string &name, bool condition) { + fmt::print(" [{}] {}\n", condition ? "PASS" : "FAIL", name); + if (condition) { + ++passed; + } else { + ++failed; + } + }; + + // 1) Periodicity: a 20 ms periodic timer should fire ~50x/s and stay on a + // fixed schedule (the k-th callback lands near k*period, i.e. no + // cumulative drift) with small per-fire jitter. + { + std::atomic count{0}; + std::atomic last_fire{0.0f}; + // worst-case deviation of any fire from its ideal time (k * period). + // Single writer (the timer task), so a plain load/store RMW is race-free. + std::atomic max_dev{0.0f}; + const float period_s = 0.020f; + auto t0 = steady_clock::now(); + auto timer = espp::Timer({.name = "test-periodicity", + .period = 20ms, + .callback = + [&count, &last_fire, &max_dev, period_s, t0]() { + const int k = count.fetch_add(1); + const float t = + duration(steady_clock::now() - t0).count(); + last_fire = t; + const float expected = k * period_s; + const float dev = t > expected ? t - expected : expected - t; + if (dev > max_dev.load()) { + max_dev.store(dev); + } + return false; + }, + .log_level = espp::Logger::Verbosity::WARN}); + std::this_thread::sleep_for(1s); + timer.cancel(); + const int n = count.load(); + // first fires immediately, then every 20 ms -> ~51 in 1 s + check("periodic timer fires ~50 times in 1 s (20 ms period)", n >= 45 && n <= 56); + // the last callback should land near (n-1)*20 ms if there is no drift + const float expected_last = (n - 1) * period_s; + const float actual_last = last_fire.load(); + check("periodic timer stays on schedule (no cumulative drift)", + n >= 2 && actual_last > expected_last - 0.030f && actual_last < expected_last + 0.030f); + // periodicity is "good enough" if no single fire strays far from its + // ideal slot (bounds worst-case jitter, not just the endpoint). + const float worst_ms = max_dev.load() * 1000.0f; + auto jmsg = fmt::format("periodic timer jitter is small (worst deviation {:.1f} ms < 15 ms)", + worst_ms); + check(jmsg, n >= 2 && max_dev.load() < 0.015f); + } + + // 2) A callback that overruns the period should run back-to-back (bounded by + // the callback duration), not stall or spiral. + { + std::atomic count{0}; + auto timer = espp::Timer({.name = "test-overrun", + .period = 20ms, + .callback = + [&count]() { + ++count; + std::this_thread::sleep_for(30ms); // longer than the period + return false; + }, + .log_level = espp::Logger::Verbosity::WARN}); + std::this_thread::sleep_for(1s); + timer.cancel(); + const int n = count.load(); + // ~30 ms per callback -> ~33 in 1 s + auto msg = fmt::format( + "Timer with a long (overrunning) callback runs continuously 27 <= {} <= 40", n); + check(msg, n >= 27 && n <= 40); + } + + // 3) Delay: the first callback fires at ~the configured delay, not before. + { + std::atomic count{0}; + std::atomic first_fire{-1.0f}; + auto t0 = steady_clock::now(); + auto timer = espp::Timer({.name = "test-delay", + .period = 50ms, + .delay = 300ms, + .callback = + [&count, &first_fire, t0]() { + if (count.fetch_add(1) == 0) { + first_fire = + duration(steady_clock::now() - t0).count(); + } + return false; + }, + .log_level = espp::Logger::Verbosity::WARN}); + std::this_thread::sleep_for(200ms); // still within the 300 ms delay + const bool none_before_delay = (count.load() == 0); + std::this_thread::sleep_for(400ms); // total 600 ms, past the delay + timer.cancel(); + const float ff = first_fire.load(); + check("delayed timer does not fire before the delay", none_before_delay); + check("delayed timer first fires at ~the delay", ff > 0.25f && ff < 0.40f); + } + + // 4) One-shot (period 0) fires exactly once. + { + std::atomic count{0}; + auto timer = espp::Timer({.name = "test-oneshot", + .period = 0ms, + .delay = 100ms, + .callback = + [&count]() { + ++count; + return false; + }, + .log_level = espp::Logger::Verbosity::WARN}); + std::this_thread::sleep_for(400ms); + check("one-shot timer (period 0) fires exactly once", count.load() == 1); + check("one-shot timer is not running after it completes", !timer.is_running()); + } + + // 5) start() / is_running() / cancel(). + { + std::atomic count{0}; + auto timer = espp::Timer({.name = "test-startstop", + .period = 50ms, + .callback = + [&count]() { + ++count; + return false; + }, + .auto_start = false, + .log_level = espp::Logger::Verbosity::WARN}); + check("timer is not running before start()", !timer.is_running()); + const bool started = timer.start(); + check("start() returns true and the timer is running", started && timer.is_running()); + check("start() on an already-running timer returns true", timer.start()); + std::this_thread::sleep_for(200ms); + timer.cancel(); + const int after_cancel = count.load(); + std::this_thread::sleep_for(150ms); + check("cancel() stops the timer (no more callbacks)", + !timer.is_running() && count.load() == after_cancel); + } + + // 6) A callback that returns true stops the timer. + { + std::atomic count{0}; + auto timer = espp::Timer({.name = "test-selfstop", + .period = 50ms, + .callback = [&count]() { return ++count >= 3; }, + .log_level = espp::Logger::Verbosity::WARN}); + std::this_thread::sleep_for(400ms); + check("callback returning true stops the timer", count.load() == 3 && !timer.is_running()); + } + + // 7) Input validation: a negative period is clamped (behaves as one-shot). + { + std::atomic count{0}; + auto timer = espp::Timer({.name = "test-negative-period", + .period = -50ms, + .callback = + [&count]() { + ++count; + return false; + }, + .log_level = espp::Logger::Verbosity::WARN}); + std::this_thread::sleep_for(300ms); + timer.cancel(); + check("negative period is clamped (runs once, not repeatedly)", count.load() == 1); + } + + // 8) Fixed-rate: a callback that does work but finishes within the period + // must not stretch the period (its run time is absorbed). A naive "sleep + // for the period after the callback" would fire at ~1/(period + work). + { + std::atomic count{0}; + auto timer = espp::Timer({.name = "test-absorb", + .period = 40ms, + .callback = + [&count]() { + ++count; + std::this_thread::sleep_for(15ms); // < period + return false; + }, + .log_level = espp::Logger::Verbosity::WARN}); + std::this_thread::sleep_for(1s); + timer.cancel(); + const int n = count.load(); + // 40 ms period with the 15 ms callback absorbed -> ~25 in 1 s (not ~18) + auto msg = + fmt::format("callback shorter than the period does not stretch it: 22 <= {} <= 28", n); + check(msg, n >= 22 && n <= 28); + } + + // 9) Delay + period together: the first callback fires at ~the delay, the + // second one period later. + { + std::atomic count{0}; + std::atomic first_fire{-1.0f}; + std::atomic second_fire{-1.0f}; + auto t0 = steady_clock::now(); + auto timer = espp::Timer({.name = "test-delay-period", + .period = 100ms, + .delay = 200ms, + .callback = + [&count, &first_fire, &second_fire, t0]() { + float t = duration(steady_clock::now() - t0).count(); + int c = count.fetch_add(1); + if (c == 0) { + first_fire = t; + } else if (c == 1) { + second_fire = t; + } + return false; + }, + .log_level = espp::Logger::Verbosity::WARN}); + std::this_thread::sleep_for(500ms); + timer.cancel(); + const float f = first_fire.load(); + const float s = second_fire.load(); + check("delay+period: first fires at ~the delay", f > 0.15f && f < 0.28f); + check("delay+period: second fires ~one period after the first", + s - f > 0.07f && s - f < 0.14f); + } + + // 10) start(delay) overload: starts with the given initial delay. + { + std::atomic count{0}; + std::atomic first_fire{-1.0f}; + auto t0 = steady_clock::now(); + auto timer = espp::Timer({.name = "test-start-delay", + .period = 50ms, + .callback = + [&count, &first_fire, t0]() { + if (count.fetch_add(1) == 0) { + first_fire = + duration(steady_clock::now() - t0).count(); + } + return false; + }, + .auto_start = false, + .log_level = espp::Logger::Verbosity::WARN}); + const bool started = timer.start(200ms); + std::this_thread::sleep_for(400ms); + timer.cancel(); + const float f = first_fire.load(); + check("start(delay) returns true", started); + check("start(delay) delays the first fire", f > 0.15f && f < 0.30f); + } + + // 11) cancel() then start() again resumes; stop() is an alias for cancel(). + { + std::atomic count{0}; + auto timer = espp::Timer({.name = "test-restart", + .period = 40ms, + .callback = + [&count]() { + ++count; + return false; + }, + .log_level = espp::Logger::Verbosity::WARN}); + std::this_thread::sleep_for(150ms); + timer.stop(); // alias for cancel() + const bool stopped = !timer.is_running(); + const int c_paused = count.load(); + std::this_thread::sleep_for(150ms); + const bool no_fire_while_stopped = (count.load() == c_paused); + const bool restarted = timer.start(); + std::this_thread::sleep_for(150ms); + timer.cancel(); + const bool resumed = (count.load() > c_paused); + check("stop() stops the timer (no more callbacks)", stopped && no_fire_while_stopped); + check("start() after cancel resumes the timer", restarted && resumed); + } + + // 12) set_period() changes the rate of a running timer. + { + std::atomic count{0}; + auto timer = espp::Timer({.name = "test-set-period", + .period = 100ms, + .callback = + [&count]() { + ++count; + return false; + }, + .log_level = espp::Logger::Verbosity::WARN}); + std::this_thread::sleep_for(250ms); // ~2-3 fires at 100 ms + timer.set_period(20ms); // speed up + count = 0; + std::this_thread::sleep_for(250ms); // now ~10-12 fires at 20 ms + const int n_fast = count.load(); + auto msg = fmt::format("set_period() speeds up a running timer: {} >= 8", n_fast); + check(msg, n_fast >= 8); + timer.set_period(200ms); // slow down + count = 0; + std::this_thread::sleep_for(300ms); // at most ~2 fires at 200 ms + const int n_slow = count.load(); + timer.cancel(); + auto slow_msg = fmt::format("set_period() slows down a running timer: {} <= 3", n_slow); + check(slow_msg, n_slow <= 3); + } + + // 13) set_period(0) turns a running periodic timer into a one-shot (it stops + // after the current callback). + { + std::atomic count{0}; + auto timer = espp::Timer({.name = "test-set-period-zero", + .period = 50ms, + .callback = + [&count]() { + ++count; + return false; + }, + .log_level = espp::Logger::Verbosity::WARN}); + std::this_thread::sleep_for(120ms); + timer.set_period(0ms); // -> one-shot + std::this_thread::sleep_for(200ms); + const bool stopped = !timer.is_running(); + const int c = count.load(); + std::this_thread::sleep_for(120ms); + check("set_period(0) stops a running timer", stopped && count.load() == c); + } + + // 14) Input validation: start() with a negative delay is rejected. + { + std::atomic count{0}; + auto timer = espp::Timer({.name = "test-neg-delay", + .period = 50ms, + .callback = + [&count]() { + ++count; + return false; + }, + .auto_start = false, + .log_level = espp::Logger::Verbosity::WARN}); + const bool result = timer.start(-100ms); + std::this_thread::sleep_for(150ms); + check("start() with a negative delay is rejected", + !result && count.load() == 0 && !timer.is_running()); + } + + // 15) A timer with a null callback stops itself without crashing. + { + auto timer = espp::Timer({.name = "test-null-callback", + .period = 50ms, + .callback = nullptr, + .log_level = espp::Logger::Verbosity::WARN}); + std::this_thread::sleep_for(150ms); + check("timer with a null callback stops itself (no crash)", !timer.is_running()); + } + + // 16) Watchdog: a timer whose callback overruns the watchdog is reported by + // get_watchdog_info(). + { + espp::Task::configure_task_watchdog(50ms, false); // 50 ms, don't panic + std::atomic count{0}; + auto timer = espp::Timer({.name = "test-watchdog", + .period = 200ms, + .callback = + [&count]() { + ++count; + std::this_thread::sleep_for(120ms); // > 50 ms watchdog + return false; + }, + .log_level = espp::Logger::Verbosity::WARN}); + const bool wd_started = timer.start_watchdog(); + std::this_thread::sleep_for(300ms); + std::error_code ec; + const std::string info = espp::Task::get_watchdog_info(ec); + const bool flagged = !ec && info.find("test-watchdog") != std::string::npos; + timer.stop_watchdog(); + timer.cancel(); + check("start_watchdog() returns true", wd_started); + check("watchdog reports an overrunning timer's task", flagged); + } + + // ---- summary ---- + fmt::print("\n"); + logger.info("======== Timer test suite: {}/{} passed ========", passed, passed + failed); + if (failed == 0) { + logger.info("TIMER TESTS RESULT: PASS ({} tests)", passed); + } else { + logger.error("TIMER TESTS RESULT: FAIL ({} passed, {} failed)", passed, failed); + } + } + logger.info("Example complete!"); while (true) { diff --git a/components/timer/example/sdkconfig.defaults b/components/timer/example/sdkconfig.defaults index 93db57dc7..670bbc974 100644 --- a/components/timer/example/sdkconfig.defaults +++ b/components/timer/example/sdkconfig.defaults @@ -1,8 +1,13 @@ +CONFIG_COMPILER_OPTIMIZATION_PERF=y + # Common ESP-related # CONFIG_ESP_SYSTEM_EVENT_TASK_STACK_SIZE=4096 CONFIG_ESP_MAIN_TASK_STACK_SIZE=8192 +# Set the FreeRTOS rate to 1ms (1000Hz) +CONFIG_FREERTOS_HZ=1000 + # Enable support for power management # NOTE: if you enable this the USB serial will not work in light sleep mode # CONFIG_PM_ENABLE=y diff --git a/components/timer/include/timer.hpp b/components/timer/include/timer.hpp index 609e66ef9..2c436a8be 100644 --- a/components/timer/include/timer.hpp +++ b/components/timer/include/timer.hpp @@ -35,6 +35,20 @@ namespace espp { /// long time, then the timer will not be able to keep up with the /// period. /// +/// @note Timing resolution. On ESP / FreeRTOS the timer waits on the +/// scheduler, which can only resolve time to a single tick +/// (1 / CONFIG_FREERTOS_HZ seconds; e.g. 10 ms at the 100 Hz default, +/// 1 ms at 1000 Hz). A period or delay that is shorter than - or within +/// a couple of ticks of - the tick period cannot be honored accurately: +/// it will be rounded up to a whole number of ticks and can jitter by up +/// to a full tick. The constructor, set_period() and start(delay) log a +/// warning when the requested period/delay is at or near the tick +/// period. For sub-tick or highly accurate periodic work, either raise +/// CONFIG_FREERTOS_HZ or use the esp_timer-based HighResolutionTimer +/// instead. The timer schedules against an absolute wake-up time (the +/// k-th callback targets start + k*period), so it does not accumulate +/// drift even when individual iterations jitter. +/// /// \section timer_ex1 Timer Example 1 /// \snippet timer_example.cpp timer example /// \section timer_ex2 Timer Watchdog Example @@ -99,7 +113,9 @@ class Timer : public BaseComponent { /// @brief Start the timer. /// @details Starts the timer. Does nothing if the timer is already running. - void start(); + /// @return true if the timer was started or is already running, false if the + /// timer could not be started. + bool start(); /// @brief Start the timer with a delay. /// @details Starts the timer with a delay. If the timer is already running, @@ -108,7 +124,9 @@ class Timer : public BaseComponent { /// with the delay. Overwrites any previous delay that might have /// been set. /// @param delay The delay before the first execution of the timer callback. - void start(const std::chrono::duration &delay); + /// @return true if the timer was started or restarted, false if the timer + /// could not be started. + bool start(const std::chrono::duration &delay); /// @brief Stop the timer, same as cancel(). /// @details Stops the timer, same as cancel(). @@ -157,9 +175,26 @@ class Timer : public BaseComponent { protected: bool timer_callback_fn(std::mutex &m, std::condition_variable &cv, bool &task_notified); + /// @brief Warn if a period/delay is at or near the FreeRTOS tick period. + /// @details On ESP / FreeRTOS the scheduler can only resolve timing to a + /// single tick (1 / CONFIG_FREERTOS_HZ), so a period or delay that + /// is shorter than - or similar to - the tick period cannot be + /// honored accurately. This logs a warning in that case. + /// @param duration The period or delay to check. + /// @param what A short label ("period" or "delay") used in the warning. + /// @note Does nothing off ESP_PLATFORM or when the duration is <= 0. + void warn_if_below_tick_period(const std::chrono::microseconds &duration, const char *what) const; + + std::recursive_mutex mutex_; ///< Mutex to protect the timer state. std::chrono::microseconds period_{0}; ///< The period of the timer. If 0, the timer will run once. std::chrono::microseconds delay_{0}; ///< The delay before the timer starts. std::atomic running_{false}; ///< True if the timer is running, false otherwise. + std::chrono::time_point + start_time_; ///< The time point when the timer was started. + std::chrono::time_point + delay_wakeup_time_; ///< The time point when the timer will wake up after the delay if any. + std::chrono::time_point + wakeup_time_; ///< The time point when the timer will wake up. float period_float; float delay_float; callback_fn callback_; ///< The callback function to call when the timer expires. diff --git a/components/timer/src/timer.cpp b/components/timer/src/timer.cpp index f91bf1663..e8264478e 100644 --- a/components/timer/src/timer.cpp +++ b/components/timer/src/timer.cpp @@ -1,7 +1,34 @@ #include "timer.hpp" +#if defined(ESP_PLATFORM) +#include +#endif + using namespace espp; +void Timer::warn_if_below_tick_period(const std::chrono::microseconds &duration, + const char *what) const { +#if defined(ESP_PLATFORM) && defined(CONFIG_FREERTOS_HZ) + if (duration.count() <= 0) { + // 0 period means one-shot; 0 delay means no delay - nothing to warn about. + return; + } + // The FreeRTOS scheduler resolves timing to a single tick, so a period/delay + // shorter than - or within ~2 ticks of - the tick period cannot be honored + // accurately (it will be rounded up and/or jitter by up to a full tick). + static constexpr int64_t tick_period_us = 1000000 / CONFIG_FREERTOS_HZ; + if (duration.count() < 2 * tick_period_us) { + logger_.warn("Requested {} of {} us is at or near the FreeRTOS tick period " + "({} us at CONFIG_FREERTOS_HZ={}); timing cannot be honored " + "accurately - use a longer {} or increase CONFIG_FREERTOS_HZ", + what, duration.count(), tick_period_us, CONFIG_FREERTOS_HZ, what); + } +#else + (void)duration; + (void)what; +#endif +} + Timer::Timer(const Timer::Config &config) : BaseComponent(config.name, config.log_level) , period_(std::chrono::duration_cast(config.period)) @@ -24,6 +51,18 @@ Timer::Timer(const Timer::Config &config) }); period_float = std::chrono::duration(period_).count(); delay_float = std::chrono::duration(delay_).count(); + if (period_float < 0) { + logger_.warn("period cannot be negative, setting to 0"); + period_ = std::chrono::microseconds(0); + period_float = 0; + } + if (delay_float < 0) { + logger_.warn("delay cannot be negative, setting to 0"); + delay_ = std::chrono::microseconds(0); + delay_float = 0; + } + warn_if_below_tick_period(period_, "period"); + warn_if_below_tick_period(delay_, "delay"); if (config.auto_start) { start(); } @@ -45,6 +84,18 @@ Timer::Timer(const Timer::AdvancedConfig &config) }); period_float = std::chrono::duration(period_).count(); delay_float = std::chrono::duration(delay_).count(); + if (period_float < 0) { + logger_.warn("period cannot be negative, setting to 0"); + period_ = std::chrono::microseconds(0); + period_float = 0; + } + if (delay_float < 0) { + logger_.warn("delay cannot be negative, setting to 0"); + delay_ = std::chrono::microseconds(0); + delay_float = 0; + } + warn_if_below_tick_period(period_, "period"); + warn_if_below_tick_period(delay_, "delay"); if (config.auto_start) { start(); } @@ -52,25 +103,63 @@ Timer::Timer(const Timer::AdvancedConfig &config) Timer::~Timer() { cancel(); } -void Timer::start() { - logger_.info("starting with period {:.3f} s and delay {:.3f} s", period_float, delay_float); - running_ = true; - // start the task - task_->start(); +bool Timer::start() { + // Atomically claim the start: only one caller can flip running_ from false to + // true. This closes the race where two concurrent start() calls both observe + // "not running" and both go on to start the task. + bool expected = false; + if (!running_.compare_exchange_strong(expected, true)) { + logger_.info("timer is already running, not starting"); + return true; + } + float local_period_float; + float local_delay_float; + std::chrono::time_point local_wakeup_time; + std::chrono::time_point local_start_time; + { + std::lock_guard lock(mutex_); + start_time_ = std::chrono::steady_clock::now(); + wakeup_time_ = start_time_; + if (delay_float > 0) { + wakeup_time_ += delay_; + delay_wakeup_time_ = wakeup_time_; + } + if (period_float > 0) { + wakeup_time_ += period_; + } + local_period_float = period_float; + local_delay_float = delay_float; + local_wakeup_time = wakeup_time_; + local_start_time = start_time_; + } + if (task_->start()) { + logger_.info("Started with period {:.3f} s and delay {:.3f} s. Will wake up in {:.3f} s", + local_period_float, local_delay_float, + std::chrono::duration(local_wakeup_time - local_start_time).count()); + return true; + } + // reset the flag if the task failed to start + running_ = false; + logger_.error("failed to start timer task"); + return false; } -void Timer::start(const std::chrono::duration &delay) { +bool Timer::start(const std::chrono::duration &delay) { if (delay.count() < 0) { logger_.warn("delay cannot be negative, not starting"); - return; + return false; } if (is_running()) { logger_.info("restarting with delay {:.3f} s", delay.count()); cancel(); } - delay_ = std::chrono::duration_cast(delay); - delay_float = std::chrono::duration(delay_).count(); - start(); + { + std::lock_guard lock(mutex_); + delay_ = std::chrono::duration_cast(delay); + delay_float = std::chrono::duration(delay_).count(); + } + warn_if_below_tick_period(std::chrono::duration_cast(delay), "delay"); + return start(); } void Timer::stop() { cancel(); } @@ -93,9 +182,14 @@ void Timer::set_period(const std::chrono::duration &period) { logger_.warn("period cannot be negative, not setting"); return; } - period_ = std::chrono::duration_cast(period); - period_float = std::chrono::duration(period_).count(); - logger_.info("setting period to {:.3f} s", period_float); + { + std::lock_guard lock(mutex_); + period_ = std::chrono::duration_cast(period); + period_float = std::chrono::duration(period_).count(); + } + warn_if_below_tick_period(std::chrono::duration_cast(period), + "period"); + logger_.info("Period set to {:.3f} s", period.count()); } bool Timer::is_running() const { return running_ && task_->is_running(); } @@ -113,50 +207,104 @@ bool Timer::timer_callback_fn(std::mutex &m, std::condition_variable &cv, bool & running_ = false; return true; } + // initial delay, if any - this is only used the first time the timer // runs - if (delay_float > 0) { - auto start_time = std::chrono::steady_clock::now(); - logger_.debug("waiting for delay {:.3f} s", delay_float); - std::unique_lock lock(m); - cv.wait_until(lock, start_time + delay_, [&task_notified] { return task_notified; }); - // reset the task_notified flag - task_notified = false; + float local_delay_float; + { + std::lock_guard lock(mutex_); + local_delay_float = delay_float; + } + if (local_delay_float > 0) { + std::chrono::time_point local_delay_wakeup_time; + { + std::lock_guard lock(mutex_); + local_delay_wakeup_time = delay_wakeup_time_; + } + logger_.debug("waiting for delay {:.3f} s", local_delay_float); + { + std::unique_lock lock(m); + cv.wait_until(lock, local_delay_wakeup_time, [&task_notified] { return task_notified; }); + // reset the task_notified flag + task_notified = false; + } if (!running_) { logger_.debug("delay canceled, stopping"); return true; } // now set the delay to 0 - delay_ = std::chrono::microseconds(0); - delay_float = 0; + { + std::lock_guard lock(mutex_); + delay_ = std::chrono::microseconds(0); + delay_float = 0; + } } + // now run the callback - auto start_time = std::chrono::steady_clock::now(); logger_.debug("running callback"); + auto start_time = std::chrono::steady_clock::now(); bool requested_stop = callback_(); - if (requested_stop || period_float <= 0) { + auto end = std::chrono::steady_clock::now(); + + std::chrono::time_point local_wakeup_time; + std::chrono::microseconds local_period; + float local_period_float; + { + std::lock_guard lock(mutex_); + local_wakeup_time = wakeup_time_; + local_period = period_; + local_period_float = period_float; + } + + if (requested_stop || local_period_float <= 0) { // stop the timer if requested or if the period is <= 0 logger_.debug("callback requested stop or period is <= 0, stopping"); running_ = false; return true; } - auto end = std::chrono::steady_clock::now(); - float elapsed = std::chrono::duration(end - start_time).count(); - if (elapsed > period_float) { - // if the callback took longer than the period, then we should just - // return and run the callback again immediately - logger_.warn_rate_limited("callback took longer ({:.3f} s) than period ({:.3f} s)", elapsed, - period_float); + + if (local_wakeup_time <= end) { + // if the callback took longer (or just as long) than the period (so it is + // already past the next wakeup time), log a warning and ensure that the + // next wakeup time is the closest multiple of the period after the current + float elapsed = std::chrono::duration(end - start_time).count(); + if (elapsed >= local_period_float) { + logger_.warn_rate_limited("callback took ~longer ({:.3f} s) than period ({:.3f} s)", elapsed, + local_period_float); + } + if (local_period.count() <= 0) { + // period changed to oneshot while running; stop after this callback + running_ = false; + return true; + } + // update the next wakeup time to the closest multiple of the period after the current time + size_t n = (end - local_wakeup_time) / local_period + 1; + // only log if we are skipping more than one period + if (n > 1) { + logger_.warn("Already passed expected wakeup time, skipping {} periods", n); + } + std::lock_guard lock(mutex_); + wakeup_time_ += n * local_period; + // return immediately to execute the next callback iteration return false; } + // now wait for the period (taking into account the time it took to run // the callback) { std::unique_lock lock(m); - cv.wait_until(lock, start_time + period_, [&task_notified] { return task_notified; }); + cv.wait_until(lock, local_wakeup_time, [&task_notified] { return task_notified; }); // reset the task_notified flag task_notified = false; } + + // now that we've waited, make sure the next wakeup time is the next multiple + // of the period after the last + { + std::lock_guard lock(mutex_); + wakeup_time_ += period_; + } + // keep the timer running return false; } diff --git a/doc/en/core/timer.rst b/doc/en/core/timer.rst index 3d2bf7bc5..4a4b2c3b0 100644 --- a/doc/en/core/timer.rst +++ b/doc/en/core/timer.rst @@ -12,6 +12,28 @@ callback is executed. The timer can be configured to run once or repeatedly. The timer API is implemented using the `Task` component, and the timer callback is executed in the context of the timer task. +The timer schedules against an absolute wake-up time (the k-th callback targets +``start + k * period``) rather than sleeping for ``period`` after each callback, +so it does not accumulate drift even when an individual callback runs long or +the scheduler jitters. If a callback overruns the period, subsequent callbacks +run back-to-back to catch up (a rate-limited warning is logged) instead of the +schedule slipping permanently. + +Timing and resolution +^^^^^^^^^^^^^^^^^^^^^^^ + +On ESP / FreeRTOS the timer waits on the scheduler, which can only resolve time +to a single tick (``1 / CONFIG_FREERTOS_HZ`` seconds - e.g. 10 ms at the 100 Hz +default, or 1 ms at 1000 Hz). A period or delay that is shorter than - or within +a couple of ticks of - the tick period cannot be honored accurately: it is +rounded up to a whole number of ticks and can jitter by up to a full tick. The +constructor, :cpp:func:`set_period` and :cpp:func:`start` log a warning when the +requested period/delay is at or near the tick period. + +For sub-tick periods or highly accurate periodic work, either raise +``CONFIG_FREERTOS_HZ`` (menuconfig: ``FreeRTOS`` → ``Tick rate (Hz)``) or use the +esp_timer-based ``HighResolutionTimer`` described below. + Code examples for the task API are provided in the `timer` example folder. .. ------------------------------- Example -------------------------------------