From 1b89174558c87841a568e89abbea351fe35fcf17 Mon Sep 17 00:00:00 2001 From: Otto Winter Date: Mon, 23 Aug 2021 20:49:19 +0200 Subject: [PATCH] Store source package in Component for debugging (#2070) --- esphome/core/application.cpp | 14 +++++------- esphome/core/component.cpp | 21 +++++++++++++++++- esphome/core/component.h | 22 +++++++++++++++++++ esphome/core/scheduler.cpp | 5 ++++- esphome/cpp_helpers.py | 33 ++++++++++++++++++++++++++++ tests/unit_tests/test_core.py | 6 ++++- tests/unit_tests/test_cpp_helpers.py | 4 ++-- 7 files changed, 91 insertions(+), 14 deletions(-) diff --git a/esphome/core/application.cpp b/esphome/core/application.cpp index 1a3158e4ce..fac17a8271 100644 --- a/esphome/core/application.cpp +++ b/esphome/core/application.cpp @@ -19,7 +19,7 @@ void Application::register_component_(Component *comp) { for (auto *c : this->components_) { if (comp == c) { - ESP_LOGW(TAG, "Component already registered! (%p)", c); + ESP_LOGW(TAG, "Component %s already registered! (%p)", c->get_component_source(), c); return; } } @@ -66,23 +66,19 @@ void Application::setup() { } void Application::loop() { uint32_t new_app_state = 0; - const uint32_t start = millis(); this->scheduler.call(); for (Component *component : this->looping_components_) { - component->call(); + { + WarnIfComponentBlockingGuard guard{component}; + component->call(); + } new_app_state |= component->get_component_state(); this->app_state_ |= new_app_state; this->feed_wdt(); } this->app_state_ = new_app_state; - const uint32_t end = millis(); - if (end - start > 200) { - ESP_LOGV(TAG, "A component took a long time in a loop() cycle (%.2f s).", (end - start) / 1e3f); - ESP_LOGV(TAG, "Components should block for at most 20-30ms in loop()."); - } - const uint32_t now = millis(); if (HighFrequencyLoopRequester::is_high_frequency()) { diff --git a/esphome/core/component.cpp b/esphome/core/component.cpp index f6b15b1977..e4535e77d9 100644 --- a/esphome/core/component.cpp +++ b/esphome/core/component.cpp @@ -92,8 +92,13 @@ void Component::call() { break; } } +const char *Component::get_component_source() const { + if (this->component_source_ == nullptr) + return ""; + return this->component_source_; +} void Component::mark_failed() { - ESP_LOGE(TAG, "Component was marked as failed."); + ESP_LOGE(TAG, "Component %s was marked as failed.", this->get_component_source()); this->component_state_ &= ~COMPONENT_STATE_MASK; this->component_state_ |= COMPONENT_STATE_FAILED; this->status_set_error(); @@ -190,4 +195,18 @@ uint32_t Nameable::get_object_id_hash() { return this->object_id_hash_; } bool Nameable::is_disabled_by_default() const { return this->disabled_by_default_; } void Nameable::set_disabled_by_default(bool disabled_by_default) { this->disabled_by_default_ = disabled_by_default; } +WarnIfComponentBlockingGuard::WarnIfComponentBlockingGuard(Component *component) { + component_ = component; + started_ = millis(); +} +WarnIfComponentBlockingGuard::~WarnIfComponentBlockingGuard() { + uint32_t now = millis(); + if (now - started_ > 50) { + const char *src = component_ == nullptr ? "" : component_->get_component_source(); + ESP_LOGV(TAG, "Component %s took a long time for an operation (%.2f s).", src, (now - started_) / 1e3f); + ESP_LOGV(TAG, "Components should block for at most 20-30ms."); + ; + } +} + } // namespace esphome diff --git a/esphome/core/component.h b/esphome/core/component.h index a4a945ef2a..b9a22c240e 100644 --- a/esphome/core/component.h +++ b/esphome/core/component.h @@ -130,6 +130,17 @@ class Component { bool has_overridden_loop() const; + /** Set where this component was loaded from for some debug messages. + * + * This is set by the ESPHome core, and should not be called manually. + */ + void set_component_source(const char *source) { component_source_ = source; } + /** Get the integration where this component was declared as a string. + * + * Returns "" if source not set + */ + const char *get_component_source() const; + protected: virtual void call_loop(); virtual void call_setup(); @@ -201,6 +212,7 @@ class Component { uint32_t component_state_{0x0000}; ///< State of this component. float setup_priority_override_{NAN}; + const char *component_source_ = nullptr; }; /** This class simplifies creating components that periodically check a state. @@ -276,4 +288,14 @@ class Nameable { bool disabled_by_default_{false}; }; +class WarnIfComponentBlockingGuard { + public: + WarnIfComponentBlockingGuard(Component *component); + ~WarnIfComponentBlockingGuard(); + + protected: + uint32_t started_; + Component *component_; +}; + } // namespace esphome diff --git a/esphome/core/scheduler.cpp b/esphome/core/scheduler.cpp index 410c68052f..60e0d4e9bd 100644 --- a/esphome/core/scheduler.cpp +++ b/esphome/core/scheduler.cpp @@ -155,7 +155,10 @@ void ICACHE_RAM_ATTR HOT Scheduler::call() { // Warning: During f(), a lot of stuff can happen, including: // - timeouts/intervals get added, potentially invalidating vector pointers // - timeouts/intervals get cancelled - item->f(); + { + WarnIfComponentBlockingGuard guard{item->component}; + item->f(); + } } { diff --git a/esphome/cpp_helpers.py b/esphome/cpp_helpers.py index 1d66eabf6c..7912e4ae06 100644 --- a/esphome/cpp_helpers.py +++ b/esphome/cpp_helpers.py @@ -1,3 +1,5 @@ +import logging + from esphome.const import ( CONF_INVERTED, CONF_MODE, @@ -15,6 +17,9 @@ from esphome.cpp_types import App, GPIOPin from esphome.util import Registry, RegistryEntry +_LOGGER = logging.getLogger(__name__) + + async def gpio_pin_expression(conf): """Generate an expression for the given pin option. @@ -42,6 +47,8 @@ async def register_component(var, config): :param var: The variable representing the component. :param config: The configuration for the component. """ + import inspect + id_ = str(var.base) if id_ not in CORE.component_ids: raise ValueError( @@ -54,6 +61,32 @@ async def register_component(var, config): add(var.set_setup_priority(config[CONF_SETUP_PRIORITY])) if CONF_UPDATE_INTERVAL in config: add(var.set_update_interval(config[CONF_UPDATE_INTERVAL])) + + # Set component source by inspecting the stack and getting the callee module + # https://stackoverflow.com/a/1095621 + name = None + try: + for frm in inspect.stack()[1:]: + mod = inspect.getmodule(frm[0]) + if mod is None: + continue + name = mod.__name__ + if name.startswith("esphome.components."): + name = name[len("esphome.components.") :] + break + if name == "esphome.automation": + name = "automation" + # continue looking further up in stack in case we find a better one + if name == "esphome.coroutine": + # Only works for async-await coroutine syntax + break + except (KeyError, AttributeError, IndexError) as e: + _LOGGER.warning( + "Error while finding name of component, please report this", exc_info=e + ) + if name is not None: + add(var.set_component_source(name)) + add(App.register_component(var)) return var diff --git a/tests/unit_tests/test_core.py b/tests/unit_tests/test_core.py index 9e4ad3d79d..37b4d6db57 100644 --- a/tests/unit_tests/test_core.py +++ b/tests/unit_tests/test_core.py @@ -473,7 +473,11 @@ class TestLibrary: ("__eq__", core.Library(name="libfoo", version="1.2.3"), True), ("__eq__", core.Library(name="libfoo", version="1.2.4"), False), ("__eq__", core.Library(name="libbar", version="1.2.3"), False), - ("__eq__", core.Library(name="libbar", version=None, repository="file:///test"), False), + ( + "__eq__", + core.Library(name="libbar", version=None, repository="file:///test"), + False, + ), ("__eq__", 1000, NotImplemented), ("__eq__", "1000", NotImplemented), ("__eq__", True, NotImplemented), diff --git a/tests/unit_tests/test_cpp_helpers.py b/tests/unit_tests/test_cpp_helpers.py index 3e317589a9..ae7a61e01f 100644 --- a/tests/unit_tests/test_cpp_helpers.py +++ b/tests/unit_tests/test_cpp_helpers.py @@ -38,7 +38,7 @@ async def test_register_component(monkeypatch): actual = await ch.register_component(var, {}) assert actual is var - add_mock.assert_called_once() + assert add_mock.call_count == 2 app_mock.register_component.assert_called_with(var) assert core_mock.component_ids == [] @@ -77,6 +77,6 @@ async def test_register_component__with_setup_priority(monkeypatch): assert actual is var add_mock.assert_called() - assert add_mock.call_count == 3 + assert add_mock.call_count == 4 app_mock.register_component.assert_called_with(var) assert core_mock.component_ids == []