refactor: time steps with ElapsedTimer::lap()

loop(), socket client init and /discovery each read a step's time and
restarted the timer by hand. lap() does both. Also put the request timing
comment back on timeRequest() and say why /discovery logs its steps.

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

src/Sockets.cpp

@@ -140,19 +140,16 @@ void SocketEmitter::initClients() {
         esp_task_wdt_reset();
         ElapsedTimer total, step;
         settings.emitSockets(slot);
-        logElapsed(TAG, "Socket init settings", step.us());
+        logElapsed(TAG, "Socket init settings", step.lap());
         if(!ws.hasClient(asyncId)) { this->newClients[i] = 255; continue; }
-        step.restart();
         somfy.emitState(slot);
-        logElapsed(TAG, "Socket init somfy state", step.us());
+        logElapsed(TAG, "Socket init somfy state", step.lap());
         if(!ws.hasClient(asyncId)) { this->newClients[i] = 255; continue; }
-        step.restart();
         git.emitUpdateCheck(slot);
-        logElapsed(TAG, "Socket init update check", step.us());
+        logElapsed(TAG, "Socket init update check", step.lap());
         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 network", step.lap());
         logElapsed(TAG, "Socket init total", total.us());
         esp_task_wdt_reset();
       }

src/SomfyController.ino

@@ -140,26 +140,22 @@ void loop() {
   // Each step only logs when it holds up the loop for LOOP_SLOW_MS or more.
   ElapsedTimer timing;
   net.loop();
-  logIfSlow(TAG, "Loop net", timing.us(), LOOP_SLOW_MS);
+  logIfSlow(TAG, "Loop net", timing.lap(), LOOP_SLOW_MS);
-  timing.restart();
   esp_task_wdt_reset();
   somfy.loop();
-  logIfSlow(TAG, "Loop somfy", timing.us(), LOOP_SLOW_MS);
+  logIfSlow(TAG, "Loop somfy", timing.lap(), 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);
+      logIfSlow(TAG, "Loop git", timing.lap(), LOOP_SLOW_MS);
       esp_task_wdt_reset();
     }
-    timing.restart();
     webServer.loop();
-    logIfSlow(TAG, "Loop web server", timing.us(), LOOP_SLOW_MS);
+    logIfSlow(TAG, "Loop web server", timing.lap(), LOOP_SLOW_MS);
     esp_task_wdt_reset();
-    timing.restart();
     sockEmit.loop();
