From 4544eb6469719b1063d24dabde89942b5392c0eb Mon Sep 17 00:00:00 2001 From: cjkas Date: Tue, 13 Oct 2026 15:39:14 +0200 Subject: [PATCH] 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 --- src/Sockets.cpp | 11 ++++------- src/SomfyController.ino | 14 +++++--------- src/Timing.h | 8 ++++++++ src/Web.cpp | 22 +++++++++++----------- test/stubs/Arduino.h | 4 +++- test/test_logging/test_logging.cpp | 22 ++++++++++++++++++++++ 6 files changed, 53 insertions(+), 28 deletions(-) diff --git a/src/Sockets.cpp b/src/Sockets.cpp index c4fad59..3e887e1 100644 --- a/src/Sockets.cpp +++ b/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(); } diff --git a/src/SomfyController.ino b/src/SomfyController.ino index 29af53e..91e351f 100644 --- a/src/SomfyController.ino +++ b/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); - timing.restart(); + logIfSlow(TAG, "Loop net", timing.lap(), LOOP_SLOW_MS); 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) { diff --git a/src/Timing.h b/src/Timing.h index 2e46f5b..78fafe3 100644 --- a/src/Timing.h +++ b/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 diff --git a/src/Web.cpp b/src/Web.cpp index 07cf46a..72a4052 100644 --- a/src/Web.cpp +++ b/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 - // reason, so time each part to find out where it goes. + // This handler runs on the async_tcp task, which also serves the sockets, + // 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. diff --git a/test/stubs/Arduino.h b/test/stubs/Arduino.h index f38a317..f247c50 100644 --- a/test/stubs/Arduino.h +++ b/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); diff --git a/test/test_logging/test_logging.cpp b/test/test_logging/test_logging.cpp index 120fe0e..7461063 100644 --- a/test/test_logging/test_logging.cpp +++ b/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(); }