diff --git a/esphome/components/api/api_connection.cpp b/esphome/components/api/api_connection.cpp index 4b3a3e2fc8..61178dee5a 100644 --- a/esphome/components/api/api_connection.cpp +++ b/esphome/components/api/api_connection.cpp @@ -11,6 +11,7 @@ #include #include #include +#include "api_timing.h" #include "esphome/components/network/util.h" #include "esphome/core/application.h" #include "esphome/core/entity_base.h" @@ -140,7 +141,9 @@ void APIConnection::loop() { return; } + API_TIMING_START(helper); APIError err = this->helper_->loop(); + API_TIMING_END(helper, HELPER_LOOP); if (err != APIError::OK) { on_fatal_error(); this->log_socket_operation_failed_(err); @@ -149,11 +152,16 @@ void APIConnection::loop() { const uint32_t now = App.get_loop_component_start_time(); // Check if socket has data ready before attempting to read - if (this->helper_->is_socket_ready()) { + API_TIMING_START(socket_check); + bool socket_ready = this->helper_->is_socket_ready(); + API_TIMING_END(socket_check, SOCKET_CHECK); + if (socket_ready) { // Read up to MAX_MESSAGES_PER_LOOP messages per loop to improve throughput for (uint8_t message_count = 0; message_count < MAX_MESSAGES_PER_LOOP; message_count++) { ReadPacketBuffer buffer; + API_TIMING_START(read); err = this->helper_->read_packet(&buffer); + API_TIMING_END(read, READ_PACKET); if (err == APIError::WOULD_BLOCK) { // No more data available break; @@ -164,11 +172,13 @@ void APIConnection::loop() { } else { this->last_traffic_ = now; // read a packet + API_TIMING_START(process); 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); } + API_TIMING_END(process, PROCESS_MESSAGE); if (this->flags_.remove) return; } @@ -177,19 +187,27 @@ void APIConnection::loop() { // Process deferred batch if scheduled and timer has expired if (this->flags_.batch_scheduled && now - this->deferred_batch_.batch_start_time >= this->get_batch_delay_ms_()) { + API_TIMING_START(deferred); this->process_batch_(); + API_TIMING_END(deferred, DEFERRED_BATCH); } if (!this->list_entities_iterator_.completed()) { + API_TIMING_START(iterator1); this->process_iterator_batch_(this->list_entities_iterator_); + API_TIMING_END(iterator1, ITERATOR_BATCH); } else if (!this->initial_state_iterator_.completed()) { + API_TIMING_START(iterator2); this->process_iterator_batch_(this->initial_state_iterator_); + API_TIMING_END(iterator2, ITERATOR_BATCH); // If we've completed initial states, process any remaining and clear the flag if (this->initial_state_iterator_.completed()) { // Process any remaining batched messages immediately if (!this->deferred_batch_.empty()) { + API_TIMING_START(deferred2); this->process_batch_(); + API_TIMING_END(deferred2, DEFERRED_BATCH); } // Now that everything is sent, enable immediate sending for future state changes this->flags_.should_try_send_immediately = true; @@ -203,6 +221,7 @@ void APIConnection::loop() { ESP_LOGW(TAG, "%s is unresponsive; disconnecting", this->get_client_combined_info().c_str()); } } else if (now - this->last_traffic_ > KEEPALIVE_TIMEOUT_MS && !this->flags_.remove) { + API_TIMING_GUARD(KEEPALIVE); // Only send ping if we're not disconnecting ESP_LOGVV(TAG, "Sending keepalive PING"); PingRequest req; @@ -219,6 +238,7 @@ void APIConnection::loop() { #ifdef USE_CAMERA if (this->image_reader_ && this->image_reader_->available() && this->helper_->can_write_without_blocking()) { + API_TIMING_GUARD(CAMERA_IMAGE); uint32_t to_send = std::min((size_t) MAX_BATCH_PACKET_SIZE, this->image_reader_->available()); bool done = this->image_reader_->available() == to_send; @@ -273,9 +293,11 @@ uint16_t APIConnection::encode_message_to_buffer(ProtoMessage &msg, uint8_t mess #endif // Calculate size + API_TIMING_START(msg_size_calc); ProtoSize size_calc; msg.calculate_size(size_calc); uint32_t calculated_size = size_calc.get_size(); + API_TIMING_END(msg_size_calc, ENCODE_MESSAGE); // Cache frame sizes to avoid repeated virtual calls const uint8_t header_padding = conn->helper_->frame_header_padding(); @@ -308,7 +330,9 @@ uint16_t APIConnection::encode_message_to_buffer(ProtoMessage &msg, uint8_t mess // Encode directly into buffer size_t size_before_encode = shared_buf.size(); + API_TIMING_START(msg_encode); msg.encode({&shared_buf}); + API_TIMING_END(msg_encode, ENCODE_MESSAGE); // Calculate actual encoded size (not including header that was already added) size_t actual_payload_size = shared_buf.size() - size_before_encode; @@ -1560,7 +1584,9 @@ bool APIConnection::send_buffer(ProtoWriteBuffer buffer, uint8_t message_type) { return false; } + API_TIMING_START(write); APIError err = this->helper_->write_protobuf_packet(message_type, buffer); + API_TIMING_END(write, WRITE_PACKET); if (err == APIError::WOULD_BLOCK) return false; if (err != APIError::OK) { @@ -1636,11 +1662,14 @@ void APIConnection::process_batch_() { return; } + API_TIMING_START(buffer_clear); // Try to clear buffer first if (!this->try_to_clear_buffer(true)) { // Can't write now, we'll try again later + API_TIMING_END(buffer_clear, BUFFER_MANAGEMENT); return; } + API_TIMING_END(buffer_clear, BUFFER_MANAGEMENT); // Get shared buffer reference once to avoid multiple calls auto &shared_buf = this->parent_->get_shared_buffer_ref(); @@ -1651,8 +1680,10 @@ void APIConnection::process_batch_() { const auto &item = this->deferred_batch_[0]; // Let the creator calculate size and encode if it fits + API_TIMING_START(single_encode); uint16_t payload_size = item.creator(item.entity, this, std::numeric_limits::max(), true, item.message_type); + API_TIMING_END(single_encode, BATCH_ENCODE); if (payload_size > 0 && this->send_buffer(ProtoWriteBuffer{&shared_buf}, item.message_type)) { #ifdef HAS_PROTO_MESSAGE_DUMP @@ -1705,11 +1736,14 @@ void APIConnection::process_batch_() { uint32_t current_offset = 0; // Process items and encode directly to buffer (up to our limit) + API_TIMING_START(batch_encode_loop); for (size_t i = 0; i < packets_to_process; i++) { const auto &item = this->deferred_batch_[i]; // Try to encode message // The creator will calculate overhead to determine if the message fits + API_TIMING_START(item_encode); uint16_t payload_size = item.creator(item.entity, this, remaining_size, false, item.message_type); + API_TIMING_END(item_encode, BATCH_ENCODE); if (payload_size == 0) { // Message won't fit, stop processing @@ -1736,6 +1770,7 @@ void APIConnection::process_batch_() { // Current buffer size + footer space for this message current_offset = shared_buf.size() + footer_size; } + API_TIMING_END(batch_encode_loop, BATCH_ENCODE); if (items_processed == 0) { this->deferred_batch_.clear(); @@ -1748,8 +1783,10 @@ void APIConnection::process_batch_() { } // Send all collected packets + API_TIMING_START(batch_write); APIError err = this->helper_->write_protobuf_packets(ProtoWriteBuffer{&shared_buf}, std::span(packet_info, packet_count)); + API_TIMING_END(batch_write, PROTO_WRITE); if (err != APIError::OK && err != APIError::WOULD_BLOCK) { on_fatal_error(); this->log_warning_("Batch write failed", err); diff --git a/esphome/components/api/api_connection.h b/esphome/components/api/api_connection.h index 6254854238..3c8cb04f96 100644 --- a/esphome/components/api/api_connection.h +++ b/esphome/components/api/api_connection.h @@ -6,6 +6,7 @@ #include "api_pb2.h" #include "api_pb2_service.h" #include "api_server.h" +#include "api_timing.h" #include "esphome/core/application.h" #include "esphome/core/component.h" #include "esphome/core/entity_base.h" @@ -335,9 +336,11 @@ class APIConnection final : public APIServerConnection { // Helper method to process multiple entities from an iterator in a batch template void process_iterator_batch_(Iterator &iterator) { size_t initial_size = this->deferred_batch_.size(); + API_TIMING_START(iter_advance); while (!iterator.completed() && (this->deferred_batch_.size() - initial_size) < MAX_INITIAL_PER_BATCH) { iterator.advance(); } + API_TIMING_END(iter_advance, ITERATOR_ENCODE); // If the batch is full, process it immediately // Note: iterator.advance() already calls schedule_batch_() via schedule_message_() @@ -681,6 +684,7 @@ class APIConnection final : public APIServerConnection { // Helper method to send a message either immediately or via batching bool send_message_smart_(EntityBase *entity, MessageCreatorPtr creator, uint8_t message_type, uint8_t estimated_size) { + API_TIMING_GUARD(SEND_STATE); // Try to send immediately if: // 1. It's an UpdateStateResponse (always send immediately to handle cases where // the main loop is blocked, e.g., during OTA updates) diff --git a/esphome/components/api/api_pb2_service.cpp b/esphome/components/api/api_pb2_service.cpp index 6b7b8b9ebd..27a3a5eff9 100644 --- a/esphome/components/api/api_pb2_service.cpp +++ b/esphome/components/api/api_pb2_service.cpp @@ -1,6 +1,7 @@ // This file was automatically generated with a tool. // See script/api_protobuf/api_protobuf.py #include "api_pb2_service.h" +#include "api_timing.h" #include "esphome/core/log.h" namespace esphome::api { @@ -14,14 +15,18 @@ void APIServerConnectionBase::log_send_message_(const char *name, const std::str #endif void APIServerConnectionBase::read_message(uint32_t msg_size, uint32_t msg_type, uint8_t *msg_data) { + API_TIMING_START(msg_decode); switch (msg_type) { case HelloRequest::MESSAGE_TYPE: { HelloRequest msg; msg.decode(msg_data, msg_size); + API_TIMING_END(msg_decode, PROTO_READ); #ifdef HAS_PROTO_MESSAGE_DUMP ESP_LOGVV(TAG, "on_hello_request: %s", msg.dump().c_str()); #endif + API_TIMING_START(msg_handle); this->on_hello_request(msg); + API_TIMING_END(msg_handle, MESSAGE_DISPATCH); break; } case ConnectRequest::MESSAGE_TYPE: { diff --git a/esphome/components/api/api_server.cpp b/esphome/components/api/api_server.cpp index 1f38f4a31a..8bee564568 100644 --- a/esphome/components/api/api_server.cpp +++ b/esphome/components/api/api_server.cpp @@ -2,6 +2,7 @@ #ifdef USE_API #include #include "api_connection.h" +#include "api_timing.h" #include "esphome/components/network/util.h" #include "esphome/core/application.h" #include "esphome/core/defines.h" @@ -135,6 +136,7 @@ void APIServer::schedule_reboot_timeout_() { void APIServer::loop() { // Accept new clients only if the socket exists and has incoming connections if (this->socket_ && this->socket_->ready()) { + API_TIMING_GUARD(ACCEPT_CLIENT); while (true) { struct sockaddr_storage source_addr; socklen_t addr_len = sizeof(source_addr); @@ -161,6 +163,7 @@ void APIServer::loop() { // Process clients and remove disconnected ones in a single pass // Check network connectivity once for all clients + API_TIMING_START(network_check); if (!network::is_connected()) { // Network is down - disconnect all clients for (auto &client : this->clients_) { @@ -169,6 +172,7 @@ void APIServer::loop() { } // Continue to process and clean up the clients below } + API_TIMING_END(network_check, NETWORK_CHECK); size_t client_index = 0; while (client_index < this->clients_.size()) { @@ -176,12 +180,15 @@ void APIServer::loop() { if (!client->flags_.remove) { // Common case: process active client + API_TIMING_START(client_loop); client->loop(); + API_TIMING_END(client_loop, CLIENT_LOOP); client_index++; continue; } // Rare case: handle disconnection + API_TIMING_GUARD(CLIENT_REMOVAL); #ifdef USE_API_CLIENT_DISCONNECTED_TRIGGER this->client_disconnected_trigger_->trigger(client->client_info_.name, client->client_info_.peername); #endif diff --git a/esphome/components/runtime_stats/runtime_stats.cpp b/esphome/components/runtime_stats/runtime_stats.cpp index 8f5d5daf01..4570fe3919 100644 --- a/esphome/components/runtime_stats/runtime_stats.cpp +++ b/esphome/components/runtime_stats/runtime_stats.cpp @@ -4,6 +4,10 @@ #include "esphome/core/component.h" #include +#include +#ifdef USE_API +#include "esphome/components/api/api_timing.h" +#endif namespace esphome { @@ -62,6 +66,29 @@ void RuntimeStatsCollector::log_stats_() { stats->get_period_time_ms()); } +#ifdef USE_API + // Log detailed API timing breakdown if available + bool has_api_timing = false; + for (int i = 0; i < static_cast(api::APITimingCategory::MAX_CATEGORIES); i++) { + if (api::api_timing_stats[i].count > 0) { + has_api_timing = true; + break; + } + } + + if (has_api_timing) { + ESP_LOGI(TAG, "API Component Breakdown (microseconds):"); + for (int i = 0; i < static_cast(api::APITimingCategory::MAX_CATEGORIES); i++) { + const api::APITimingStats &stats = api::api_timing_stats[i]; + if (stats.count > 0) { + const char *category_name = api::api_timing_category_to_str(static_cast(i)); + ESP_LOGI(TAG, " %s: count=%" PRIu32 ", avg=%.1fus, max=%" PRIu32 "us, total=%" PRIu64 "us", category_name, + stats.count, stats.get_avg_us(), stats.max_us, stats.total_us); + } + } + } +#endif + // Log total stats since boot ESP_LOGI(TAG, "Total stats (since boot):"); @@ -81,6 +108,16 @@ void RuntimeStatsCollector::log_stats_() { } } +void RuntimeStatsCollector::reset_stats_() { + for (auto &it : this->component_stats_) { + it.second.reset_period_stats(); + } +#ifdef USE_API + // Reset API timing stats for next period + api::reset_api_timing_stats(); +#endif +} + void RuntimeStatsCollector::process_pending_stats(uint32_t current_time) { if (this->next_log_time_ == 0) return; diff --git a/esphome/components/runtime_stats/runtime_stats.h b/esphome/components/runtime_stats/runtime_stats.h index e2f8bee563..3dcf289d01 100644 --- a/esphome/components/runtime_stats/runtime_stats.h +++ b/esphome/components/runtime_stats/runtime_stats.h @@ -103,11 +103,7 @@ class RuntimeStatsCollector { protected: void log_stats_(); - void reset_stats_() { - for (auto &it : this->component_stats_) { - it.second.reset_period_stats(); - } - } + void reset_stats_(); // Use const char* keys for efficiency // Custom comparator for const char* keys in map