fix: skip formatting request timings that won't be logged

timeRequest built both 112-byte descriptions (with a String copy of the URL)
on async_tcp for every request, and logElapsed threw them away for anything
under 100ms.  Check worthLogging() first.

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

src/Timing.h

@@ -26,10 +26,13 @@ class ElapsedTimer {
     uint32_t us() const { return micros() - _start; }
 };
 
+// Whether logElapsed() would print a timing this long.  Check it before
+// building the description so the common, fast case costs nothing.
+static inline bool worthLogging(uint32_t us) { return us / 1000 >= TIMING_LOG_MIN_MS; }
 // Logs how long something took as milliseconds with microsecond precision.
 static inline void logElapsed(const char *tag, const char *what, uint32_t us) {
+  if(!worthLogging(us)) return;
   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);
 }

src/Web.cpp

@@ -1300,17 +1300,21 @@ static void timeRequest(AsyncWebServerRequest *request, ArMiddlewareNext next, c
   // this runs, and replacing it would stop the reboot after an update.
   if(!request->multipart()) {
     request->onDisconnect([request, timer, server, ip]() {
+      const uint32_t us = timer.us();
+      if(!worthLogging(us)) return;
       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());
+      logElapsed(TAG, what, us);
     });
   }
   next();
+  const uint32_t us = timer.us();
+  if(!worthLogging(us)) return;
   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());
+  logElapsed(TAG, what, us);
 }
 
 void Web::begin() {

test/stubs/Arduino.h

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

test/test_logging/test_logging.cpp

@@ -1,5 +1,6 @@
 #include <unity.h>
 #include "LogLockPolicy.h"
+#include "Timing.h"
 
 void setUp() {}
 void tearDown() {}
@@ -25,6 +26,20 @@ static void test_logLock_no_wait_allowed() {
   TEST_ASSERT_FALSE(keepWaitingForLogLock(LogHolder::running, 0, 0));
 }
 
+/*********************************************************************
+ * worthLogging
+ ********************************************************************/
+static void test_worthLogging_fast_timings_are_skipped() {
+  TEST_ASSERT_FALSE(worthLogging(0));
+  TEST_ASSERT_FALSE(worthLogging(999));
+  TEST_ASSERT_FALSE(worthLogging(TIMING_LOG_MIN_MS * 1000 - 1));
+}
+static void test_worthLogging_from_the_threshold() {
+  TEST_ASSERT_TRUE(worthLogging(TIMING_LOG_MIN_MS * 1000));
+  TEST_ASSERT_TRUE(worthLogging(TIMING_SLOW_MS * 1000));
+  TEST_ASSERT_TRUE(worthLogging(UINT32_MAX));
+}
+
 int main(int argc, char **argv) {
   (void)argc;
   (void)argv;
@@ -34,5 +49,7 @@ int main(int argc, char **argv) {
   RUN_TEST(test_logLock_waits_for_a_holder_preempted_here);
   RUN_TEST(test_logLock_gives_up_on_a_holder_preempted_elsewhere);
   RUN_TEST(test_logLock_no_wait_allowed);
+  RUN_TEST(test_worthLogging_fast_timings_are_skipped);
+  RUN_TEST(test_worthLogging_from_the_threshold);
   return UNITY_END();
 }