feat(logger): add rate limiter#5799
feat(logger): add rate limiter#5799kalyazin wants to merge 4 commits intofirecracker-microvm:mainfrom
Conversation
kalyazin
force-pushed
the
log_rate_limiter
branch
from
2325c61 to
3ddd1f5
Compare
Codecov Report❌ Patch coverage is Additional details and impacted files@@ Coverage Diff @@
## main #5799 +/- ##
==========================================
- Coverage 83.00% 82.99% -0.02%
==========================================
Files 275 276 +1
Lines 29396 29421 +25
==========================================
+ Hits 24401 24417 +16
- Misses 4995 5004 +9
Flags with carried forward coverage won't be shown. Click here to find out more. ☔ View full report in Codecov by Sentry. 🚀 New features to boost your workflow:
|
kalyazin
force-pushed
the
log_rate_limiter
branch
2 times, most recently
from
0240225 to
eb60521
Compare
kalyazin
added
the
Status: Awaiting review
kalyazin
force-pushed
the
log_rate_limiter
branch
3 times, most recently
from
531998b to
80580f3
Compare
kalyazin
force-pushed
the
log_rate_limiter
branch
from
80580f3 to
b795a7b
Compare
| use crate::rate_limiter::TokenBucket; | ||
|
|
||
| /// Maximum number of messages allowed per refill period. | ||
| pub const DEFAULT_BURST: u64 = 10; |
There was a problem hiding this comment.
Is 10 message per 5 seconds overly conservative?
Add a per-callsite rate limiter for logging that reuses the existing TokenBucket implementation. LogRateLimiter wraps TokenBucket in OnceLock<Mutex<...>> for lazy initialization and thread safety. The check() method calls TokenBucket::reduce(1) to consume a token and returns whether the message should be logged. Default configuration: 10 messages per 5-second refill period. Includes unit tests for burst enforcement, callsite independence, and token refill after the refill period. Signed-off-by: Nikita Kalyazin <kalyazin@amazon.com>
Define error_rate_limited!, warn_rate_limited!, and info_rate_limited! macros via a shared __log_rate_limited_impl! helper. Each macro first checks log_enabled! at the appropriate level to avoid rate limiter overhead for filtered-out messages. If the level is enabled, each invocation site creates an independent static LogRateLimiter and AtomicU64 suppression counter. Allowed messages are emitted normally; suppressed messages increment the counter and the global rate_limited_log_count metric. When logging resumes, a warn-level summary reports the suppression count. Add rate_limited_log_count field to LoggerSystemMetrics and to the fcmetrics.py validation schema. Re-export all rate-limited macros via crate::logger for consistency with other log macros. Signed-off-by: Nikita Kalyazin <kalyazin@amazon.com>
Migrate error!, warn!, and info! log callsites in device and VMM paths to their rate-limited equivalents. debug! calls are left unchanged as they are disabled in release Firecracker builds and the log_enabled! check in the rate-limited macros already ensures zero overhead for disabled levels. Covers all virtio devices (balloon, net, block, rng, vsock, pmem, mem), transport layers (MMIO, PCI), vCPU exit handling, memory management, and the I/O rate limiter. Each callsite independently rate-limits to 10 messages per 5-second refill period. Signed-off-by: Nikita Kalyazin <kalyazin@amazon.com>
kalyazin
force-pushed
the
log_rate_limiter
branch
from
b795a7b to
0514643
Compare
Add an entry under the Unreleased section documenting per-callsite rate limiting for error, warn, and info level log messages and the new rate_limited_log_count metric. Signed-off-by: Nikita Kalyazin <kalyazin@amazon.com>
kalyazin
force-pushed
the
log_rate_limiter
branch
from
0514643 to
d5835aa
Compare
| use crate::cpu_config::aarch64::custom_cpu_template::VcpuFeatures; | ||
| use crate::cpu_config::templates::CpuConfiguration; | ||
| use crate::logger::{IncMetric, METRICS, error}; | ||
| use crate::logger::{IncMetric, METRICS, error_rate_limited}; |
There was a problem hiding this comment.
can we make crate::logger::error be the rate limited one and ensure we're not using log::error directly?
Clippy can be configured to check it with clippy::disallowed_macros and
disallowed-macros = [
{ path = "log::error", reason = "use crate::logger::error! instead" },
{ path = "log::warn", reason = "use crate::logger::warn! instead" },
{ path = "log::info", reason = "use crate::logger::info! instead" },
]
There was a problem hiding this comment.
I think it is worth keeping the _rate_limited suffix for all rate limited logs for consistency
disallowed_macros looks interesting though
| static LIMITER: $crate::logger::rate_limited::LogRateLimiter = | ||
| $crate::logger::rate_limited::LogRateLimiter::new(); | ||
| static SUPPRESSED: std::sync::atomic::AtomicU64 = | ||
| std::sync::atomic::AtomicU64::new(0); |
There was a problem hiding this comment.
this seems to be 88 bytes per callsite, so roughly 14KiB (with roughly 150 callsites) in .bss. I think it's acceptable, just noting it.
There was a problem hiding this comment.
In the future we can shrink TokenBucket to 48 bytes if we replace all u64 to u32 and then here we will get nice 64 bytes per call.
But here maybe switching to AtomicU32/U16 maybe worth since suppressing 64K logs wold be pretty uncommon + we only track this value as a metadata, so even overflow is not an issue.
| pub const fn new() -> Self { | ||
| Self { | ||
| inner: OnceLock::new(), | ||
| } | ||
| } |
There was a problem hiding this comment.
can this take burst and refil_time as args? And then the Default can be implement with new(DEFAULT_BURST, ...)
This way it can be configured if needed, like in the unit test that waits for 5 seconds for no reason.
| static LIMITER: $crate::logger::rate_limited::LogRateLimiter = | ||
| $crate::logger::rate_limited::LogRateLimiter::new(); | ||
| static SUPPRESSED: std::sync::atomic::AtomicU64 = | ||
| std::sync::atomic::AtomicU64::new(0); |
There was a problem hiding this comment.
In the future we can shrink TokenBucket to 48 bytes if we replace all u64 to u32 and then here we will get nice 64 bytes per call.
But here maybe switching to AtomicU32/U16 maybe worth since suppressing 64K logs wold be pretty uncommon + we only track this value as a metadata, so even overflow is not an issue.
| use crate::cpu_config::aarch64::custom_cpu_template::VcpuFeatures; | ||
| use crate::cpu_config::templates::CpuConfiguration; | ||
| use crate::logger::{IncMetric, METRICS, error}; | ||
| use crate::logger::{IncMetric, METRICS, error_rate_limited}; |
There was a problem hiding this comment.
I think it is worth keeping the _rate_limited suffix for all rate limited logs for consistency
disallowed_macros looks interesting though
4 participants
Changes
Add per-callsite rate limiting for guest-triggered logging paths, following the Linux kernel printk_ratelimited pattern. The error_rate_limited! macro gives each callsite its own independent, preconfigured rate limiter set to 10 messages per 5-second window. When messages are suppressed, a summary is emitted once the callsite resumes logging. A new rate_limited_log_count metric tracks total suppressions.
I was not able to build an integration test that demonstrates that the rate limiting is effective against a real end-to-end scenario because it would've required a custom guest kernel, but I ran an ad hoc experiment by inserting an extra
error_rate_limited!line into the ballooninflate descriptor processing loop (hot path) and saw that it was rate-limited from 128 lines to 10 as expected.
Reason
Guest VMs can trigger repeated error!() calls through various virtio device paths (balloon, net, block, PCI, MMIO). Under sustained error conditions, this leads to excessive disk I/O and CPU consumption on the host from synchronous log writes.
License Acceptance
By submitting this pull request, I confirm that my contribution is made under
the terms of the Apache 2.0 license. For more information on following Developer
Certificate of Origin and signing off your commits, please check
CONTRIBUTING.md.PR Checklist
tools/devtool checkbuild --allto verify that the PR passesbuild checks on all supported architectures.
tools/devtool checkstyleto verify that the PR passes theautomated style checks.
how they are solving the problem in a clear and encompassing way.
in the PR.
CHANGELOG.md.Runbook for Firecracker API changes.
integration tests.
TODO.rust-vmm.