Merge remote-tracking branch 'upstream/dev' into add_api_stats

esphome/components/api/api_connection.cpp

@@ -3,6 +3,9 @@
 #include <cerrno>
 #include <cinttypes>
 #include <utility>
+#include <algorithm>
+#include <map>
+#include <string>
 #include "esphome/components/network/util.h"
 #include "esphome/core/application.h"
 #include "esphome/core/entity_base.h"
@@ -85,6 +88,9 @@ void APIConnection::start() {
   // This ensures the first ping happens after the keepalive period
   this->next_ping_retry_ = this->last_traffic_ + KEEPALIVE_TIMEOUT_MS;
 
+  // Pass stats collection to the helper for detailed timing
+  this->helper_->set_section_stats(&this->section_stats_);
+
   APIError err = this->helper_->init();
   if (err != APIError::OK) {
     on_fatal_error();
@@ -111,6 +117,9 @@ APIConnection::~APIConnection() {
 }
 
 void APIConnection::loop() {
+  // Measure total time for entire loop function
+  const uint32_t loop_start_time = millis();
+
   if (this->remove_)
     return;
 
@@ -128,15 +137,30 @@ void APIConnection::loop() {
     return;
   }
 
+  const uint32_t now = millis();
+  uint32_t start_time;
+  uint32_t duration;
+
+  // Section: Helper Loop
+  start_time = millis();
   APIError err = this->helper_->loop();
+  duration = millis() - start_time;
+  this->section_stats_["helper_loop"].record_time(duration);
+
   if (err != APIError::OK) {
     on_fatal_error();
     ESP_LOGW(TAG, "%s: Socket operation failed: %s errno=%d", this->client_combined_info_.c_str(),
              api_error_to_str(err), errno);
     return;
   }
+
+  // Section: Read Packet
+  start_time = millis();
   ReadPacketBuffer buffer;
   err = this->helper_->read_packet(&buffer);
+  duration = millis() - start_time;
+  this->section_stats_["read_packet"].record_time(duration);
+
   if (err == APIError::WOULD_BLOCK) {
     // pass
   } else if (err != APIError::OK) {
@@ -152,28 +176,42 @@ void APIConnection::loop() {
     return;
   } else {
     this->last_traffic_ = App.get_loop_component_start_time();
-    // read a packet
+
+    // Section: Process Message
+    start_time = millis();
     if (buffer.data_len > 0) {
       this->read_message(buffer.data_len, buffer.type, &buffer.container[buffer.data_offset]);
     } else {
       this->read_message(0, buffer.type, nullptr);
     }
+    duration = millis() - start_time;
+    this->section_stats_["process_message"].record_time(duration);
+
     if (this->remove_)
       return;
   }
 
+  // Section: Process Queue
+  start_time = millis();
   if (!this->deferred_message_queue_.empty() && this->helper_->can_write_without_blocking()) {
     this->deferred_message_queue_.process_queue();
   }
+  duration = millis() - start_time;
+  this->section_stats_["process_queue"].record_time(duration);
 
+  // Section: Iterator Advance
+  start_time = millis();
   if (!this->list_entities_iterator_.completed())
     this->list_entities_iterator_.advance();
   if (!this->initial_state_iterator_.completed() && this->list_entities_iterator_.completed())
     this->initial_state_iterator_.advance();
+  duration = millis() - start_time;
+  this->section_stats_["iterator_advance"].record_time(duration);
 
+  // Section: Keepalive
+  start_time = millis();
   static uint8_t max_ping_retries = 60;
   static uint16_t ping_retry_interval = 1000;
-  const uint32_t now = App.get_loop_component_start_time();
   if (this->sent_ping_) {
     // Disconnect if not responded within 2.5*keepalive
     if (now - this->last_traffic_ > (KEEPALIVE_TIMEOUT_MS * 5) / 2) {
@@ -199,8 +237,12 @@ void APIConnection::loop() {
       }
     }
   }
+  duration = millis() - start_time;
+  this->section_stats_["keepalive"].record_time(duration);
 
 #ifdef USE_ESP32_CAMERA
+  // Section: Camera
+  start_time = millis();
   if (this->image_reader_.available() && this->helper_->can_write_without_blocking()) {
     // Message will use 8 more bytes than the minimum size, and typical
     // MTU is 1500. Sometimes users will see as low as 1460 MTU.
@@ -239,8 +281,12 @@ void APIConnection::loop() {
       this->image_reader_.return_image();
     }
   }
+  duration = millis() - start_time;
+  this->section_stats_["camera"].record_time(duration);
 #endif
 
+  // Section: State Subscriptions
+  start_time = millis();
   if (state_subs_at_ != -1) {
     const auto &subs = this->parent_->get_state_subs();
     if (state_subs_at_ >= (int) subs.size()) {
@@ -256,6 +302,24 @@ void APIConnection::loop() {
       }
     }
   }
+  duration = millis() - start_time;
+  this->section_stats_["state_subs"].record_time(duration);
+
+  // Log stats periodically
+  if (this->stats_enabled_) {
+    // If next_stats_log_ is 0, initialize it
+    if (this->next_stats_log_ == 0) {
+      this->next_stats_log_ = now + this->stats_log_interval_;
+    } else if (now >= this->next_stats_log_) {
+      this->log_section_stats_();
+      this->reset_section_stats_();
+      this->next_stats_log_ = now + this->stats_log_interval_;
+    }
+  }
+
+  // Record total loop execution time
+  const uint32_t total_loop_duration = millis() - loop_start_time;
+  this->section_stats_["total_loop"].record_time(total_loop_duration);
 }
 
 std::string get_default_unique_id(const std::string &component_type, EntityBase *entity) {
@@ -1632,8 +1696,14 @@ bool APIConnection::try_to_clear_buffer(bool log_out_of_space) {
     return false;
   if (this->helper_->can_write_without_blocking())
     return true;
+
+  // Track try_to_clear_buffer time
+  const uint32_t start_time = millis();
   delay(0);
   APIError err = this->helper_->loop();
+  const uint32_t duration = millis() - start_time;
+  this->section_stats_["try_to_clear_buffer"].record_time(duration);
+
   if (err != APIError::OK) {
     on_fatal_error();
     ESP_LOGW(TAG, "%s: Socket operation failed: %s errno=%d", this->client_combined_info_.c_str(),
@@ -1648,11 +1718,17 @@ bool APIConnection::try_to_clear_buffer(bool log_out_of_space) {
   return false;
 }
 bool APIConnection::send_buffer(ProtoWriteBuffer buffer, uint32_t message_type) {
+  // Track send_buffer time
+  const uint32_t start_time = millis();
+
   if (!this->try_to_clear_buffer(message_type != 29)) {  // SubscribeLogsResponse
     return false;
   }
 
+  uint32_t write_start = millis();
   APIError err = this->helper_->write_protobuf_packet(message_type, buffer);
+  uint32_t write_duration = millis() - write_start;
+  this->section_stats_["write_packet"].record_time(write_duration);
   if (err == APIError::WOULD_BLOCK)
     return false;
   if (err != APIError::OK) {
@@ -1665,6 +1741,11 @@ bool APIConnection::send_buffer(ProtoWriteBuffer buffer, uint32_t message_type)
     }
     return false;
   }
+
+  // Measure total send_buffer function time
+  uint32_t total_duration = millis() - start_time;
+  this->section_stats_["send_buffer_total"].record_time(total_duration);
+
   // Do not set last_traffic_ on send
   return true;
 }
@@ -1681,6 +1762,90 @@ void APIConnection::on_fatal_error() {
   this->remove_ = true;
 }
 
+void APIConnection::log_section_stats_() {
+  const char *STATS_TAG = "api.stats";
+  ESP_LOGI(STATS_TAG, "Logging API section stats now (current time: %" PRIu32 ", scheduled time: %" PRIu32 ")",
+           millis(), this->next_stats_log_);
+  ESP_LOGI(STATS_TAG, "Stats collection status: enabled=%d, sections=%zu", this->stats_enabled_,
+           this->section_stats_.size());
+
+  // Check if we have minimal data
+  bool has_data = false;
+  for (const auto &it : this->section_stats_) {
+    if (it.second.get_period_count() > 0) {
+      has_data = true;
+      break;
+    }
+  }
+
+  if (has_data) {
+    size_t helper_count = 0;
+    size_t read_count = 0;
+    size_t total_count = 0;
+    if (this->section_stats_.count("helper_loop") > 0)
+      helper_count = this->section_stats_["helper_loop"].get_period_count();
+    if (this->section_stats_.count("read_packet") > 0)
+      read_count = this->section_stats_["read_packet"].get_period_count();
+    if (this->section_stats_.count("total_loop") > 0)
+      total_count = this->section_stats_["total_loop"].get_period_count();
+
+    ESP_LOGI(STATS_TAG, "Record count for key sections: helper_loop=%zu, read_packet=%zu, total_loop=%zu", helper_count,
+             read_count, total_count);
+  }
+
+  ESP_LOGI(STATS_TAG, "API Connection Section Runtime Statistics");
+  ESP_LOGI(STATS_TAG, "Period stats (last %" PRIu32 "ms):", this->stats_log_interval_);
+
+  // First collect stats we want to display
+  std::vector<std::pair<std::string, const APISectionStats *>> stats_to_display;
+
+  for (const auto &it : this->section_stats_) {
+    const APISectionStats &stats = it.second;
+    if (stats.get_period_count() > 0) {
+      stats_to_display.push_back({it.first, &stats});
+    }
+  }
+
+  // Sort by period runtime (descending)
+  std::sort(stats_to_display.begin(), stats_to_display.end(), [](const auto &a, const auto &b) {
+    return a.second->get_period_time_ms() > b.second->get_period_time_ms();
+  });
+
+  // Log top components by period runtime
+  for (const auto &it : stats_to_display) {
+    const std::string &section = it.first;
+    const APISectionStats *stats = it.second;
+
+    ESP_LOGI(STATS_TAG, "  %s: count=%" PRIu32 ", avg=%.2fms, max=%" PRIu32 "ms, total=%" PRIu32 "ms", section.c_str(),
+             stats->get_period_count(), stats->get_period_avg_time_ms(), stats->get_period_max_time_ms(),
+             stats->get_period_time_ms());
+  }
+
+  // Log total stats since boot
+  ESP_LOGI(STATS_TAG, "Total stats (since boot):");
+
+  // Re-sort by total runtime for all-time stats
+  std::sort(stats_to_display.begin(), stats_to_display.end(),
+            [](const auto &a, const auto &b) { return a.second->get_total_time_ms() > b.second->get_total_time_ms(); });
+
+  for (const auto &it : stats_to_display) {
+    const std::string &section = it.first;
+    const APISectionStats *stats = it.second;
+
+    ESP_LOGI(STATS_TAG, "  %s: count=%" PRIu32 ", avg=%.2fms, max=%" PRIu32 "ms, total=%" PRIu32 "ms", section.c_str(),
+             stats->get_total_count(), stats->get_total_avg_time_ms(), stats->get_total_max_time_ms(),
+             stats->get_total_time_ms());
+  }
+
+  ESP_LOGD(STATS_TAG, "Resetting API section stats, sections count: %zu", this->section_stats_.size());
+}
+
+void APIConnection::reset_section_stats_() {
+  for (auto &it : this->section_stats_) {
+    it.second.reset_period_stats();
+  }
+}
+
 }  // namespace api
 }  // namespace esphome
 #endif

esphome/components/api/api_connection.h

@@ -9,8 +9,12 @@
 #include "esphome/core/application.h"
 #include "esphome/core/component.h"
 #include "esphome/core/entity_base.h"
+#include "esphome/core/helpers.h"
+#include "esphome/core/log.h"
 
 #include <vector>
+#include <map>
+#include <string>
 
 namespace esphome {
 namespace api {
@@ -64,6 +68,9 @@ class APIConnection : public APIServerConnection {
   APIConnection(std::unique_ptr<socket::Socket> socket, APIServer *parent);
   virtual ~APIConnection();
 
+  // Use the APISectionStats from api_frame_helper.h to avoid duplication
+  using APISectionStats = ::esphome::api::APISectionStats;
+
   void start();
   void loop();
 
@@ -556,6 +563,14 @@ class APIConnection : public APIServerConnection {
   InitialStateIterator initial_state_iterator_;
   ListEntitiesIterator list_entities_iterator_;
   int state_subs_at_ = -1;
+
+  // API loop section performance statistics
+  std::map<std::string, APISectionStats> section_stats_;
+  uint32_t stats_log_interval_{60000};  // 60 seconds default
+  uint32_t next_stats_log_{0};
+  bool stats_enabled_{true};
+  void log_section_stats_();
+  void reset_section_stats_();
 };
 
 }  // namespace api

esphome/components/api/api_frame_helper.cpp

@@ -111,7 +111,12 @@ APIError APIFrameHelper::write_raw_(const struct iovec *iov, int iovcnt) {
   }
 
   // Try to send directly if no buffered data
+  uint32_t write_start = millis();
   ssize_t sent = this->socket_->writev(iov, iovcnt);
+  uint32_t write_duration = millis() - write_start;
+  if (write_duration > 0 && section_stats_) {
+    (*section_stats_)["write_packet.socket_writev"].record_time(write_duration);
+  }
 
   if (sent == -1) {
     if (errno == EWOULDBLOCK || errno == EAGAIN) {
@@ -160,7 +165,12 @@ APIError APIFrameHelper::try_send_tx_buf_() {
     SendBuffer &front_buffer = this->tx_buf_.front();
 
     // Try to send the remaining data in this buffer
+    uint32_t write_start = millis();
     ssize_t sent = this->socket_->write(front_buffer.current_data(), front_buffer.remaining());
+    uint32_t write_duration = millis() - write_start;
+    if (write_duration > 0 && section_stats_) {
+      (*section_stats_)["send_buffer_total.socket_write"].record_time(write_duration);
+    }
 
     if (sent == -1) {
       if (errno != EWOULDBLOCK && errno != EAGAIN) {
@@ -311,7 +321,12 @@ APIError APINoiseFrameHelper::try_read_frame_(ParsedFrame *frame) {
   if (rx_header_buf_len_ < 3) {
     // no header information yet
     uint8_t to_read = 3 - rx_header_buf_len_;
+    uint32_t socket_start = millis();
     ssize_t received = this->socket_->read(&rx_header_buf_[rx_header_buf_len_], to_read);
+    uint32_t socket_duration = millis() - socket_start;
+    if (socket_duration > 0 && section_stats_) {
+      (*section_stats_)["read_packet.socket_read_header"].record_time(socket_duration);
+    }
     if (received == -1) {
       if (errno == EWOULDBLOCK || errno == EAGAIN) {
         return APIError::WOULD_BLOCK;
@@ -352,13 +367,23 @@ APIError APINoiseFrameHelper::try_read_frame_(ParsedFrame *frame) {
 
   // reserve space for body
   if (rx_buf_.size() != msg_size) {
+    uint32_t resize_start = millis();
     rx_buf_.resize(msg_size);
+    uint32_t resize_duration = millis() - resize_start;
+    if (resize_duration > 0 && section_stats_) {
+      (*section_stats_)["read_packet.buffer_resize"].record_time(resize_duration);
+    }
   }
 
   if (rx_buf_len_ < msg_size) {
     // more data to read
     uint16_t to_read = msg_size - rx_buf_len_;
+    uint32_t socket_start = millis();
     ssize_t received = this->socket_->read(&rx_buf_[rx_buf_len_], to_read);
+    uint32_t socket_duration = millis() - socket_start;
+    if (socket_duration > 0 && section_stats_) {
+      (*section_stats_)["read_packet.socket_read_body"].record_time(socket_duration);
+    }
     if (received == -1) {
       if (errno == EWOULDBLOCK || errno == EAGAIN) {
         return APIError::WOULD_BLOCK;
@@ -554,7 +579,15 @@ void APINoiseFrameHelper::send_explicit_handshake_reject_(const std::string &rea
 APIError APINoiseFrameHelper::read_packet(ReadPacketBuffer *buffer) {
   int err;
   APIError aerr;
+  uint32_t start_time, duration;
+
+  // Track state_action timing
+  start_time = millis();
   aerr = state_action_();
+  duration = millis() - start_time;
+  if (duration > 0 && section_stats_) {
+    (*section_stats_)["read_packet.state_action"].record_time(duration);
+  }
   if (aerr != APIError::OK) {
     return aerr;
   }
@@ -563,15 +596,27 @@ APIError APINoiseFrameHelper::read_packet(ReadPacketBuffer *buffer) {
     return APIError::WOULD_BLOCK;
   }
 
+  // Track frame reading timing
+  start_time = millis();
   ParsedFrame frame;
   aerr = try_read_frame_(&frame);
+  duration = millis() - start_time;
+  if (duration > 0 && section_stats_) {
+    (*section_stats_)["read_packet.try_read_frame"].record_time(duration);
+  }
   if (aerr != APIError::OK)
     return aerr;
 
+  // Track decryption timing
+  start_time = millis();
   NoiseBuffer mbuf;
   noise_buffer_init(mbuf);
   noise_buffer_set_inout(mbuf, frame.msg.data(), frame.msg.size(), frame.msg.size());
   err = noise_cipherstate_decrypt(recv_cipher_, &mbuf);
+  duration = millis() - start_time;
+  if (duration > 0 && section_stats_) {
+    (*section_stats_)["read_packet.decrypt"].record_time(duration);
+  }
   if (err != 0) {
     state_ = State::FAILED;
     HELPER_LOG("noise_cipherstate_decrypt failed: %s", noise_err_to_str(err).c_str());
@@ -836,7 +881,12 @@ APIError APIPlaintextFrameHelper::try_read_frame_(ParsedFrame *frame) {
     // there is no data on the wire (which is the common case).
     // This results in faster failure detection compared to
     // attempting to read multiple bytes at once.
+    uint32_t socket_start = millis();
     ssize_t received = this->socket_->read(&data, 1);
+    uint32_t socket_duration = millis() - socket_start;
+    if (socket_duration > 0 && section_stats_) {
+      (*section_stats_)["read_packet.socket_read_header"].record_time(socket_duration);
+    }
     if (received == -1) {
       if (errno == EWOULDBLOCK || errno == EAGAIN) {
         return APIError::WOULD_BLOCK;
@@ -926,13 +976,23 @@ APIError APIPlaintextFrameHelper::try_read_frame_(ParsedFrame *frame) {
 
   // reserve space for body
   if (rx_buf_.size() != rx_header_parsed_len_) {
+    uint32_t resize_start = millis();
     rx_buf_.resize(rx_header_parsed_len_);
+    uint32_t resize_duration = millis() - resize_start;
+    if (resize_duration > 0 && section_stats_) {
+      (*section_stats_)["read_packet.buffer_resize"].record_time(resize_duration);
+    }
   }
 
   if (rx_buf_len_ < rx_header_parsed_len_) {
     // more data to read
     uint16_t to_read = rx_header_parsed_len_ - rx_buf_len_;
+    uint32_t socket_start = millis();
     ssize_t received = this->socket_->read(&rx_buf_[rx_buf_len_], to_read);
+    uint32_t socket_duration = millis() - socket_start;
+    if (socket_duration > 0 && section_stats_) {
+      (*section_stats_)["read_packet.socket_read_body"].record_time(socket_duration);
+    }
     if (received == -1) {
       if (errno == EWOULDBLOCK || errno == EAGAIN) {
         return APIError::WOULD_BLOCK;
@@ -966,13 +1026,20 @@ APIError APIPlaintextFrameHelper::try_read_frame_(ParsedFrame *frame) {
 }
 APIError APIPlaintextFrameHelper::read_packet(ReadPacketBuffer *buffer) {
   APIError aerr;
+  uint32_t start_time, duration;
 
   if (state_ != State::DATA) {
     return APIError::WOULD_BLOCK;
   }
 
+  // Track frame reading timing
+  start_time = millis();
   ParsedFrame frame;
   aerr = try_read_frame_(&frame);
+  duration = millis() - start_time;
+  if (duration > 0 && section_stats_) {
+    (*section_stats_)["read_packet.try_read_frame"].record_time(duration);
+  }
   if (aerr != APIError::OK) {
     if (aerr == APIError::BAD_INDICATOR) {
       // Make sure to tell the remote that we don't

esphome/components/api/api_frame_helper.h

@@ -13,10 +13,71 @@
 
 #include "api_noise_context.h"
 #include "esphome/components/socket/socket.h"
+#include <map>
+#include <string>
 
 namespace esphome {
 namespace api {
 
+// Forward declaration from api_connection.h
+class APIConnection;
+
+// Stats class definition (copied from api_connection.h to avoid circular dependency)
+class APISectionStats {
+ public:
+  APISectionStats()
+      : period_count_(0),
+        total_count_(0),
+        period_time_ms_(0),
+        total_time_ms_(0),
+        period_max_time_ms_(0),
+        total_max_time_ms_(0) {}
+
+  void record_time(uint32_t duration_ms) {
+    // Update period counters
+    this->period_count_++;
+    this->period_time_ms_ += duration_ms;
+    if (duration_ms > this->period_max_time_ms_)
+      this->period_max_time_ms_ = duration_ms;
+
+    // Update total counters
+    this->total_count_++;
+    this->total_time_ms_ += duration_ms;
+    if (duration_ms > this->total_max_time_ms_)
+      this->total_max_time_ms_ = duration_ms;
+  }
+
+  void reset_period_stats() {
+    this->period_count_ = 0;
+    this->period_time_ms_ = 0;
+    this->period_max_time_ms_ = 0;
+  }
+
+  // Getters for period stats
+  uint32_t get_period_count() const { return this->period_count_; }
+  uint32_t get_period_time_ms() const { return this->period_time_ms_; }
+  uint32_t get_period_max_time_ms() const { return this->period_max_time_ms_; }
+  float get_period_avg_time_ms() const {
+    return this->period_count_ > 0 ? static_cast<float>(this->period_time_ms_) / this->period_count_ : 0.0f;
+  }
+
+  // Getters for total stats
+  uint32_t get_total_count() const { return this->total_count_; }
+  uint32_t get_total_time_ms() const { return this->total_time_ms_; }
+  uint32_t get_total_max_time_ms() const { return this->total_max_time_ms_; }
+  float get_total_avg_time_ms() const {
+    return this->total_count_ > 0 ? static_cast<float>(this->total_time_ms_) / this->total_count_ : 0.0f;
+  }
+
+ private:
+  uint32_t period_count_;
+  uint32_t total_count_;
+  uint32_t period_time_ms_;
+  uint32_t total_time_ms_;
+  uint32_t period_max_time_ms_;
+  uint32_t total_max_time_ms_;
+};
+
 class ProtoWriteBuffer;
 
 struct ReadPacketBuffer {
@@ -85,6 +146,8 @@ class APIFrameHelper {
   }
   // Give this helper a name for logging
   void set_log_info(std::string info) { info_ = std::move(info); }
+  // Set stats collection for detailed timing
+  void set_section_stats(std::map<std::string, APISectionStats> *stats) { section_stats_ = stats; }
   virtual APIError write_protobuf_packet(uint16_t type, ProtoWriteBuffer buffer) = 0;
   // Get the frame header padding required by this protocol
   virtual uint8_t frame_header_padding() = 0;
@@ -160,6 +223,9 @@ class APIFrameHelper {
 
   // Common initialization for both plaintext and noise protocols
   APIError init_common_();
+
+  // Stats collection pointer - shared from APIConnection
+  std::map<std::string, APISectionStats> *section_stats_{nullptr};
 };
 
 #ifdef USE_API_NOISE