feat: log timings for slow work, socket clients and boot crashes

Add Timing.h and use it to log what holds up the main loop, how long a
new socket client's setup takes, slow socket sends, and how long each
web request took and from which client. Socket connects and disconnects
are logged with how long the client stayed, and late pings as warnings.
Routine sends and pings are not logged, as each line costs several ms
on a 115200 baud console.

Report a stored crash once with the crashed and running build IDs, then
erase it, since it was reported on every boot and its backtrace only
decodes against the build that crashed. Mount the file system once.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

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;
   }

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);
+  logIfSlow(TAG, "Loop net", timing.us(), LOOP_SLOW_MS);
-  timing = millis();
+  timing.restart();
   esp_task_wdt_reset();
   somfy.loop();
-  if(millis() - timing > 100) ESP_LOGD(TAG, "Timing Somfy: %ldms", millis() - timing);
+  logIfSlow(TAG, "Loop somfy", timing.us(), LOOP_SLOW_MS);
-  timing = millis();
   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);
+    timing.restart();
-    esp_task_wdt_reset();
-    timing = millis();
     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();

src/Timing.h

@@ -0,0 +1,50 @@
+#ifndef timing_h
+#define timing_h
+#include <Arduino.h>
+#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

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);

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;

src/Web.cpp

@@ -14,6 +14,7 @@
 #include "MQTT.h"
 #include "GitOTA.h"
 #include "ESPNetwork.h"
+#include "Timing.h"
 #include <AsyncTCP.h>
 #include <ESPAsyncWebServer.h>
 #include <AsyncJson.h>
@@ -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");