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." + )