-    logIfSlow(TAG, "Loop sockets", timing.us(), LOOP_SLOW_MS);
+    logIfSlow(TAG, "Loop sockets", timing.lap(), LOOP_SLOW_MS);
     esp_task_wdt_reset();
   }
   if(rebootDelay.reboot && millis() > rebootDelay.rebootTime) {

src/Timing.h

@@ -24,6 +24,14 @@ class ElapsedTimer {
     ElapsedTimer() : _start(micros()) {}
     void restart() { _start = micros(); }
     uint32_t us() const { return micros() - _start; }
+    // The time since the last lap (or start) and starts the next one, for
+    // timing a series of steps.
+    uint32_t lap() {
+      const uint32_t now = micros();
+      const uint32_t us = now - _start;
+      _start = now;
+      return us;
+    }
 };
 
 // Whether logElapsed() would print a timing this long.  Check it before

src/Web.cpp

@@ -703,8 +703,8 @@ void Web::handleDiscovery(AsyncWebServerRequest *request) {
     char connType[10] = "Unknown";
     if(net.connType == conn_types_t::ethernet) strcpy(connType, "Ethernet");
     else if(net.connType == conn_types_t::wifi) strcpy(connType, "Wifi");
-    // This handler takes about 200ms on the async_tcp task for no obvious
+    // This handler runs on the async_tcp task, which also serves the sockets,
-    // reason, so time each part to find out where it goes.
+    // so a slow one is logged with where its time went.
     ElapsedTimer total, step;
     uint32_t usHead, usMem, usRooms, usShades, usGroups, usSend;
     AsyncJsonResp resp;
@@ -720,7 +720,7 @@ void Web::handleDiscovery(AsyncWebServerRequest *request) {
     resp.addElem("chipModel", settings.chipModel);
     resp.addElem("connType", connType);
     resp.addElem("checkForUpdate", settings.checkForUpdate);
-    usHead = step.us(); step.restart();
+    usHead = step.lap();
     resp.beginObject("memory");
     resp.addElem("max", ESP.getMaxAllocHeap());
     resp.addElem("free", ESP.getFreeHeap());
@@ -728,20 +728,20 @@ void Web::handleDiscovery(AsyncWebServerRequest *request) {
     resp.addElem("total", ESP.getHeapSize());
     resp.addElem("uptime", (uint64_t)millis());
     resp.endObject();
-    usMem = step.us(); step.restart();
+    usMem = step.lap();
     resp.beginArray("rooms");
     serializeRooms(resp);
     resp.endArray();
-    usRooms = step.us(); step.restart();
+    usRooms = step.lap();
     resp.beginArray("shades");
     serializeShades(resp);
     resp.endArray();
-    usShades = step.us(); step.restart();
+    usShades = step.lap();
     resp.beginArray("groups");
     serializeGroups(resp);
     resp.endArray();
     resp.endObject();
-    usGroups = step.us(); step.restart();
+    usGroups = step.lap();
     resp.endResponse();
     usSend = step.us();
     net.needsBroadcast = true;
@@ -1279,10 +1279,6 @@ 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.
 // Logs how long part of a request took, when it is worth logging.
 static void logRequestTime(const char *server, AsyncWebServerRequest *request, const IPAddress &ip, const char *part, uint32_t us) {
   if(!worthLogging(us)) return;
@@ -1291,6 +1287,10 @@ static void logRequestTime(const char *server, AsyncWebServerRequest *request, c
     ip[0], ip[1], ip[2], ip[3], part);
   logElapsed(TAG, what, us);
 }
+// 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.

test/stubs/Arduino.h

@@ -16,7 +16,9 @@ typedef uint8_t byte;
 
 // Fixed so anything formatted from it is deterministic.
 inline unsigned long millis() { return 0; }
-inline unsigned long micros() { return 0; }
+// Tests that measure time set this.
+inline unsigned long stubMicros = 0;
+inline unsigned long micros() { return stubMicros; }
 inline bool getLocalTime(struct tm *info, uint32_t ms = 5000) {
   (void)ms;
   time_t now = time(nullptr);

test/test_logging/test_logging.cpp

@@ -40,6 +40,26 @@ static void test_worthLogging_from_the_threshold() {
   TEST_ASSERT_TRUE(worthLogging(UINT32_MAX));
 }
 
+/*********************************************************************
+ * ElapsedTimer
+ ********************************************************************/
+static void test_elapsedTimer_lap_times_each_step() {
+  stubMicros = 1000;
+  ElapsedTimer timer;
+  stubMicros = 1250;
+  TEST_ASSERT_EQUAL_UINT32(250, timer.lap());
+  stubMicros = 1300;
+  TEST_ASSERT_EQUAL_UINT32(50, timer.lap());
+  TEST_ASSERT_EQUAL_UINT32(0, timer.us());
+}
+static void test_elapsedTimer_lap_across_micros_wrap() {
+  stubMicros = 0xFFFFFF00UL;
+  ElapsedTimer timer;
+  stubMicros = 0x100;
+  TEST_ASSERT_EQUAL_UINT32(0x200, timer.lap());
+  stubMicros = 0;
+}
+
 int main(int argc, char **argv) {
   (void)argc;
   (void)argv;
@@ -51,5 +71,7 @@ int main(int argc, char **argv) {
   RUN_TEST(test_logLock_no_wait_allowed);
   RUN_TEST(test_worthLogging_fast_timings_are_skipped);
   RUN_TEST(test_worthLogging_from_the_threshold);
+  RUN_TEST(test_elapsedTimer_lap_times_each_step);
+  RUN_TEST(test_elapsedTimer_lap_across_micros_wrap);
   return UNITY_END();
 }