perf: skip guest tracing work while the log level is off

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
 

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
@@ -532,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
 

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,

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.

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.

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<Weak<Mutex<GuestState>>> = spin::Once::new();
     static GUEST_SUBSCRIBER: spin::Once<Weak<GuestSubscriber>> = 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,25 +76,28 @@ 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.
     pub fn update_guest_tracing(guest_start_tsc: u64, max_log_level: LevelFilter) {
         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)
     }
 }

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<Mutex<GuestState>> {
@@ -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 =

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<Snapshot>` can
         /// each `restore` back to it, and stay memory-isolated from
         /// each other in between.