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}"