Skip to content

firmware_uefi: EfiDiagnostics change to tracelimit with custom period and limit #1706

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 12 commits into from
Jul 17, 2025
Merged

firmware_uefi: EfiDiagnostics change to tracelimit with custom period and limit #1706

Show file tree
Hide file tree
Changes from 3 commits
Commits
Show all changes
12 commits
Select commit Hold shift + click to select a range
b7e3b4c
let tracelimit define custom period and limit
maheeraeron Jul 15, 2025
6358f3f
Use new tracelimit with limit
maheeraeron Jul 15, 2025
f9a9c40
Add runtime support for ratelimiting
maheeraeron Jul 15, 2025
c9cd010
Fix lifetime on handle_efi_diagnostics_log
maheeraeron Jul 16, 2025
2335395
Merge branch 'main' into user/maheeraeron/efidiagnostics-tracing
maheeraeron Jul 16, 2025
bcb95e7
Remove hashmap in rate limiter
maheeraeron Jul 16, 2025
9aec5a1
Use inner mutex, change state in event_with_config(), additional feed…
maheeraeron Jul 16, 2025
de764b9
Merge branch 'main' into user/maheeraeron/efidiagnostics-tracing
maheeraeron Jul 16, 2025
2d26358
Remove unncessary doc hidden
maheeraeron Jul 16, 2025
aab7e8e
Remove shared rate limiter and create a static one for every callsite
maheeraeron Jul 16, 2025
fdc52da
Use only one events_per_period limit value, prevent reprocessing on w…
maheeraeron Jul 16, 2025
39acd25
Change context to triggered_by, output it on success
maheeraeron Jul 16, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
194 changes: 192 additions & 2 deletions support/tracelimit/src/lib.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -17,14 +17,18 @@
#![forbid(unsafe_code)]

use parking_lot::Mutex;
use std::collections::HashMap;
use std::sync::LazyLock;
use std::sync::atomic::AtomicBool;
use std::sync::atomic::Ordering;
use std::time::Instant;
#[doc(hidden)]
pub use tracing;

const PERIOD_MS: u32 = 5000;
const EVENTS_PER_PERIOD: u32 = 10;
#[doc(hidden)]
pub const PERIOD_MS: u32 = 5000;
#[doc(hidden)]
pub const EVENTS_PER_PERIOD: u32 = 10;

static DISABLE_RATE_LIMITING: AtomicBool = AtomicBool::new(false);

Expand Down Expand Up @@ -96,9 +100,95 @@ impl RateLimiter {
}
}

