diff --git a/src/Timing.h b/src/Timing.h index 1367ec9..2e46f5b 100644 --- a/src/Timing.h +++ b/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); } diff --git a/src/Web.cpp b/src/Web.cpp index 2da4208..faff038 100644 --- a/src/Web.cpp +++ b/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() { diff --git a/test/stubs/Arduino.h b/test/stubs/Arduino.h index b9584dc..f38a317 100644 --- a/test/stubs/Arduino.h +++ b/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); diff --git a/test/test_logging/test_logging.cpp b/test/test_logging/test_logging.cpp index 3cfda43..120fe0e 100644 --- a/test/test_logging/test_logging.cpp +++ b/test/test_logging/test_logging.cpp @@ -1,5 +1,6 @@ #include #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(); }