From 5b728f19c3074f4413f01727ecdd60c42cf38578 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Tue, 2 Jun 2026 13:29:27 -0500 Subject: [PATCH] [core] Attribute "took a long time" blocking warning to its source A blocking operation that runs inside a deferred scheduler continuation (e.g. after a delay in a script/automation) was reported as: took a long time for an operation (83 ms), max is 30 ms Two problems: * The DelayAction continuation carries no component (since #16129 dropped Component inheritance), so the warning had nothing to name and printed "". Telling the user an anonymous delay action is blocking is not useful; naming the component that hosts the automation is. * The threshold was hardcoded to "30 ms" but the real default is 50 ms (WARN_IF_BLOCKING_OVER_CS) and is adaptive per component. DelayAction now records App.get_current_component() on the scheduler item, so the warning names the component whose automation chain hit the delay (falling back to "a scheduled task" when there is genuinely no current component). This propagates across chained delays because the scheduler restores the item's component as the current component before each callback. For SELF_POINTER items the stored component is log-attribution only: the key (the caller's `this`) is globally unique, so matches_item_locked_ ignores the component when matching and the is_failed() skip is bypassed. This keeps delay cancellation (restart/parallel/stop) and always-fire semantics unchanged. The warning now reports the real (pre-ratchet) threshold instead of the stale "30 ms". Adds an integration test reproducing the deferred-block path via an interval + delay + busy lambda and asserting the warning names a component and reports "max is 50 ms". --- esphome/core/base_automation.h | 11 +++- esphome/core/component.cpp | 24 +++---- esphome/core/component.h | 2 +- esphome/core/scheduler.cpp | 6 +- esphome/core/scheduler.h | 14 +++-- .../fixtures/scheduler_blocking_warning.yaml | 21 +++++++ .../test_scheduler_blocking_warning.py | 62 +++++++++++++++++++ 7 files changed, 120 insertions(+), 20 deletions(-) create mode 100644 tests/integration/fixtures/scheduler_blocking_warning.yaml create mode 100644 tests/integration/test_scheduler_blocking_warning.py diff --git a/esphome/core/base_automation.h b/esphome/core/base_automation.h index dcad7c9d2e..547b5b5938 100644 --- a/esphome/core/base_automation.h +++ b/esphome/core/base_automation.h @@ -198,7 +198,12 @@ template class DelayAction : public Action { // to avoid overhead from capturing arguments by value if constexpr (sizeof...(Ts) == 0) { App.scheduler.set_timer_common_( - /* component= */ nullptr, Scheduler::SchedulerItem::TIMEOUT, Scheduler::NameType::SELF_POINTER, + // The component is stored for blocking-warning log attribution only (SELF_POINTER items + // match by `this`, so it does not affect cancellation). Capturing the current component + // lets the warning name the source instead of ""; it propagates across chained + // delays because the scheduler restores it as the current component before each callback. + /* component= */ App.get_current_component(), Scheduler::SchedulerItem::TIMEOUT, + Scheduler::NameType::SELF_POINTER, /* static_name= */ reinterpret_cast(this), /* hash_or_id= */ 0, this->delay_.value(), [this]() { this->play_next_(); }, /* is_retry= */ false, /* skip_cancel= */ this->num_running_ > 1); @@ -209,7 +214,9 @@ template class DelayAction : public Action { // are passed as non-const lvalues to play_next_(const Ts&...) where Ts may be `T&` auto f = [this, x...]() mutable { this->play_next_(x...); }; App.scheduler.set_timer_common_( - /* component= */ nullptr, Scheduler::SchedulerItem::TIMEOUT, Scheduler::NameType::SELF_POINTER, + // See the no-argument branch above: component is captured for log attribution only. + /* component= */ App.get_current_component(), Scheduler::SchedulerItem::TIMEOUT, + Scheduler::NameType::SELF_POINTER, /* static_name= */ reinterpret_cast(this), /* hash_or_id= */ 0, this->delay_.value(x...), std::move(f), /* is_retry= */ false, /* skip_cancel= */ this->num_running_ > 1); diff --git a/esphome/core/component.cpp b/esphome/core/component.cpp index 2d80301897..7d4137554c 100644 --- a/esphome/core/component.cpp +++ b/esphome/core/component.cpp @@ -258,9 +258,11 @@ void Component::call() { break; } } -bool Component::should_warn_of_blocking(uint32_t blocking_time) { +bool Component::should_warn_of_blocking(uint32_t blocking_time, uint32_t &threshold_ms_out) { // Convert centisecond threshold to milliseconds for comparison uint32_t threshold_ms = static_cast(this->warn_if_blocking_over_) * 10U; + // Report the threshold that was exceeded (before any ratcheting below) so the warning is accurate. + threshold_ms_out = threshold_ms; if (blocking_time > threshold_ms) { // Set new threshold: blocking_time + increment, converted back to centiseconds uint32_t new_threshold_ms = blocking_time + WARN_IF_BLOCKING_INCREMENT_MS; @@ -493,17 +495,17 @@ uint64_t ComponentRuntimeStats::global_recorded_us = 0; // NOLINT(cppcoreguidel void __attribute__((noinline, cold)) WarnIfComponentBlockingGuard::warn_blocking(Component *component, uint32_t blocking_time) { - bool should_warn; - if (component != nullptr) { - should_warn = component->should_warn_of_blocking(blocking_time); - } else { - should_warn = true; // Already checked > WARN_IF_BLOCKING_OVER_MS in caller - } - if (should_warn) { - ESP_LOGW(TAG, "%s took a long time for an operation (%" PRIu32 " ms), max is 30 ms", - component == nullptr ? LOG_STR_LITERAL("") : LOG_STR_ARG(component->get_component_log_str()), - blocking_time); + // Default threshold for the null path (no component to consult); the caller already checked + // blocking_time > WARN_IF_BLOCKING_OVER_MS, so always warn in that case. + uint32_t threshold_ms = WARN_IF_BLOCKING_OVER_MS; + if (component != nullptr && !component->should_warn_of_blocking(blocking_time, threshold_ms)) { + return; // Component's (possibly ratcheted) threshold not exceeded yet } + // A null component means the work ran in a scheduler continuation with no associated component + // (e.g. a delay inside a script/automation), so report it as a scheduled task rather than "". + ESP_LOGW(TAG, "%s took a long time for an operation (%" PRIu32 " ms), max is %" PRIu32 " ms", + component == nullptr ? LOG_STR_LITERAL("a scheduled task") : LOG_STR_ARG(component->get_component_log_str()), + blocking_time, threshold_ms); } #ifdef USE_SETUP_PRIORITY_OVERRIDE diff --git a/esphome/core/component.h b/esphome/core/component.h index ff10f1a8f1..c7e24455bf 100644 --- a/esphome/core/component.h +++ b/esphome/core/component.h @@ -326,7 +326,7 @@ class Component { return component_source_lookup(this->component_source_index_); } - bool should_warn_of_blocking(uint32_t blocking_time); + bool should_warn_of_blocking(uint32_t blocking_time, uint32_t &threshold_ms_out); protected: friend class Application; diff --git a/esphome/core/scheduler.cpp b/esphome/core/scheduler.cpp index a7c624486d..d4dfc7a372 100644 --- a/esphome/core/scheduler.cpp +++ b/esphome/core/scheduler.cpp @@ -642,8 +642,10 @@ uint32_t HOT Scheduler::call(uint32_t now) { // Not reached timeout yet, done for this call break; } - // Don't run on failed components - if (item->component != nullptr && item->component->is_failed()) { + // Don't run on failed components. + // SELF_POINTER items (e.g. DelayAction) store the component for log attribution only and + // must always fire regardless of that component's failed state, so skip the check for them. + if (item->component != nullptr && item->get_name_type() != NameType::SELF_POINTER && item->component->is_failed()) { LockGuard guard{this->lock_}; this->recycle_item_main_loop_(this->pop_raw_locked_()); continue; diff --git a/esphome/core/scheduler.h b/esphome/core/scheduler.h index b640aa86fe..31bb36830f 100644 --- a/esphome/core/scheduler.h +++ b/esphome/core/scheduler.h @@ -402,7 +402,7 @@ class Scheduler { // Fixes: https://github.com/esphome/esphome/issues/11940 if (item == nullptr) return false; - if (item->component != component || item->type != type || (skip_removed && this->is_item_removed_locked_(item)) || + if (item->type != type || (skip_removed && this->is_item_removed_locked_(item)) || (match_retry && !item->is_retry)) { return false; } @@ -411,12 +411,18 @@ class Scheduler { return false; // STATIC_STRING: compare string content. SELF_POINTER: raw pointer equality (no strcmp). // Other types: compare hash/ID value. + if (name_type == NameType::SELF_POINTER) { + // SELF_POINTER keys are globally unique (the caller's `this`), so the stored component is + // log-attribution only (e.g. DelayAction records the current component for blocking + // warnings) and must NOT participate in matching. Match by pointer equality alone. + return item->name_.static_name == static_name; + } + // All other name types must also match on component identity. + if (item->component != component) + return false; if (name_type == NameType::STATIC_STRING) { return this->names_match_static_(item->get_name(), static_name); } - if (name_type == NameType::SELF_POINTER) { - return item->name_.static_name == static_name; - } return item->get_name_hash_or_id() == hash_or_id; } diff --git a/tests/integration/fixtures/scheduler_blocking_warning.yaml b/tests/integration/fixtures/scheduler_blocking_warning.yaml new file mode 100644 index 0000000000..baa367a691 --- /dev/null +++ b/tests/integration/fixtures/scheduler_blocking_warning.yaml @@ -0,0 +1,21 @@ +esphome: + name: scheduler-blocking-warning + +host: +api: +logger: + level: DEBUG + +# An interval fires via the scheduler (so the current component is the interval), +# defers through a delay, then busy-blocks well over the 50 ms warn threshold inside +# the deferred continuation. The blocking warning must be attributed to the interval +# component (captured at schedule time) instead of "". +interval: + - interval: 500ms + then: + - delay: 10ms + - lambda: |- + const uint32_t start = millis(); + // Spin for longer than WARN_IF_BLOCKING_OVER_MS (50 ms) to trip the warning. + while (millis() - start < 80) { + } diff --git a/tests/integration/test_scheduler_blocking_warning.py b/tests/integration/test_scheduler_blocking_warning.py new file mode 100644 index 0000000000..d4137e5065 --- /dev/null +++ b/tests/integration/test_scheduler_blocking_warning.py @@ -0,0 +1,62 @@ +"""Integration test for blocking-warning source attribution. + +A blocking operation that runs inside a deferred scheduler continuation (e.g. after +a ``delay`` in a script/automation) used to be reported as +`` took a long time for an operation (NN ms), max is 30 ms`` because the +continuation carries no component. The warning should instead name the component that +was current when the delay was scheduled and report the real threshold (50 ms). +""" + +from __future__ import annotations + +import asyncio +import re + +import pytest + +from .types import APIClientConnectedFactory, RunCompiledFunction + +# Matches: " took a long time for an operation (NN ms), max is NN ms" +WARN_PATTERN = re.compile( + r"took a long time for an operation \((\d+) ms\), max is (\d+) ms" +) + + +@pytest.mark.asyncio +async def test_scheduler_blocking_warning( + yaml_config: str, + run_compiled: RunCompiledFunction, + api_client_connected: APIClientConnectedFactory, +) -> None: + """Deferred blocking work is attributed to a real component, not "".""" + loop = asyncio.get_running_loop() + warning_future: asyncio.Future[str] = loop.create_future() + + def check_output(line: str) -> None: + if WARN_PATTERN.search(line) and not warning_future.done(): + warning_future.set_result(line) + + async with ( + run_compiled(yaml_config, line_callback=check_output), + api_client_connected() as client, + ): + device_info = await client.device_info() + assert device_info is not None + + # The interval fires, defers via delay, then busy-blocks > 50 ms in the + # continuation, which should trip the blocking warning. + warning_line = await asyncio.wait_for(warning_future, timeout=10.0) + + # The deferred block must be attributed to a real component, not "". + assert "" not in warning_line, ( + f"Warning should name a component, got: {warning_line}" + ) + # The delay was scheduled from a known component (the interval), so the warning + # must name it rather than falling back to the generic scheduled-task label. + assert "a scheduled task" not in warning_line, ( + f"Warning should name the interval component, got: {warning_line}" + ) + # The reported threshold must be the real default (50 ms), not the stale "30 ms". + match = WARN_PATTERN.search(warning_line) + assert match is not None + assert match.group(2) == "50", f"Expected 'max is 50 ms', got: {warning_line}"