// Runtime rate limiter support
//
// NOTE: We can't use static rate limiters when users pass runtime variables to macros
// The solution is to use a global cache of rate limiters created on-demand
//
// HashMap: Cache rate limiters to preserve state across calls
// Mutex: Thread-safe access to the HashMap
// LazyLock: Initialize HashMap on first use
//
// The keys are (period, limit, call_site) to ensure that each macro location gets
// independent rate limiting.
static RUNTIME_RATE_LIMITERS: LazyLock<Mutex<HashMap<(u32, u32, &'static str), RateLimiter>>> =
LazyLock::new(|| Mutex::new(HashMap::new()));

/// Get or create a runtime rate limiter for the given parameters and call site.
/// This will reuse existing rate limiters if they exist, otherwise create a new one.
#[doc(hidden)]
pub fn get_runtime_rate_limiter(
period_ms: u32,
events_per_period: u32,
call_site: &'static str,
) -> Result<Option<u64>, RateLimited> {
if DISABLE_RATE_LIMITING.load(Ordering::Relaxed) {
return Ok(None);
}

let key = (period_ms, events_per_period, call_site);
let mut limiters = RUNTIME_RATE_LIMITERS.lock();

let limiter = limiters
.entry(key)
.or_insert_with(|| RateLimiter::new(period_ms, events_per_period));

limiter.event()
}

/// As [`tracing::error!`], but rate limited.
///
/// Can be called with optional parameters to customize rate limiting:
/// - `period: <ms>` - rate limiting period in milliseconds
/// - `limit: <count>` - maximum events per period
///
/// Examples:
/// ```
/// use tracelimit::error_ratelimited;
/// error_ratelimited!("simple message");
/// error_ratelimited!(period: 1000, limit: 5, "custom rate limit");
/// error_ratelimited!(period: 10000, "custom period only");
/// error_ratelimited!(limit: 50, "custom limit only");
/// ```
#[macro_export]
macro_rules! error_ratelimited {
// With both period and limit
(period: $period:expr, limit: $limit:expr, $($rest:tt)*) => {
{
if let Ok(missed_events) = $crate::get_runtime_rate_limiter(
$period,
$limit,
concat!(file!(), ":", line!(), ":", column!())
) {
$crate::tracing::error!(dropped_ratelimited = missed_events, $($rest)*);
}
}
};
// With period only
(period: $period:expr, $($rest:tt)*) => {
{
if let Ok(missed_events) = $crate::get_runtime_rate_limiter(
$period,
$crate::EVENTS_PER_PERIOD,
concat!(file!(), ":", line!(), ":", column!())
) {
$crate::tracing::error!(dropped_ratelimited = missed_events, $($rest)*);
}
}
};
// With limit only
(limit: $limit:expr, $($rest:tt)*) => {
{
if let Ok(missed_events) = $crate::get_runtime_rate_limiter(
$crate::PERIOD_MS,
$limit,
concat!(file!(), ":", line!(), ":", column!())
) {
$crate::tracing::error!(dropped_ratelimited = missed_events, $($rest)*);
}
}
};
// Default case (no custom parameters)
($($rest:tt)*) => {
{
static RATE_LIMITER: $crate::RateLimiter = $crate::RateLimiter::new_default();
Expand All @@ -110,8 +200,58 @@ macro_rules! error_ratelimited {
}

/// As [`tracing::warn!`], but rate limited.
///
/// Can be called with optional parameters to customize rate limiting:
/// - `period: <ms>` - rate limiting period in milliseconds
/// - `limit: <count>` - maximum events per period
///
/// Examples:
/// ```
/// use tracelimit::warn_ratelimited;
/// warn_ratelimited!("simple message");
/// warn_ratelimited!(period: 1000, limit: 5, "custom rate limit");
/// warn_ratelimited!(period: 10000, "custom period only");
/// warn_ratelimited!(limit: 50, "custom limit only");
/// ```
#[macro_export]
macro_rules! warn_ratelimited {
// With both period and limit
(period: $period:expr, limit: $limit:expr, $($rest:tt)*) => {
{
if let Ok(missed_events) = $crate::get_runtime_rate_limiter(
$period,
$limit,
concat!(file!(), ":", line!(), ":", column!())
) {
$crate::tracing::warn!(dropped_ratelimited = missed_events, $($rest)*);
}
}
};
// With period only
(period: $period:expr, $($rest:tt)*) => {
{
if let Ok(missed_events) = $crate::get_runtime_rate_limiter(
$period,
$crate::EVENTS_PER_PERIOD,
concat!(file!(), ":", line!(), ":", column!())
) {
$crate::tracing::warn!(dropped_ratelimited = missed_events, $($rest)*);
}
}
};
// With limit only
(limit: $limit:expr, $($rest:tt)*) => {
{
if let Ok(missed_events) = $crate::get_runtime_rate_limiter(
$crate::PERIOD_MS,
$limit,
concat!(file!(), ":", line!(), ":", column!())
) {
$crate::tracing::warn!(dropped_ratelimited = missed_events, $($rest)*);
}
}
};
// Default case (no custom parameters)
($($rest:tt)*) => {
{
static RATE_LIMITER: $crate::RateLimiter = $crate::RateLimiter::new_default();
Expand All @@ -123,8 +263,58 @@ macro_rules! warn_ratelimited {
}

/// As [`tracing::info!`], but rate limited.
///
/// Can be called with optional parameters to customize rate limiting:
/// - `period: <ms>` - rate limiting period in milliseconds
/// - `limit: <count>` - maximum events per period
///
/// Examples:
/// ```
/// use tracelimit::info_ratelimited;
/// info_ratelimited!("simple message");
/// info_ratelimited!(period: 1000, limit: 5, "custom rate limit");
/// info_ratelimited!(period: 10000, "custom period only");
/// info_ratelimited!(limit: 50, "custom limit only");
/// ```
#[macro_export]
macro_rules! info_ratelimited {
// With both period and limit
(period: $period:expr, limit: $limit:expr, $($rest:tt)*) => {
{
if let Ok(missed_events) = $crate::get_runtime_rate_limiter(
$period,
$limit,
concat!(file!(), ":", line!(), ":", column!())
) {
$crate::tracing::info!(dropped_ratelimited = missed_events, $($rest)*);
}
}
};
// With period only
(period: $period:expr, $($rest:tt)*) => {
{
if let Ok(missed_events) = $crate::get_runtime_rate_limiter(
$period,
$crate::EVENTS_PER_PERIOD,
concat!(file!(), ":", line!(), ":", column!())
) {
$crate::tracing::info!(dropped_ratelimited = missed_events, $($rest)*);
}
}
};
// With limit only
(limit: $limit:expr, $($rest:tt)*) => {
{
if let Ok(missed_events) = $crate::get_runtime_rate_limiter(
$crate::PERIOD_MS,
$limit,
concat!(file!(), ":", line!(), ":", column!())
) {
$crate::tracing::info!(dropped_ratelimited = missed_events, $($rest)*);
}
}
};
// Default case (no custom parameters)
($($rest:tt)*) => {
{
static RATE_LIMITER: $crate::RateLimiter = $crate::RateLimiter::new_default();
Expand Down
10 changes: 7 additions & 3 deletions vm/devices/firmware/firmware_uefi/src/lib.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -70,6 +70,8 @@ use local_clock::InspectableLocalClock;
use pal_async::local::block_on;
use platform::logger::UefiLogger;
use platform::nvram::VsmConfig;
use service::diagnostics::DEFAULT_LOGS_PER_PERIOD;
use service::diagnostics::GUEST_LOGS_PER_PERIOD;
use std::convert::TryInto;
use std::ops::RangeInclusive;
use std::task::Context;
Expand Down Expand Up @@ -269,13 +271,15 @@ impl UefiDevice {
tracelimit::info_ratelimited!(?addr, data, "set gpa for diagnostics");
self.service.diagnostics.set_gpa(data)
}
UefiCommand::PROCESS_EFI_DIAGNOSTICS => self.process_diagnostics(false, "guest"),
UefiCommand::PROCESS_EFI_DIAGNOSTICS => {
self.process_diagnostics(false, GUEST_LOGS_PER_PERIOD, "guest")
}
_ => tracelimit::warn_ratelimited!(addr, data, "unknown uefi write"),
}
}

fn inspect_extra(&mut self, _resp: &mut inspect::Response<'_>) {
self.process_diagnostics(true, "inspect_extra");
self.process_diagnostics(true, DEFAULT_LOGS_PER_PERIOD, "inspect_extra");
}
}

Expand Down Expand Up @@ -318,7 +322,7 @@ impl PollDevice for UefiDevice {
// Poll watchdog timeout events
if let Poll::Ready(Ok(())) = self.watchdog_recv.poll_recv(cx) {
tracing::info!("watchdog timeout received");
self.process_diagnostics(true, "watchdog timeout");
self.process_diagnostics(true, DEFAULT_LOGS_PER_PERIOD, "watchdog timeout");
}
}
}
Expand Down
31 changes: 21 additions & 10 deletions vm/devices/firmware/firmware_uefi/src/service/diagnostics.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -32,6 +32,12 @@ use uefi_specs::hyperv::debug_level::DEBUG_FLAG_NAMES;
use uefi_specs::hyperv::debug_level::DEBUG_WARN;
use zerocopy::FromBytes;

/// Default number of logs emitted per period
pub const DEFAULT_LOGS_PER_PERIOD: u32 = 500;

/// Guest specific amount of logs emitted per period
pub const GUEST_LOGS_PER_PERIOD: u32 = 150;

/// 8-byte alignment for every entry
const ALIGNMENT: usize = 8;

Expand Down Expand Up @@ -103,26 +109,29 @@ fn phase_to_string(phase: u16) -> &'static str {
}

/// Defines how we want EfiDiagnosticsLog entries to be handled.
pub fn handle_efi_diagnostics_log<'a>(log: EfiDiagnosticsLog<'a>) {
pub fn handle_efi_diagnostics_log<'a>(log: EfiDiagnosticsLog<'a>, limit: u32) {
let debug_level_str = debug_level_to_string(log.debug_level);
let phase_str = phase_to_string(log.phase);

match log.debug_level {
DEBUG_WARN => tracing::warn!(
DEBUG_WARN => tracelimit::warn_ratelimited!(
limit: limit,
debug_level = %debug_level_str,
ticks = log.ticks,
phase = %phase_str,
log_message = log.message,
"EFI log entry"
),
DEBUG_ERROR => tracing::error!(
DEBUG_ERROR => tracelimit::error_ratelimited!(
limit: limit,
debug_level = %debug_level_str,
ticks = log.ticks,
phase = %phase_str,
log_message = log.message,
"EFI log entry"
),
_ => tracing::info!(
_ => tracelimit::info_ratelimited!(
limit: limit,
debug_level = %debug_level_str,
ticks = log.ticks,
phase = %phase_str,
Expand Down Expand Up @@ -462,12 +471,14 @@ impl UefiDevice {
/// # Arguments
/// * `allow_reprocess` - If true, allows processing even if already processed for guest
/// * `context` - String to indicate who triggered the diagnostics processing
pub(crate) fn process_diagnostics(&mut self, allow_reprocess: bool, context: &str) {
if let Err(error) = self.service.diagnostics.process_diagnostics(
allow_reprocess,
&self.gm,
handle_efi_diagnostics_log,
) {
pub(crate) fn process_diagnostics(&mut self, allow_reprocess: bool, limit: u32, context: &str) {
if let Err(error) =
self.service
.diagnostics
.process_diagnostics(allow_reprocess, &self.gm, |log| {
handle_efi_diagnostics_log(log, limit)
})
{
tracelimit::error_ratelimited!(
error = &error as &dyn std::error::Error,
context,
Expand Down