diff --git a/src/Sockets.cpp b/src/Sockets.cpp index ba4babe..0fb61c7 100644 --- a/src/Sockets.cpp +++ b/src/Sockets.cpp @@ -7,6 +7,7 @@ #include "Somfy.h" #include "ESPNetwork.h" #include "GitOTA.h" +#include "Timing.h" static const char *TAG = "Sockets"; @@ -21,6 +22,11 @@ AsyncWebSocket ws("/"); #define MAX_WS_CLIENTS 5 static uint32_t clientMap[MAX_WS_CLIENTS] = {0,0,0,0,0}; +// When each slot connected and last saw a ping, so the logs show how long a +// client stayed and how far apart its pings arrived. +static uint32_t connectedAt[MAX_WS_CLIENTS] = {0,0,0,0,0}; +static uint32_t lastPing[MAX_WS_CLIENTS] = {0,0,0,0,0}; +#define PING_LATE_MS 25000 static uint8_t mapClientId(uint32_t asyncId) { for(uint8_t i = 0; i < MAX_WS_CLIENTS; i++) @@ -131,13 +137,22 @@ void SocketEmitter::initClients() { if(asyncId != 0 && ws.hasClient(asyncId)) { ESP_LOGD(TAG, "Initializing Socket Client %u (asyncId=%lu)", slot, asyncId); esp_task_wdt_reset(); + ElapsedTimer total, step; settings.emitSockets(slot); + logElapsed(TAG, "Socket init settings", step.us()); if(!ws.hasClient(asyncId)) { this->newClients[i] = 255; continue; } + step.restart(); somfy.emitState(slot); + logElapsed(TAG, "Socket init somfy state", step.us()); if(!ws.hasClient(asyncId)) { this->newClients[i] = 255; continue; } + step.restart(); git.emitUpdateCheck(slot); + logElapsed(TAG, "Socket init update check", step.us()); if(!ws.hasClient(asyncId)) { this->newClients[i] = 255; continue; } + step.restart(); net.emitSockets(slot); + logElapsed(TAG, "Socket init network", step.us()); + logElapsed(TAG, "Socket init total", total.us()); esp_task_wdt_reset(); } this->newClients[i] = 255; @@ -176,7 +191,9 @@ void SocketEmitter::wsEvent(AsyncWebSocket *server, AsyncWebSocketClient *client return; } IPAddress ip = client->remoteIP(); - ESP_LOGD(TAG, "Socket [%lu] Connected from %d.%d.%d.%d (slot %u)", asyncId, ip[0], ip[1], ip[2], ip[3], slot); + ESP_LOGI(TAG, "Socket [%lu] Connected from %d.%d.%d.%d (slot %u)", asyncId, ip[0], ip[1], ip[2], ip[3], slot); + connectedAt[slot] = millis(); + lastPing[slot] = 0; client->text("Connected"); client->setCloseClientOnQueueFull(false); sockEmit.delayInit(slot); @@ -185,8 +202,9 @@ void SocketEmitter::wsEvent(AsyncWebSocket *server, AsyncWebSocketClient *client case WS_EVT_DISCONNECT: { uint8_t slot = mapClientId(asyncId); - ESP_LOGD(TAG, "Socket [%lu] Disconnected (slot %u)", asyncId, slot); if(slot != 255) { + ESP_LOGI(TAG, "Socket [%lu] Disconnected (slot %u) after %lums, last ping %lums ago", asyncId, slot, + (unsigned long)(millis() - connectedAt[slot]), lastPing[slot] ? (unsigned long)(millis() - lastPing[slot]) : 0UL); for(uint8_t i = 0; i < SOCK_MAX_ROOMS; i++) sockEmit.rooms[i].leave(slot); } @@ -218,6 +236,20 @@ void SocketEmitter::wsEvent(AsyncWebSocket *server, AsyncWebSocketClient *client case WS_EVT_ERROR: ESP_LOGE(TAG, "Socket [%lu] Error", asyncId); break; + case WS_EVT_PING: + { + // Home Assistant pings every 20s and drops the socket when the pong is + // late, so only a late ping is worth a line; it points at a stalled + // network task or a lossy link. + uint8_t slot = mapClientId(asyncId); + if(slot != 255) { + uint32_t now = millis(); + if(lastPing[slot] && now - lastPing[slot] > PING_LATE_MS) + ESP_LOGW(TAG, "Socket [%lu] late ping, %lums since the last", asyncId, (unsigned long)(now - lastPing[slot])); + lastPing[slot] = now; + } + } + break; case WS_EVT_PONG: break; } diff --git a/src/SomfyController.ino b/src/SomfyController.ino index 976bb44..25205c3 100644 --- a/src/SomfyController.ino +++ b/src/SomfyController.ino @@ -11,8 +11,18 @@ #include "MQTT.h" #include "GitOTA.h" #include "esp_core_dump.h" +#include "esp_idf_version.h" +#if ESP_IDF_VERSION >= ESP_IDF_VERSION_VAL(5, 0, 0) +#include "esp_app_desc.h" +#define getRunningElfSha esp_app_get_elf_sha256 +#else +#include "esp_ota_ops.h" +#define getRunningElfSha esp_ota_get_app_elf_sha256 +#endif +#include "Timing.h" static const char *TAG = "Main"; +#define LOOP_SLOW_MS 100 ConfigSettings settings; Web webServer; @@ -65,21 +75,28 @@ void setup() { ESP_LOGW(TAG, " MTVAL: 0x%08x RA: 0x%08x SP: 0x%08x", summary.ex_info.mtval, summary.ex_info.ra, summary.ex_info.sp); #endif + // The backtrace only decodes against the firmware.elf of the build that + // crashed, so say whether that is the one running now. + const char *crashedSha = (const char *)summary.app_elf_sha256; + char runningSha[APP_ELF_SHA256_SZ] = {0}; + getRunningElfSha(runningSha, sizeof(runningSha)); + if(strcmp(crashedSha, runningSha) == 0) + ESP_LOGW(TAG, " Build: %s (running %s, same build)", crashedSha, runningSha); + else + ESP_LOGW(TAG, " Build: %s (running %s, different build, decode the backtrace with the matching firmware.elf)", crashedSha, runningSha); + // Erase it so the next boot only reports a new crash. + if(esp_core_dump_image_erase() != ESP_OK) ESP_LOGE(TAG, "Could not erase the coredump"); } ESP_LOGI(TAG, "Mounting File System..."); - - if (LittleFS.begin()) { ESP_LOGI(TAG, "Total: %d bytes", LittleFS.totalBytes()); ESP_LOGI(TAG, "Used: %d bytes", LittleFS.usedBytes()); ESP_LOGI(TAG, "Free: %d bytes", LittleFS.totalBytes() - LittleFS.usedBytes()); listDir("/", 3); + ESP_LOGI(TAG, "File system mounted successfully"); } else { ESP_LOGE(TAG, "LittleFS mount failed!"); } - - if(LittleFS.begin()) ESP_LOGI(TAG, "File system mounted successfully"); - else ESP_LOGE(TAG, "Error mounting file system"); settings.begin(); if(WiFi.status() == WL_CONNECTED) WiFi.disconnect(true); delay(10); @@ -108,30 +125,30 @@ void loop() { ESP.restart(); return; } - uint32_t timing = millis(); - + // Each step only logs when it holds up the loop for LOOP_SLOW_MS or more. + ElapsedTimer timing; net.loop(); - if(millis() - timing > 100) ESP_LOGD(TAG, "Timing Net: %ldms", millis() - timing); - timing = millis(); + logIfSlow(TAG, "Loop net", timing.us(), LOOP_SLOW_MS); + timing.restart(); esp_task_wdt_reset(); somfy.loop(); - if(millis() - timing > 100) ESP_LOGD(TAG, "Timing Somfy: %ldms", millis() - timing); - timing = millis(); + logIfSlow(TAG, "Loop somfy", timing.us(), LOOP_SLOW_MS); esp_task_wdt_reset(); if(net.connected() || net.softAPOpened) { if(!rebootDelay.reboot && net.connected() && !net.softAPOpened) { + timing.restart(); git.loop(); + logIfSlow(TAG, "Loop git", timing.us(), LOOP_SLOW_MS); esp_task_wdt_reset(); } + timing.restart(); webServer.loop(); + logIfSlow(TAG, "Loop web server", timing.us(), LOOP_SLOW_MS); esp_task_wdt_reset(); - if(millis() - timing > 100) ESP_LOGD(TAG, "Timing WebServer: %ldms", millis() - timing); - esp_task_wdt_reset(); - timing = millis(); + timing.restart(); sockEmit.loop(); - if(millis() - timing > 100) ESP_LOGD(TAG, "Timing Socket: %ldms", millis() - timing); + logIfSlow(TAG, "Loop sockets", timing.us(), LOOP_SLOW_MS); esp_task_wdt_reset(); - timing = millis(); } if(rebootDelay.reboot && millis() > rebootDelay.rebootTime) { net.end(); diff --git a/src/Timing.h b/src/Timing.h new file mode 100644 index 0000000..160b8fc --- /dev/null +++ b/src/Timing.h @@ -0,0 +1,50 @@ +#ifndef timing_h +#define timing_h +#include +#include "esp_log.h" + +// Timings shorter than this are not logged. Every line costs several ms on a +// 115200 baud console so raise it (e.g. -DTIMING_LOG_MIN_MS=50) to see only +// the calls worth looking at. +#ifndef TIMING_LOG_MIN_MS +#define TIMING_LOG_MIN_MS 0 +#endif +// Anything that takes at least this long is logged as a warning so the slow +// calls stand out from the routine timings. +#ifndef TIMING_SLOW_MS +#define TIMING_SLOW_MS 1000 +#endif + +// Measures elapsed time in microseconds. micros() wraps every ~71 minutes but +// the unsigned subtraction keeps any span shorter than that correct. +class ElapsedTimer { + uint32_t _start; + public: + ElapsedTimer() : _start(micros()) {} + void restart() { _start = micros(); } + uint32_t us() const { return micros() - _start; } +}; + +// Logs how long something took as milliseconds with microsecond precision. +static inline void logElapsed(const char *tag, const char *what, uint32_t us) { + const unsigned long ms = us / 1000, frac = us % 1000; + if(ms < TIMING_LOG_MIN_MS) return; + if(ms >= TIMING_SLOW_MS) ESP_LOGW(tag, "%s took %lu.%03lums (slow)", what, ms, frac); + else ESP_LOGI(tag, "%s took %lu.%03lums", what, ms, frac); +} +// For calls that run constantly, like loop(), where logging every pass would +// flood the console. Only logs once the time reaches minMs. +static inline void logIfSlow(const char *tag, const char *what, uint32_t us, uint32_t minMs) { + if(us >= minMs * 1000) logElapsed(tag, what, us); +} + +// Logs the time the enclosing scope took when it ends. +class ScopeTimer { + const char *_tag; + const char *_what; + ElapsedTimer _timer; + public: + ScopeTimer(const char *tag, const char *what) : _tag(tag), _what(what) {} + ~ScopeTimer() { logElapsed(_tag, _what, _timer.us()); } +}; +#endif diff --git a/src/WResp.cpp b/src/WResp.cpp index 1fb8aa4..1d4dcde 100644 --- a/src/WResp.cpp +++ b/src/WResp.cpp @@ -1,9 +1,12 @@ #include "WResp.h" #include "esp_log.h" +#include "Timing.h" static const char *TAG = "WResp"; +#define EMIT_SLOW_MS 20 void JsonSockEvent::beginEvent(AsyncWebSocket *server, const char *evt, char *buff, size_t buffSize) { this->server = server; + this->_evt = evt; this->buff = buff; this->buffSize = buffSize; this->_nocomma = true; @@ -27,8 +30,16 @@ void JsonSockEvent::endEvent(uint32_t clientId) { ESP_LOGE(TAG, "Socket event too large for %u bytes, not sent: %.32s", (unsigned)this->buffSize, this->buff); return; } + ElapsedTimer timer; if(clientId == 0) this->server->textAll(this->buff); else this->server->text(clientId, this->buff); + // Sends happen every few seconds, so only the slow ones are worth a line. + const uint32_t us = timer.us(); + if(us < EMIT_SLOW_MS * 1000) return; + char what[80]; + if(clientId == 0) snprintf(what, sizeof(what), "Socket emit %s (%u bytes) to all", this->_evt, (unsigned)strlen(this->buff)); + else snprintf(what, sizeof(what), "Socket emit %s (%u bytes) to %lu", this->_evt, (unsigned)strlen(this->buff), (unsigned long)clientId); + logElapsed(TAG, what, us); } void JsonSockEvent::_safecat(const char *val, bool escape) { size_t len = (escape ? this->calcEscapedLength(val) : strlen(val)) + strlen(this->buff); diff --git a/src/WResp.h b/src/WResp.h index 23de961..ad5890f 100644 --- a/src/WResp.h +++ b/src/WResp.h @@ -17,6 +17,7 @@ class AsyncJsonResp : public JsonFormatter { class JsonSockEvent : public JsonFormatter { protected: bool _closed = false; + const char *_evt = ""; void _safecat(const char *val, bool escape = false) override; public: AsyncWebSocket *server = nullptr; diff --git a/src/Web.cpp b/src/Web.cpp index 604c2dc..89b4965 100644 --- a/src/Web.cpp +++ b/src/Web.cpp @@ -14,6 +14,7 @@ #include "MQTT.h" #include "GitOTA.h" #include "ESPNetwork.h" +#include "Timing.h" #include #include #include @@ -1245,8 +1246,35 @@ void Web::handleNotFound(AsyncWebServerRequest *request) { request->send(404, _encoding_text, g_async_content); } +// Logs how long a request takes to handle and, once the connection closes, how +// long the whole exchange took. The total includes chunked bodies like +// /controller that are built while they are sent, after the handler returns. +// The server name must be a literal as the disconnect handler keeps it. +static void timeRequest(AsyncWebServerRequest *request, ArMiddlewareNext next, const char *server) { + ElapsedTimer timer; + // Taken now as the client may already be gone when the disconnect runs. + IPAddress ip = request->client() ? request->client()->remoteIP() : IPAddress(); + // Uploads set their own disconnect handler while the body arrives, before + // this runs, and replacing it would stop the reboot after an update. + if(!request->multipart()) { + request->onDisconnect([request, timer, server, ip]() { + char what[112]; + snprintf(what, sizeof(what), "%s %s %s from %u.%u.%u.%u total", server, request->methodToString(), request->url().c_str(), + ip[0], ip[1], ip[2], ip[3]); + logElapsed(TAG, what, timer.us()); + }); + } + next(); + char what[112]; + snprintf(what, sizeof(what), "%s %s %s from %u.%u.%u.%u handler", server, request->methodToString(), request->url().c_str(), + ip[0], ip[1], ip[2], ip[3]); + logElapsed(TAG, what, timer.us()); +} + void Web::begin() { ESP_LOGI(TAG, "Creating Web MicroServices..."); + asyncApiServer.addMiddleware([](AsyncWebServerRequest *r, ArMiddlewareNext next) { timeRequest(r, next, "api"); }); + asyncServer.addMiddleware([](AsyncWebServerRequest *r, ArMiddlewareNext next) { timeRequest(r, next, "web"); }); // Async API Server (port 8081) DefaultHeaders::Instance().addHeader("Access-Control-Allow-Origin", "*"); DefaultHeaders::Instance().addHeader("Access-Control-Allow-Methods", "PUT,POST,GET,OPTIONS");