From 15cb0e4ff3c3d8a7307b50a8a9fd86a9790e7d35 Mon Sep 17 00:00:00 2001
From: Otto Winter <otto@otto-winter.com>
Date: Wed, 29 May 2019 11:13:05 +0200
Subject: [PATCH] Warn if a component does long-running work in loop thread
 (#565)

* Warn if a component does long-running work in loop thread

* Update application.cpp
---
 esphome/config_validation.py |  1 +
 esphome/core/application.cpp | 36 ++++++++++++++++++++++++++++++++++++
 esphome/core/application.h   | 29 +----------------------------
 3 files changed, 38 insertions(+), 28 deletions(-)

diff --git a/esphome/config_validation.py b/esphome/config_validation.py
index 466c540c81..3fcc4d05f4 100644
--- a/esphome/config_validation.py
+++ b/esphome/config_validation.py
@@ -61,6 +61,7 @@ RESERVED_IDS = [
     'App', 'pinMode', 'delay', 'delayMicroseconds', 'digitalRead', 'digitalWrite', 'INPUT',
     'OUTPUT',
     'uint8_t', 'uint16_t', 'uint32_t', 'uint64_t', 'int8_t', 'int16_t', 'int32_t', 'int64_t',
+    'close', 'pause', 'sleep', 'open',
 ]
 
 
diff --git a/esphome/core/application.cpp b/esphome/core/application.cpp
index 98eca4ce87..6bebd3b927 100644
--- a/esphome/core/application.cpp
+++ b/esphome/core/application.cpp
@@ -66,6 +66,42 @@ void Application::dump_config() {
     component->dump_config();
   }
 }
+void Application::loop() {
+  uint32_t new_app_state = 0;
+  const uint32_t start = millis();
+  for (Component *component : this->components_) {
+    if (!component->is_failed()) {
+      component->call_loop();
+    }
+    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 (%.1f s).", (end - start) / 1e3f);
+    ESP_LOGV(TAG, "Components should block for at most 20-30ms in loop().");
+    ESP_LOGV(TAG, "This will become a warning soon.");
+  }
+
+  const uint32_t now = millis();
+
+  if (HighFrequencyLoopRequester::is_high_frequency()) {
+    yield();
+  } else {
+    uint32_t delay_time = this->loop_interval_;
+    if (now - this->last_loop_ < this->loop_interval_)
+      delay_time = this->loop_interval_ - (now - this->last_loop_);
+    delay(delay_time);
+  }
+  this->last_loop_ = now;
+
+  if (this->dump_config_scheduled_) {
+    this->dump_config();
+    this->dump_config_scheduled_ = false;
+  }
+}
 
 void ICACHE_RAM_ATTR HOT Application::feed_wdt() {
   static uint32_t LAST_FEED = 0;
diff --git a/esphome/core/application.h b/esphome/core/application.h
index 8c36da6ae4..2ee8404a9f 100644
--- a/esphome/core/application.h
+++ b/esphome/core/application.h
@@ -87,34 +87,7 @@ class Application {
   void setup();
 
   /// Make a loop iteration. Call this in your loop() function.
-  void loop() {
-    uint32_t new_app_state = 0;
-    for (Component *component : this->components_) {
-      if (!component->is_failed()) {
-        component->call_loop();
-      }
-      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 now = millis();
-    if (HighFrequencyLoopRequester::is_high_frequency()) {
-      yield();
-    } else {
-      uint32_t delay_time = this->loop_interval_;
-      if (now - this->last_loop_ < this->loop_interval_)
-        delay_time = this->loop_interval_ - (now - this->last_loop_);
-      delay(delay_time);
-    }
-    this->last_loop_ = now;
-
-    if (this->dump_config_scheduled_) {
-      this->dump_config();
-      this->dump_config_scheduled_ = false;
-    }
-  }
+  void loop();
 
   /// Get the name of this Application set by set_name().
   const std::string &get_name() const { return this->name_; }