From abeb25718d14fcbbe03218b3840bd50af47e64d6 Mon Sep 17 00:00:00 2001 From: Jorge Prendes Date: Thu, 17 Sep 2026 17:36:35 +0100 Subject: [PATCH 1/2] perf: skip guest tracing work while the log level is off An off guest log level avoids TSC reads, span setup, trace state locking, and flush plumbing on every guest call. * `is_trace_enabled` and `accepts_trace_events` derive from one relaxed atomic holding the encoded filter. * `register_callsite` caches per-level interest, and a level change rebuilds the interest cache. * `generic_init` and the dispatch path open spans only while tracing is active. Signed-off-by: Jorge Prendes --- CHANGELOG.md | 4 + Justfile | 2 + .../src/guest_handle/host_comm.rs | 4 +- .../src/guest_function/call.rs | 8 +- src/hyperlight_guest_bin/src/lib.rs | 7 +- src/hyperlight_guest_tracing/src/lib.rs | 49 ++++++++--- .../src/subscriber.rs | 30 ++++--- .../src/sandbox/initialized_multi_use.rs | 82 +++++++++++++++++++ 8 files changed, 151 insertions(+), 35 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 058834963..917aef715 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -18,6 +18,10 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.1.0/). * Expose C guest `ByteChunks` values as pointer and length arrays. * Return typed `hl_ReturnValue` objects from C guest functions through `hl_result_from_*` constructors. +* Guest tracing skips its per-call and per-callsite work while the guest log + level is `OFF`. `hyperlight_guest_tracing::is_trace_enabled` reports whether + the configured level is above `OFF` rather than whether the tracing state was + allocated. ### Removed diff --git a/Justfile b/Justfile index 3f65c0a08..5447d696e 100644 --- a/Justfile +++ b/Justfile @@ -245,6 +245,8 @@ test-isolated target=default-target features="" : {{ cargo-cmd }} test {{ if features =="" {''} else if features=="no-default-features" {"--no-default-features" } else {"--no-default-features -F " + features } }} --profile={{ if target == "debug" { "dev" } else { target } }} {{ target-triple-flag }} -p hyperlight-host --lib -- sandbox::initialized_multi_use::tests::from_snapshot::max_guest_log_level_is_honored_from_snapshot --exact --ignored {{ cargo-cmd }} test {{ if features =="" {''} else if features=="no-default-features" {"--no-default-features" } else {"--no-default-features -F " + features } }} --profile={{ if target == "debug" { "dev" } else { target } }} {{ target-triple-flag }} -p hyperlight-host --lib -- sandbox::initialized_multi_use::tests::from_snapshot::max_guest_log_level_overrides_initialized_snapshot --exact --ignored {{ cargo-cmd }} test {{ if features =="" {''} else if features=="no-default-features" {"--no-default-features" } else {"--no-default-features -F " + features } }} --profile={{ if target == "debug" { "dev" } else { target } }} {{ target-triple-flag }} -p hyperlight-host --lib -- sandbox::initialized_multi_use::tests::from_snapshot::max_guest_log_level_setter_survives_restore --exact --ignored + {{ cargo-cmd }} test {{ if features =="" {''} else if features=="no-default-features" {"--no-default-features" } else {"--no-default-features -F " + features } }} --profile={{ if target == "debug" { "dev" } else { target } }} {{ target-triple-flag }} -p hyperlight-host --lib -- sandbox::initialized_multi_use::tests::from_snapshot::max_guest_log_level_can_be_disabled_and_reenabled --exact --ignored + {{ cargo-cmd }} test {{ if features =="" {''} else if features=="no-default-features" {"--no-default-features" } else {"--no-default-features -F " + features } }} --profile={{ if target == "debug" { "dev" } else { target } }} {{ target-triple-flag }} -p hyperlight-host --lib -- sandbox::initialized_multi_use::tests::from_snapshot::max_guest_log_level_can_be_enabled_after_off_init --exact --ignored {{ cargo-cmd }} test {{ if features =="" {''} else if features=="no-default-features" {"--no-default-features" } else {"--no-default-features -F " + features } }} --profile={{ if target == "debug" { "dev" } else { target } }} {{ target-triple-flag }} -p hyperlight-host --test integration_test -- log_message --exact --ignored @# CPU vendor check, gated to known CI runner hardware {{ cargo-cmd }} test {{ if features =="" {''} else if features=="no-default-features" {"--no-default-features" } else {"--no-default-features -F " + features } }} --profile={{ if target == "debug" { "dev" } else { target } }} {{ target-triple-flag }} -p hyperlight-host --lib -- sandbox::snapshot::file::config::tests::cpu_vendor_current_is_recognized --exact --ignored diff --git a/src/hyperlight_guest/src/guest_handle/host_comm.rs b/src/hyperlight_guest/src/guest_handle/host_comm.rs index 2776ed8c5..684330ecc 100644 --- a/src/hyperlight_guest/src/guest_handle/host_comm.rs +++ b/src/hyperlight_guest/src/guest_handle/host_comm.rs @@ -173,9 +173,7 @@ impl GuestHandle { }; #[cfg(all(feature = "trace_guest", target_arch = "x86_64"))] - if hyperlight_guest_tracing::is_trace_enabled() - && hyperlight_guest_tracing::accepts_trace_events() - { + if hyperlight_guest_tracing::accepts_trace_events() { // If the "trace_guest" feature is enabled and tracing is initialized, log using tracing tracing::trace!( event = message, diff --git a/src/hyperlight_guest_bin/src/guest_function/call.rs b/src/hyperlight_guest_bin/src/guest_function/call.rs index 8ae69bfeb..9f0644443 100644 --- a/src/hyperlight_guest_bin/src/guest_function/call.rs +++ b/src/hyperlight_guest_bin/src/guest_function/call.rs @@ -78,14 +78,14 @@ pub(crate) fn internal_dispatch_function() { // Read the current TSC to report it to the host with the spans/events // This helps calculating the timestamps relative to the guest call #[cfg(all(feature = "trace_guest", target_arch = "x86_64"))] - let _entered = { + let entered = hyperlight_guest_tracing::is_trace_enabled().then(|| { let guest_start_tsc = hyperlight_guest_tracing::invariant_tsc::read_tsc(); // Reset the trace state for the new guest function call with the new start TSC // This clears any existing spans/events from previous calls ensuring a clean state hyperlight_guest_tracing::new_call(guest_start_tsc); tracing::span!(tracing::Level::INFO, "internal_dispatch_function").entered() - }; + }); let handle = unsafe { GUEST_HANDLE }; @@ -126,7 +126,9 @@ pub(crate) fn internal_dispatch_function() { // spans, when preparing to close a guest function call context. // It is not mandatory, though, but avoids a warning on the host that alerts a spans // that has not been opened but is being closed. - _entered.exit(); + if let Some(entered) = entered { + entered.exit(); + } // Ensure that any tracing output during the call is flushed to // the host, if necessary. diff --git a/src/hyperlight_guest_bin/src/lib.rs b/src/hyperlight_guest_bin/src/lib.rs index 6e71421b9..054dd9e3b 100644 --- a/src/hyperlight_guest_bin/src/lib.rs +++ b/src/hyperlight_guest_bin/src/lib.rs @@ -310,7 +310,8 @@ pub(crate) extern "C" fn generic_init( // This is done here because the tracing subscriber is initialized and the guest is in a // well-known state #[cfg(all(feature = "trace_guest", target_arch = "x86_64"))] - let _entered = tracing::span!(tracing::Level::INFO, "generic_init").entered(); + let entered = hyperlight_guest_tracing::is_trace_enabled() + .then(|| tracing::span!(tracing::Level::INFO, "generic_init").entered()); #[cfg(feature = "macros")] for registration in __private::GUEST_FUNCTION_INIT { @@ -329,7 +330,9 @@ pub(crate) extern "C" fn generic_init( // spans, when preparing to close a guest function call context. // It is not mandatory, though, but avoids a warning on the host that alerts a spans // that has not been opened but is being closed. - _entered.exit(); + if let Some(entered) = entered { + entered.exit(); + } // Ensure that any tracing output from the initialisation phase is // flushed to the host, if necessary. diff --git a/src/hyperlight_guest_tracing/src/lib.rs b/src/hyperlight_guest_tracing/src/lib.rs index 0fa8f0c3f..8ec1840a5 100644 --- a/src/hyperlight_guest_tracing/src/lib.rs +++ b/src/hyperlight_guest_tracing/src/lib.rs @@ -35,7 +35,9 @@ pub use trace::{ mod trace { extern crate alloc; use alloc::sync::{Arc, Weak}; + use core::sync::atomic::{AtomicU64, Ordering}; + use hyperlight_common::log_level::GuestLogFilter; use spin::Mutex; use tracing_core::LevelFilter; @@ -50,6 +52,16 @@ mod trace { /// The mutex ensures safe access to the state from both places. static GUEST_STATE: spin::Once>> = spin::Once::new(); static GUEST_SUBSCRIBER: spin::Once> = spin::Once::new(); + /// Mirrors the subscriber filter as an encoded [`GuestLogFilter`] so hot paths + /// do not have to upgrade `GUEST_SUBSCRIBER`. + static MAX_LOG_FILTER: AtomicU64 = AtomicU64::new(0); + + fn store_max_log_filter(max_log_level: LevelFilter) { + MAX_LOG_FILTER.store( + u64::from(GuestLogFilter::from(max_log_level)), + Ordering::Relaxed, + ); + } /// Initialize the guest tracing subscriber as global default. pub fn init_guest_tracing(guest_start_tsc: u64, max_log_level: LevelFilter) { @@ -64,7 +76,9 @@ mod trace { GUEST_SUBSCRIBER.call_once(|| Arc::downgrade(&sub)); // Set global dispatcher - let _ = tracing_core::dispatcher::set_global_default(tracing_core::Dispatch::new(sub)); + if tracing_core::dispatcher::set_global_default(tracing_core::Dispatch::new(sub)).is_ok() { + store_max_log_filter(max_log_level); + } } /// Update the maximum log level for an existing guest tracing subscriber. @@ -72,17 +86,18 @@ mod trace { if let Some(w) = GUEST_SUBSCRIBER.get() && let Some(subscriber) = w.upgrade() { - subscriber.set_max_log_level(max_log_level); + let changed = subscriber.set_max_log_level(max_log_level); + store_max_log_filter(max_log_level); + if changed { + tracing_core::callsite::rebuild_interest_cache(); + } } else if max_log_level != LevelFilter::OFF { init_guest_tracing(guest_start_tsc, max_log_level); } } pub fn accepts_trace_events() -> bool { - GUEST_SUBSCRIBER - .get() - .and_then(Weak::upgrade) - .is_some_and(|subscriber| subscriber.accepts_trace_events()) + MAX_LOG_FILTER.load(Ordering::Relaxed) == u64::from(GuestLogFilter::Trace) } /// Ends the current trace by ending all active spans in the @@ -94,6 +109,9 @@ mod trace { /// /// NOTE: Panics if unable to lock the guest state. pub fn end_trace() { + if !is_trace_enabled() { + return; + } if let Some(w) = GUEST_STATE.get() && let Some(state_mutex) = w.upgrade() { @@ -118,6 +136,9 @@ mod trace { /// Flushes the current trace data to prepare it for reading by the host. /// NOTE: Panics if unable to lock the guest state. pub fn flush() { + if !is_trace_enabled() { + return; + } if let Some(w) = GUEST_STATE.get() && let Some(state_mutex) = w.upgrade() { @@ -144,6 +165,9 @@ mod trace { /// This clears any existing spans/events from previous calls ensuring a clean state. /// NOTE: Panics if unable to lock the guest state. pub fn new_call(guest_start_tsc: u64) { + if !is_trace_enabled() { + return; + } if let Some(w) = GUEST_STATE.get() && let Some(state_mutex) = w.upgrade() { @@ -171,6 +195,9 @@ mod trace { /// are still active (in the stack) and remove all other spans and events. /// NOTE: Panics if unable to lock the guest state. pub fn reset() { + if !is_trace_enabled() { + return; + } if let Some(w) = GUEST_STATE.get() && let Some(state_mutex) = w.upgrade() { @@ -195,6 +222,9 @@ mod trace { /// Returns information about the current trace state needed by the host to read the spans. pub fn serialized_data() -> Option<(u64, u64)> { + if !is_trace_enabled() { + return None; + } if let Some(w) = GUEST_STATE.get() && let Some(state_mutex) = w.upgrade() { @@ -219,11 +249,8 @@ mod trace { } } - /// Returns true if tracing is enabled (the guest tracing state is initialized). + /// Returns whether guest tracing is active at the configured level. pub fn is_trace_enabled() -> bool { - GUEST_STATE - .get() - .map(|w| w.upgrade().is_some()) - .unwrap_or(false) + MAX_LOG_FILTER.load(Ordering::Relaxed) != u64::from(GuestLogFilter::Off) } } diff --git a/src/hyperlight_guest_tracing/src/subscriber.rs b/src/hyperlight_guest_tracing/src/subscriber.rs index 95fece9a8..c244da02d 100644 --- a/src/hyperlight_guest_tracing/src/subscriber.rs +++ b/src/hyperlight_guest_tracing/src/subscriber.rs @@ -33,14 +33,12 @@ impl GuestSubscriber { } } - pub(crate) fn set_max_log_level(&self, filter: LevelFilter) { - self.max_log_level - .store(u64::from(GuestLogFilter::from(filter)), Ordering::Relaxed); + /// Returns whether the filter changed. + pub(crate) fn set_max_log_level(&self, filter: LevelFilter) -> bool { + let filter = u64::from(GuestLogFilter::from(filter)); + self.max_log_level.swap(filter, Ordering::Relaxed) != filter } - pub(crate) fn accepts_trace_events(&self) -> bool { - self.max_log_level.load(Ordering::Relaxed) == u64::from(GuestLogFilter::Trace) - } /// Returns a reference to the internal state of the subscriber /// This is used to access the spans and events collected by the subscriber pub(crate) fn state(&self) -> &Arc> { @@ -49,8 +47,12 @@ impl GuestSubscriber { } impl Subscriber for GuestSubscriber { - fn register_callsite(&self, _: &'static Metadata<'static>) -> Interest { - Interest::sometimes() + fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { + if self.enabled(metadata) { + Interest::always() + } else { + Interest::never() + } } fn enabled(&self, md: &Metadata<'_>) -> bool { @@ -210,19 +212,15 @@ mod tests { } #[test] - fn callsite_interest_is_rechecked_after_filter_updates() { + fn callsite_interest_tracks_filter_updates() { let subscriber = GuestSubscriber::new(0, LevelFilter::ERROR); - assert!( - subscriber - .register_callsite(&CALLSITE_METADATA) - .is_sometimes() - ); + assert!(subscriber.register_callsite(&CALLSITE_METADATA).is_never()); subscriber.set_max_log_level(LevelFilter::TRACE); - assert!(subscriber.enabled(&CALLSITE_METADATA)); + assert!(subscriber.register_callsite(&CALLSITE_METADATA).is_always()); subscriber.set_max_log_level(LevelFilter::ERROR); - assert!(!subscriber.enabled(&CALLSITE_METADATA)); + assert!(subscriber.register_callsite(&CALLSITE_METADATA).is_never()); } static CALLSITE: tracing_core::callsite::DefaultCallsite = diff --git a/src/hyperlight_host/src/sandbox/initialized_multi_use.rs b/src/hyperlight_host/src/sandbox/initialized_multi_use.rs index 46491e161..029d17847 100644 --- a/src/hyperlight_host/src/sandbox/initialized_multi_use.rs +++ b/src/hyperlight_host/src/sandbox/initialized_multi_use.rs @@ -4889,6 +4889,88 @@ mod tests { assert_eq!(before_restore, after_restore); } + /// Runtime log-level updates can disable and re-enable guest tracing. + /// + /// Ignored because it installs a process-global `log` logger. Run in + /// isolation via the `test-isolated` Justfile recipe. + #[test] + #[ignore] + fn max_guest_log_level_can_be_disabled_and_reenabled() { + use hyperlight_common::log_level::GuestLogFilter; + use hyperlight_testing::logger::{LOGGER, Logger}; + use tracing_core::LevelFilter; + + Logger::initialize_test_logger(); + LOGGER.set_max_level(log::LevelFilter::Trace); + + let mut sandbox = SandboxBuilder::from_file(simple_guest_as_pathbuf()) + .guest_log_level(LevelFilter::TRACE) + .build() + .unwrap(); + let encoded: u64 = GuestLogFilter::Trace.into(); + let count_guest_logs = |sandbox: &mut MultiUseSandbox| { + LOGGER.clear_log_calls(); + sandbox + .call::<()>("LogMessage", ("hello".to_string(), encoded as i32)) + .unwrap(); + (0..LOGGER.num_log_calls()) + .filter_map(|i| LOGGER.get_log_call(i)) + .filter(|call| call.target == "hyperlight_guest") + .count() + }; + + assert!(count_guest_logs(&mut sandbox) > 0); + sandbox.log_level(LevelFilter::OFF).unwrap(); + assert_eq!(count_guest_logs(&mut sandbox), 0); + sandbox.log_level(LevelFilter::TRACE).unwrap(); + assert!(count_guest_logs(&mut sandbox) > 0); + } + + /// Callsites reached while the guest runs at `OFF` still produce trace + /// data once the level is raised, matching a guest started at `TRACE`. + /// + /// Ignored because it installs a process-global `log` logger. Run in + /// isolation via the `test-isolated` Justfile recipe. + #[test] + #[ignore] + fn max_guest_log_level_can_be_enabled_after_off_init() { + use hyperlight_common::log_level::GuestLogFilter; + use hyperlight_testing::logger::{LOGGER, Logger}; + use tracing_core::LevelFilter; + + Logger::initialize_test_logger(); + LOGGER.set_max_level(log::LevelFilter::Trace); + + let encoded: u64 = GuestLogFilter::Trace.into(); + let count_guest_logs = |sandbox: &mut MultiUseSandbox| { + LOGGER.clear_log_calls(); + sandbox + .call::<()>("LogMessage", ("hello".to_string(), encoded as i32)) + .unwrap(); + (0..LOGGER.num_log_calls()) + .filter_map(|i| LOGGER.get_log_call(i)) + .filter(|call| call.target == "hyperlight_guest") + .count() + }; + + let mut from_trace = SandboxBuilder::from_file(simple_guest_as_pathbuf()) + .guest_log_level(LevelFilter::TRACE) + .build() + .unwrap(); + let _ = count_guest_logs(&mut from_trace); + let expected = count_guest_logs(&mut from_trace); + + let mut from_off = SandboxBuilder::from_file(simple_guest_as_pathbuf()) + .guest_log_level(LevelFilter::OFF) + .build() + .unwrap(); + // Runs the guest at OFF so its callsites cache a disabled interest. + assert_eq!(count_guest_logs(&mut from_off), 0); + + from_off.log_level(LevelFilter::TRACE).unwrap(); + assert_eq!(count_guest_logs(&mut from_off), expected); + } + /// Two sandboxes built from clones of one `Arc` can /// each `restore` back to it, and stay memory-isolated from /// each other in between. From f77b85bb7e06a60ff007d1663528c61c065d6f21 Mon Sep 17 00:00:00 2001 From: Jorge Prendes Date: Thu, 17 Sep 2026 22:52:41 +0100 Subject: [PATCH 2/2] test: run guest log level transition tests under coverage `coverage-run` carries its own isolated test list, so it names the disable and re-enable test and the off init test alongside the other guest log level tests. Signed-off-by: Jorge Prendes --- Justfile | 2 ++ 1 file changed, 2 insertions(+) diff --git a/Justfile b/Justfile index 5447d696e..9d42e66cb 100644 --- a/Justfile +++ b/Justfile @@ -534,6 +534,8 @@ coverage-run hypervisor="kvm": ensure-cargo-llvm-cov cargo +nightly test -p hyperlight-host --lib -- sandbox::initialized_multi_use::tests::from_snapshot::max_guest_log_level_is_honored_from_snapshot --exact --ignored cargo +nightly test -p hyperlight-host --lib -- sandbox::initialized_multi_use::tests::from_snapshot::max_guest_log_level_overrides_initialized_snapshot --exact --ignored cargo +nightly test -p hyperlight-host --lib -- sandbox::initialized_multi_use::tests::from_snapshot::max_guest_log_level_setter_survives_restore --exact --ignored + cargo +nightly test -p hyperlight-host --lib -- sandbox::initialized_multi_use::tests::from_snapshot::max_guest_log_level_can_be_disabled_and_reenabled --exact --ignored + cargo +nightly test -p hyperlight-host --lib -- sandbox::initialized_multi_use::tests::from_snapshot::max_guest_log_level_can_be_enabled_after_off_init --exact --ignored cargo +nightly test -p hyperlight-host --test integration_test -- log_message --exact --ignored cargo +nightly test -p hyperlight-host --no-default-features -F function_call_metrics,{{ if hypervisor == "mshv3" { "mshv3" } else { "kvm" } }} --lib -- metrics::tests::test_metrics_are_emitted --exact