mirror of
https://github.com/esphome/esphome.git
synced 2026-09-04 03:56:04 +00:00
[core] address review polish on main-loop decoupling
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.
This commit is contained in:
@@ -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,
|
||||
|
||||
@@ -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.
|
||||
@@ -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}"
|
||||
)
|
||||
|
||||
@@ -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."
|
||||
)
|
||||
Reference in New Issue
Block a user