Timing.h
| Line | Branch | Exec | Source |
|---|---|---|---|
| 1 | #ifndef timing_h | ||
| 2 | #define timing_h | ||
| 3 | #include <Arduino.h> | ||
| 4 | #include "esp_log.h" | ||
| 5 | |||
| 6 | // Timings shorter than this are not logged. Every line costs several ms on a | ||
| 7 | // 115200 baud console, and per-request timings would add dozens of lines to | ||
| 8 | // every page load on the task that serves the sockets. Build with | ||
| 9 | // -DTIMING_LOG_MIN_MS=0 to see every timing. | ||
| 10 | #ifndef TIMING_LOG_MIN_MS | ||
| 11 | #define TIMING_LOG_MIN_MS 100 | ||
| 12 | #endif | ||
| 13 | // Anything that takes at least this long is logged as a warning so the slow | ||
| 14 | // calls stand out from the routine timings. | ||
| 15 | #ifndef TIMING_SLOW_MS | ||
| 16 | #define TIMING_SLOW_MS 1000 | ||
| 17 | #endif | ||
| 18 | |||
| 19 | // Measures elapsed time in microseconds. micros() wraps every ~71 minutes but | ||
| 20 | // the unsigned subtraction keeps any span shorter than that correct. | ||
| 21 | class ElapsedTimer { | ||
| 22 | uint32_t _start; | ||
| 23 | public: | ||
| 24 | 2 | ElapsedTimer() : _start(micros()) {} | |
| 25 | void restart() { _start = micros(); } | ||
| 26 | 1 | uint32_t us() const { return micros() - _start; } | |
| 27 | // The time since the last lap (or start) and starts the next one, for | ||
| 28 | // timing a series of steps. | ||
| 29 | 3 | uint32_t lap() { | |
| 30 | 3 | const uint32_t now = micros(); | |
| 31 | 3 | const uint32_t us = now - _start; | |
| 32 | 3 | _start = now; | |
| 33 | 3 | return us; | |
| 34 | } | ||
| 35 | }; | ||
| 36 | |||
| 37 | // Whether logElapsed() would print a timing this long. Check it before | ||
| 38 | // building the description so the common, fast case costs nothing. | ||
| 39 | 6 | static inline bool worthLogging(uint32_t us) { return us / 1000 >= TIMING_LOG_MIN_MS; } | |
| 40 | // Logs how long something took as milliseconds with microsecond precision. | ||
| 41 | static inline void logElapsed(const char *tag, const char *what, uint32_t us) { | ||
| 42 | if(!worthLogging(us)) return; | ||
| 43 | const unsigned long ms = us / 1000, frac = us % 1000; | ||
| 44 | if(ms >= TIMING_SLOW_MS) ESP_LOGW(tag, "%s took %lu.%03lums (slow)", what, ms, frac); | ||
| 45 | else ESP_LOGI(tag, "%s took %lu.%03lums", what, ms, frac); | ||
| 46 | } | ||
| 47 | // For calls that run constantly, like loop(), where logging every pass would | ||
| 48 | // flood the console. Only logs once the time reaches minMs. | ||
| 49 | static inline void logIfSlow(const char *tag, const char *what, uint32_t us, uint32_t minMs) { | ||
| 50 | if(us >= minMs * 1000) logElapsed(tag, what, us); | ||
| 51 | } | ||
| 52 | #endif | ||
| 53 |