more stats

This commit is contained in:
J. Nick Koston 2025-05-22 21:58:16 -05:00
parent 663f38d2ec
commit 0a1f3e813c
No known key found for this signature in database
4 changed files with 138 additions and 58 deletions

View File

@ -88,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();

View File

@ -68,64 +68,8 @@ class APIConnection : public APIServerConnection {
APIConnection(std::unique_ptr<socket::Socket> socket, APIServer *parent);
virtual ~APIConnection();
// Performance statistics class for API loop sections
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;
}
// Period stats (reset each logging interval)
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 ? this->period_time_ms_ / static_cast<float>(this->period_count_) : 0.0f;
}
// Total stats (persistent until reboot)
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 ? this->total_time_ms_ / static_cast<float>(this->total_count_) : 0.0f;
}
protected:
// Period stats (reset each logging interval)
uint32_t period_count_;
uint32_t period_time_ms_;
uint32_t period_max_time_ms_;
// Total stats (persistent until reboot)
uint32_t total_count_;
uint32_t total_time_ms_;
uint32_t total_max_time_ms_;
};
// Use the APISectionStats from api_frame_helper.h to avoid duplication
using APISectionStats = ::esphome::api::APISectionStats;
void start();
void loop();

View File

@ -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

View File

@ -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