feat(logger): Minor cleanup / improvement to impl for rate limiting - #685
Conversation
|
✅Static analysis result - no issues found! ✅ |
There was a problem hiding this comment.
Pull request overview
Note
Copilot couldn't run its full agentic review because it didn't start before the timeout. Make sure your repository has a runner available, or add a copilot-code-review.yml file specifying one with the runs-on attribute. See the docs for more details.
Updates the logger’s rate-limiting implementation to use a monotonic clock and make time comparisons explicit/consistent.
Changes:
- Introduces a
steady_clockalias for rate-limiting (clock_t). - Switches rate-limit timing from
high_resolution_clocktosteady_clock. - Casts elapsed time to
std::chrono::duration<float>before comparing withrate_limit_.
Address review feedback on the rate-limiting impl: - Store last_print_ as a std::atomic<clock_t::rep> timestamp so the check-and-update in the *_rate_limited() methods is free of the data race / UB that occurred when logging from multiple threads. - Store rate_limit_ in the clock's native clock_t::duration (converted once in the constructor / set_rate_limit) and compare in that type, removing the per-call duration<float> casts and their precision loss. - Drop the redundant Logger:: qualifier on clock_t inside the class. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
There was a problem hiding this comment.
Pull request overview
Copilot reviewed 1 out of 1 changed files in this pull request and generated 1 comment.
Suppressed comments (4)
components/logger/include/logger.hpp:366
- With
last_print_defaulting to 0, the first call after startup can be suppressed for up torate_limit_(sincenow - 0may be <rate_limit_). If the intent is “first call prints, subsequent calls are limited”, treat0as a sentinel meaning “never printed yet” and bypass the duration check in that case.
if (rate_limit_ > clock_t::duration::zero()) {
const auto now = clock_t::now().time_since_epoch().count();
// last_print_ is an atomic timestamp (clock_t rep) so the check/update is
// free of data races when logging from multiple threads.
if (clock_t::duration(now - last_print_.load()) < rate_limit_)
components/logger/include/logger.hpp:390
- With
last_print_defaulting to 0, the first call after startup can be suppressed for up torate_limit_(sincenow - 0may be <rate_limit_). If the intent is “first call prints, subsequent calls are limited”, treat0as a sentinel meaning “never printed yet” and bypass the duration check in that case.
if (rate_limit_ > clock_t::duration::zero()) {
const auto now = clock_t::now().time_since_epoch().count();
// last_print_ is an atomic timestamp (clock_t rep) so the check/update is
// free of data races when logging from multiple threads.
if (clock_t::duration(now - last_print_.load()) < rate_limit_)
components/logger/include/logger.hpp:414
- With
last_print_defaulting to 0, the first call after startup can be suppressed for up torate_limit_(sincenow - 0may be <rate_limit_). If the intent is “first call prints, subsequent calls are limited”, treat0as a sentinel meaning “never printed yet” and bypass the duration check in that case.
if (rate_limit_ > clock_t::duration::zero()) {
const auto now = clock_t::now().time_since_epoch().count();
// last_print_ is an atomic timestamp (clock_t rep) so the check/update is
// free of data races when logging from multiple threads.
if (clock_t::duration(now - last_print_.load()) < rate_limit_)
components/logger/include/logger.hpp:342
- With
last_print_defaulting to 0, the first call after startup can be suppressed for up torate_limit_(sincenow - 0may be <rate_limit_). If the intent is “first call prints, subsequent calls are limited”, treat0as a sentinel meaning “never printed yet” and bypass the duration check in that case.
This issue also appears in the following locations of the same file:
- line 362
- line 386
- line 410
if (rate_limit_ > clock_t::duration::zero()) {
const auto now = clock_t::now().time_since_epoch().count();
// last_print_ is an atomic timestamp (clock_t rep) so the check/update is
// free of data races when logging from multiple threads.
if (clock_t::duration(now - last_print_.load()) < rate_limit_)
| void set_rate_limit(const std::chrono::duration<float> rate_limit) { | ||
| rate_limit_ = std::chrono::duration_cast<clock_t::duration>(rate_limit); | ||
| } |
Description
Reworks the
Loggerrate-limiting implementation:std::chrono::high_resolution_clocktostd::chrono::steady_clock, exposed as a newLogger::clock_talias.steady_clockis guaranteed monotonic, so rate limiting no longer misbehaves if the underlying clock jumps (high_resolution_clockis allowed to aliassystem_clock).last_print_as astd::atomic<clock_t::rep>timestamp, so the check-and-update inside the*_rate_limited()helpers is free of the data race / UB that occurred when a logger was used from multiple tasks.rate_limit_in the clock's nativeclock_t::duration(converted once in the constructor andset_rate_limit()) and compares in that type, removing the per-callduration<float>casts and their precision loss.get_rate_limit()still returnsstd::chrono::duration<float>, so the public API is unchanged.Motivation and Context
The rate-limited log helpers computed elapsed time with
high_resolution_clock(not guaranteed monotonic) and read/updatedlast_print_without synchronization — a data race when logging from multiple tasks that could also miss or duplicate prints. Each call additionally re-cast durations toduration<float>. These changes make the rate limiter correct under concurrency, robust against non-monotonic clocks, and free of unnecessary conversions, without changing the public API.How has this been tested?
idf.py buildon theloggerexample builds clean on ESP32 (also confirms the 64-bitstd::atomic<clock_t::rep>links on the 32-bit target).logger.hpp.loggerexample exercises the*_rate_limited()paths.Screenshots (if appropriate, e.g. schematic, board, console logs, lab pictures):
N/A
Types of changes
Checklist:
Software
.github/workflows/build.ymlfile to add my new test to the automated cloud build github action.