From 7d12b984a815614bc24dfab698fe69b9e29d87f8 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Sat, 18 Apr 2026 17:32:29 -0500 Subject: [PATCH] [core] address review polish on main-loop decoupling MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Doc and test updates from a code review of this PR: - Correct the `tail_us == 0 on Phase A-only ticks` claim in the Application::loop() comment and the RuntimeStatsCollector::record_loop_active docstring. `loop_tail_start_us` is set to `loop_before_end_us`, and `loop_now_us` is sampled later, so `tail_us` on Phase A-only ticks is the small gate-check + record prefix — tiny but non-zero. (Also flagged by Copilot on application.h:623 and runtime_stats.h:45.) - Call out ESP8266 as the floor case in the WDT_FEED_INTERVAL_MS margin table. Its soft WDT (~1.6 s) is the tightest margin at ~5x, so future changes to the constant need to preserve comfortable headroom there. - Tighten the test lower bound at tests/integration/test_loop_interval_decoupling.py from `2 <= loop_delta <= 6` to `3 <= loop_delta <= 6`. Allowing 2 would let a >50% slowdown from the 4-in-2s nominal pass as CI jitter, which undermines the regression signal. 3 keeps the test honest while still absorbing realistic CI jitter. - Add a second integration test (test_loop_interval_default_not_pulled_forward) that covers the inverse direction: at the default loop_interval_ with a fast scheduler item (5 ms — well under the old delay_time/2 = 8 ms floor), the component phase must still run at ~62 Hz, not the pre-fix ~128 Hz. This locks down the original 128 Hz → 62 Hz regression that motivated the PR. --- .../components/runtime_stats/runtime_stats.h | 4 +- ...p_interval_default_not_pulled_forward.yaml | 51 ++++++++++++++ .../test_loop_interval_decoupling.py | 4 +- ...oop_interval_default_not_pulled_forward.py | 67 +++++++++++++++++++ 4 files changed, 124 insertions(+), 2 deletions(-) create mode 100644 tests/integration/fixtures/loop_interval_default_not_pulled_forward.yaml create mode 100644 tests/integration/test_loop_interval_default_not_pulled_forward.py 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/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." + )