diff --git a/esphome/components/runtime_stats/runtime_stats.h b/esphome/components/runtime_stats/runtime_stats.h index 58abfa8da1..24b6807008 100644 --- a/esphome/components/runtime_stats/runtime_stats.h +++ b/esphome/components/runtime_stats/runtime_stats.h @@ -42,7 +42,9 @@ class RuntimeStatsCollector { // before_us = time spent in Phase A (scheduler tick) excluding time // already attributed to per-component stats. // tail_us = time spent in after_loop_tasks_ + the trailing record/stats - // prefix. Zero on Phase A-only ticks (component phase gated). + // prefix. On Phase A-only ticks (component phase gated) this + // is just the small trailing prefix between loop_before_end_us + // and loop_now_us — non-zero but typically a few µs. // Residual overhead at log time = active − Σ(component) − before − tail, // which captures per-iteration inter-component bookkeeping (set_current_component, // WarnIfComponentBlockingGuard construction/destruction, feed_wdt_with_time calls, diff --git a/esphome/core/application.cpp b/esphome/core/application.cpp index 53953040f5..06b2736f67 100644 --- a/esphome/core/application.cpp +++ b/esphome/core/application.cpp @@ -219,6 +219,11 @@ void Application::feed_wdt() { if (now - this->last_wdt_feed_ > WDT_FEED_INTERVAL_MS) { this->feed_wdt_slow_(now); } +#ifdef USE_STATUS_LED + if (now - this->last_status_led_service_ > STATUS_LED_DISPATCH_INTERVAL_MS) { + this->service_status_led_slow_(now); + } +#endif } void HOT Application::feed_wdt_slow_(uint32_t time) { @@ -226,27 +231,36 @@ void HOT Application::feed_wdt_slow_(uint32_t time) { // confirmed the WDT_FEED_INTERVAL_MS rate limit was exceeded. arch_feed_wdt(); this->last_wdt_feed_ = time; -#ifdef USE_STATUS_LED - if (status_led::global_status_led != nullptr) { - auto *sl = status_led::global_status_led; - uint8_t sl_state = sl->get_component_state() & COMPONENT_STATE_MASK; - if (sl_state == COMPONENT_STATE_LOOP_DONE) { - // status_led only transitions to LOOP_DONE from inside its own loop() (after the - // first idle-path dispatch), so its pin is already initialized by pre_setup() and - // its setup() has already run. Re-dispatch only if an error or warning bit has been - // set since; otherwise skip entirely. - if ((this->app_state_ & STATUS_LED_MASK) == 0) - return; - sl->enable_loop(); - } else if (sl_state != COMPONENT_STATE_LOOP) { - // CONSTRUCTION/SETUP/FAILED: not our job — App::setup() drives the lifecycle. - return; - } - sl->loop(); - } -#endif } +#ifdef USE_STATUS_LED +void HOT Application::service_status_led_slow_(uint32_t time) { + // Callers (feed_wdt(), feed_wdt_with_time()) have already confirmed the + // STATUS_LED_DISPATCH_INTERVAL_MS rate limit was exceeded. Rate-limited + // separately from arch_feed_wdt() so the LED blink pattern stays readable + // (status_led error blink period is 250 ms) while HAL watchdog pokes can + // still run at the much coarser WDT_FEED_INTERVAL_MS cadence. + this->last_status_led_service_ = time; + if (status_led::global_status_led == nullptr) + return; + auto *sl = status_led::global_status_led; + uint8_t sl_state = sl->get_component_state() & COMPONENT_STATE_MASK; + if (sl_state == COMPONENT_STATE_LOOP_DONE) { + // status_led only transitions to LOOP_DONE from inside its own loop() (after the + // first idle-path dispatch), so its pin is already initialized by pre_setup() and + // its setup() has already run. Re-dispatch only if an error or warning bit has been + // set since; otherwise skip entirely. + if ((this->app_state_ & STATUS_LED_MASK) == 0) + return; + sl->enable_loop(); + } else if (sl_state != COMPONENT_STATE_LOOP) { + // CONSTRUCTION/SETUP/FAILED: not our job — App::setup() drives the lifecycle. + return; + } + sl->loop(); +} +#endif + bool Application::any_component_has_status_flag_(uint8_t flag) const { // Walk all components (not just looping ones) so non-looping components' // status bits are respected. Only called from the slow-path clear helpers diff --git a/esphome/core/application.h b/esphome/core/application.h index ba21ea910b..4f5889620d 100644 --- a/esphome/core/application.h +++ b/esphome/core/application.h @@ -237,7 +237,8 @@ class Application { /// this threshold triggers a real feed naturally. /// Safety margins vs. platform watchdog timeouts: /// - ESP32 task WDT default (5 s): ~16x - /// - ESP8266 soft WDT (~1.6 s): ~5x + /// - ESP8266 soft WDT (~1.6 s): ~5x <-- floor case; any future change + /// must keep comfortable margin here /// - ESP8266 HW WDT (~6 s): ~20x static constexpr uint32_t WDT_FEED_INTERVAL_MS = 300; @@ -245,14 +246,33 @@ class Application { /// timestamp in hand. Out of line to keep call sites tiny. void feed_wdt(); +#ifdef USE_STATUS_LED + /// Dispatch interval for the status LED update. Deliberately shorter than + /// WDT_FEED_INTERVAL_MS because the status LED error blink has a 250 ms + /// period (status_led.cpp:ERROR_PERIOD_MS) and a 150 ms on-window; the + /// dispatch cadence must be short enough to render that blink without + /// aliasing. Sampling every 100 ms yields an on/off observation inside + /// every error period with headroom for the 250 ms warning on-window. + static constexpr uint32_t STATUS_LED_DISPATCH_INTERVAL_MS = 100; +#endif + /// Feed the task watchdog, hot entry. Callers that already have a /// millis() timestamp pay only a load + sub + branch on the common - /// (no-op) path. The actual arch feed + status LED update live in - /// feed_wdt_slow_. + /// (no-op) path. The actual arch feed lives in feed_wdt_slow_. + /// When USE_STATUS_LED is compiled in, also gates a separate (shorter) + /// interval for dispatching status_led so the LED blink pattern stays + /// readable even though arch_feed_wdt pokes are now rate-limited at + /// 300 ms. The two rate limits are independent so raising + /// WDT_FEED_INTERVAL_MS does not distort the LED cadence. void ESPHOME_ALWAYS_INLINE feed_wdt_with_time(uint32_t time) { if (static_cast(time - this->last_wdt_feed_) > WDT_FEED_INTERVAL_MS) [[unlikely]] { this->feed_wdt_slow_(time); } +#ifdef USE_STATUS_LED + if (static_cast(time - this->last_status_led_service_) > STATUS_LED_DISPATCH_INTERVAL_MS) [[unlikely]] { + this->service_status_led_slow_(time); + } +#endif } void reboot(); @@ -415,11 +435,21 @@ class Application { /// Caller must ensure dump_config_at_ < components_.size(). void __attribute__((noinline)) process_dump_config_(); - /// Slow path for feed_wdt(): actually calls arch_feed_wdt(), updates - /// last_wdt_feed_, and re-dispatches the status LED. Out of line so the - /// inline wrapper stays tiny. + /// Slow path for feed_wdt(): actually calls arch_feed_wdt() and updates + /// last_wdt_feed_. Out of line so the inline wrapper stays tiny. Does NOT + /// touch status_led — that's gated separately via service_status_led_slow_ + /// because the two rate limits have very different safe ranges (~ seconds + /// for WDT, < 250 ms for LED blink rendering). void feed_wdt_slow_(uint32_t time); +#ifdef USE_STATUS_LED + /// Slow path for the status_led dispatch rate limit. Runs the status_led + /// component's loop() based on its state (LOOP / LOOP_DONE with status + /// bits set), and updates last_status_led_service_. Out of line to keep + /// the feed_wdt_with_time hot path a couple of load+branch sequences. + void service_status_led_slow_(uint32_t time); +#endif + /// Perform a delay while also monitoring socket file descriptors for readiness #ifdef USE_HOST // select() fallback path is too complex to inline (host platform) @@ -471,6 +501,10 @@ class Application { uint32_t last_loop_{0}; uint32_t loop_component_start_time_{0}; uint32_t last_wdt_feed_{0}; // millis() of most recent arch_feed_wdt(); rate-limits feed_wdt() hot path +#ifdef USE_STATUS_LED + // millis() of most recent status_led dispatch; rate-limits independently of last_wdt_feed_ + uint32_t last_status_led_service_{0}; +#endif #ifdef USE_HOST int max_fd_{-1}; // Highest file descriptor number for select() @@ -616,7 +650,9 @@ inline void ESPHOME_ALWAYS_INLINE __attribute__((optimize("O2"))) Application::l #ifdef USE_RUNTIME_STATS uint32_t loop_before_end_us = micros(); uint64_t loop_before_scheduled_us = ComponentRuntimeStats::global_recorded_us - loop_recorded_snap; - // Default tail_start to end-of-before so tail_us == 0 on Phase A-only ticks. + // Default tail_start to end-of-before so tail_us on Phase A-only ticks + // captures only the small gate-check + record_loop_active prefix between + // here and the loop_now_us sample below (not strictly zero, but tiny). uint32_t loop_tail_start_us = loop_before_end_us; #endif diff --git a/tests/integration/fixtures/loop_interval_default_not_pulled_forward.yaml b/tests/integration/fixtures/loop_interval_default_not_pulled_forward.yaml new file mode 100644 index 0000000000..fec83865b9 --- /dev/null +++ b/tests/integration/fixtures/loop_interval_default_not_pulled_forward.yaml @@ -0,0 +1,51 @@ +esphome: + name: loop-default-not-pulled + on_boot: + priority: -100 + then: + # Leave loop_interval_ at its default (16 ms → ~62 Hz). Do NOT call + # set_loop_interval here. The fast scheduler interval below used to + # pull the component phase forward to ~128 Hz via the old + # std::max(next_schedule, delay_time / 2) floor. + # Start measurement after 1s so boot transients settle. + - delay: 1000ms + - lambda: |- + id(loop_at_start) = id(loop_counter)->get_loop_count(); + ESP_LOGI("test", "MEASUREMENT_STARTED loop=%d", id(loop_at_start)); + # Observe for 2s. + - delay: 2000ms + - lambda: |- + int loop_delta = id(loop_counter)->get_loop_count() - id(loop_at_start); + ESP_LOGI("test", "MEASUREMENT_DONE loop_delta=%d", loop_delta); + +host: +api: +logger: + level: INFO + logs: + loop_test_component: WARN # Silence per-loop log spam + +external_components: + - source: + type: local + path: EXTERNAL_COMPONENT_PATH + +globals: + - id: loop_at_start + type: int + initial_value: "0" + +loop_test_component: + components: + - id: loop_counter + name: loop_counter + +interval: + # Fast scheduler interval (well under loop_interval_/2 = 8ms). In the + # pre-decoupling code this would have pulled the component phase forward + # to ~128 Hz. After the decoupling fix the component phase stays at + # ~62 Hz regardless. + - interval: 5ms + then: + - lambda: |- + // No-op; the presence of a due scheduler item is what matters. diff --git a/tests/integration/test_loop_interval_decoupling.py b/tests/integration/test_loop_interval_decoupling.py index 1cf8bf477d..6c34aed458 100644 --- a/tests/integration/test_loop_interval_decoupling.py +++ b/tests/integration/test_loop_interval_decoupling.py @@ -58,7 +58,9 @@ async def test_loop_interval_decoupling( # Component phase should fire ~4 times in 2s. The upper bound must be # less than 8: the pre-decoupling behavior clamped to ~250ms cadence # giving ~8 loops/2s, so allowing 8 would let the old behavior pass. - assert 2 <= loop_delta <= 6, ( + # Lower bound 3 (not 2) keeps the test honest: a >30% slowdown from + # the ~4 nominal is not normal CI jitter and should fail. + assert 3 <= loop_delta <= 6, ( f"Component loop should fire ~4 times in 2s at loop_interval=500ms, " f"got {loop_delta}" ) diff --git a/tests/integration/test_loop_interval_default_not_pulled_forward.py b/tests/integration/test_loop_interval_default_not_pulled_forward.py new file mode 100644 index 0000000000..17a7070436 --- /dev/null +++ b/tests/integration/test_loop_interval_default_not_pulled_forward.py @@ -0,0 +1,67 @@ +"""Test that a fast scheduler item does not pull the component phase forward. + +Regression test for the original ~128 Hz → ~62 Hz bug fixed by decoupling +Application::loop() component-phase cadence from scheduler wake timing. + +Setup: +- loop_interval_ left at its default (16 ms → ~62 Hz component phase). +- Scheduler interval at 5 ms (well under the old loop_interval_/2 = 8 ms floor). + +Before the decoupling fix the ``std::max(next_schedule, delay_time / 2)`` floor +clamped the sleep to ~8 ms whenever any scheduler item was due sooner than +loop_interval_/2. That pulled the component phase forward to ~128 Hz — twice +what the documented ~62 Hz default promised. After the fix the component +phase stays at ~62 Hz regardless of scheduler activity. +""" + +from __future__ import annotations + +import asyncio +import re + +import pytest + +from .types import APIClientConnectedFactory, RunCompiledFunction + + +@pytest.mark.asyncio +async def test_loop_interval_default_not_pulled_forward( + yaml_config: str, + run_compiled: RunCompiledFunction, + api_client_connected: APIClientConnectedFactory, +) -> None: + """Fast scheduler item must not pull component phase past default ~62 Hz.""" + loop = asyncio.get_running_loop() + measurement_done: asyncio.Future[int] = loop.create_future() + + def on_log_line(line: str) -> None: + match = re.search(r"MEASUREMENT_DONE loop_delta=(\d+)", line) + if match and not measurement_done.done(): + measurement_done.set_result(int(match.group(1))) + + async with ( + run_compiled(yaml_config, line_callback=on_log_line), + api_client_connected() as client, + ): + device_info = await client.device_info() + assert device_info is not None + assert device_info.name == "loop-default-not-pulled" + + try: + loop_delta = await asyncio.wait_for(measurement_done, timeout=10.0) + except TimeoutError: + pytest.fail("MEASUREMENT_DONE marker never appeared") + + # Observation window = 2s, loop_interval_ default = 16ms → ~62 Hz → + # ~125 component-phase iterations expected. + # Pre-fix behavior: the 5 ms scheduler interval tripped the old + # delay_time/2 = 8 ms floor, pulling the phase to ~128 Hz → ~256. + # Upper bound 180 is comfortably below the ~256 pre-fix rate but + # above the ~125 nominal with CI jitter. + # Lower bound 80 covers very slow CI hosts without permitting a + # complete regression. + assert 80 <= loop_delta <= 180, ( + f"Component loop at default loop_interval_ should fire ~125 times " + f"in 2s (≈62 Hz × 2s); got {loop_delta}. Values >200 indicate the " + f"scheduler is again pulling the component phase forward." + )