Store source package in Component for debugging (#2070)

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()) {

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 "<unknown>";
+  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 ? "<null>" : 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

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

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();
+      }
     }
 
     {

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
 

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),

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 == []