diff --git a/.github/workflows/CargoPublish.yml b/.github/workflows/CargoPublish.yml index 0c4ad8304..6652ca710 100644 --- a/.github/workflows/CargoPublish.yml +++ b/.github/workflows/CargoPublish.yml @@ -85,13 +85,6 @@ jobs: CARGO_REGISTRY_TOKEN: ${{ secrets.CARGO_PUBLISH_TOKEN }} if: env.PUBLISH_HYPERLIGHT_COMMON != 'false' - - name: Publish hyperlight-guest-tracing-macro - continue-on-error: ${{ inputs.dry_run }} - run: cargo publish --manifest-path ./src/hyperlight_guest_tracing_macro/Cargo.toml ${{ inputs.dry_run && '--dry-run' || '' }} - env: - CARGO_REGISTRY_TOKEN: ${{ secrets.CARGO_PUBLISH_TOKEN }} - if: env.PUBLISH_HYPERLIGHT_GUEST_TRACING_MACRO != 'false' - - name: Publish hyperlight-guest-tracing continue-on-error: ${{ inputs.dry_run }} run: cargo publish --manifest-path ./src/hyperlight_guest_tracing/Cargo.toml ${{ inputs.dry_run && '--dry-run' || '' }} diff --git a/.github/workflows/dep_rust.yml b/.github/workflows/dep_rust.yml index 25777ca43..2c096ddc2 100644 --- a/.github/workflows/dep_rust.yml +++ b/.github/workflows/dep_rust.yml @@ -137,7 +137,7 @@ jobs: cargo check -p hyperlight-host --features crashdump cargo check -p hyperlight-host --features print_debug cargo check -p hyperlight-host --features gdb - cargo check -p hyperlight-host --features trace_guest,unwind_guest,mem_profile + cargo check -p hyperlight-host --features trace_guest,mem_profile # without any features just test-compilation-no-default-features ${{ matrix.config }} diff --git a/Cargo.lock b/Cargo.lock index 7b95df4d7..baf69fa67 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1209,6 +1209,25 @@ dependencies = [ "scroll", ] +[[package]] +name = "h2" +version = "0.4.12" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f3c0b69cfcb4e1b9f1bf2f53f95f766e4661169728ec61cd3fe5a0166f2d1386" +dependencies = [ + "atomic-waker", + "bytes", + "fnv", + "futures-core", + "futures-sink", + "http", + "indexmap", + "slab", + "tokio", + "tokio-util", + "tracing", +] + [[package]] name = "half" version = "2.6.0" @@ -1219,6 +1238,15 @@ dependencies = [ "crunchy", ] +[[package]] +name = "hash32" +version = "0.3.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "47d60b12902ba28e2730cd37e95b8c9223af2808df9e902d4df49588d1470606" +dependencies = [ + "byteorder", +] + [[package]] name = "hashbrown" version = "0.15.5" @@ -1229,6 +1257,17 @@ dependencies = [ "serde", ] +[[package]] +name = "heapless" +version = "0.8.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "0bfb9eb618601c89945a70e254898da93b13be0388091d42117462b265bb3fad" +dependencies = [ + "hash32", + "serde", + "stable_deref_trait", +] + [[package]] name = "heck" version = "0.5.0" @@ -1291,6 +1330,7 @@ dependencies = [ "bytes", "futures-channel", "futures-core", + "h2", "http", "http-body", "httparse", @@ -1302,6 +1342,19 @@ dependencies = [ "want", ] +[[package]] +name = "hyper-timeout" +version = "0.5.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "2b90d566bffbce6a75bd8b09a05aa8c2cb1fabb6cb348f8840c9e4c90a0d83b0" +dependencies = [ + "hyper", + "hyper-util", + "pin-project-lite", + "tokio", + "tower-service", +] + [[package]] name = "hyper-util" version = "0.1.16" @@ -1384,6 +1437,7 @@ dependencies = [ "hyperlight-common", "hyperlight-guest-tracing", "serde_json", + "tracing", ] [[package]] @@ -1399,24 +1453,18 @@ dependencies = [ "hyperlight-guest-tracing", "log", "spin 0.10.0", + "tracing", ] [[package]] name = "hyperlight-guest-tracing" version = "0.9.0" dependencies = [ + "heapless", "hyperlight-common", - "hyperlight-guest-tracing-macro", "spin 0.10.0", -] - -[[package]] -name = "hyperlight-guest-tracing-macro" -version = "0.9.0" -dependencies = [ - "proc-macro2", - "quote", - "syn", + "tracing", + "tracing-core", ] [[package]] @@ -2235,6 +2283,8 @@ dependencies = [ "prost", "reqwest", "thiserror 2.0.16", + "tokio", + "tonic", ] [[package]] @@ -3407,6 +3457,19 @@ dependencies = [ "tokio", ] +[[package]] +name = "tokio-util" +version = "0.7.16" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "14307c986784f72ef81c89db7d9e28d6ac26d16213b109ea501696195e6e3ce5" +dependencies = [ + "bytes", + "futures-core", + "futures-sink", + "pin-project-lite", + "tokio", +] + [[package]] name = "toml" version = "0.8.23" @@ -3460,10 +3523,15 @@ dependencies = [ "http", "http-body", "http-body-util", + "hyper", + "hyper-timeout", + "hyper-util", "percent-encoding", "pin-project", "prost", + "tokio", "tokio-stream", + "tower", "tower-layer", "tower-service", "tracing", @@ -3477,11 +3545,15 @@ checksum = "d039ad9159c98b70ecfd540b2573b97f7f52c3e8d9f8ad57a24b916a536975f9" dependencies = [ "futures-core", "futures-util", + "indexmap", "pin-project-lite", + "slab", "sync_wrapper", "tokio", + "tokio-util", "tower-layer", "tower-service", + "tracing", ] [[package]] diff --git a/Cargo.toml b/Cargo.toml index 8bccc53d3..ef5d332f5 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -11,7 +11,6 @@ members = [ "src/hyperlight_host", "src/hyperlight_guest_capi", "src/hyperlight_guest_tracing", - "src/hyperlight_guest_tracing_macro", "src/hyperlight_testing", "fuzz", "src/hyperlight_guest_bin", @@ -42,7 +41,6 @@ hyperlight-guest = { path = "src/hyperlight_guest", version = "0.9.0", default-f hyperlight-guest-bin = { path = "src/hyperlight_guest_bin", version = "0.9.0", default-features = false } hyperlight-testing = { path = "src/hyperlight_testing", default-features = false } hyperlight-guest-tracing = { path = "src/hyperlight_guest_tracing", version = "0.9.0", default-features = false } -hyperlight-guest-tracing-macro = { path = "src/hyperlight_guest_tracing_macro", version = "0.9.0", default-features = false } hyperlight-component-util = { path = "src/hyperlight_component_util", version = "0.9.0", default-features = false } hyperlight-component-macro = { path = "src/hyperlight_component_macro", version = "0.9.0", default-features = false } diff --git a/Justfile b/Justfile index 6e8218958..55d7826f1 100644 --- a/Justfile +++ b/Justfile @@ -78,7 +78,7 @@ test-like-ci config=default-target hypervisor="kvm": cargo check -p hyperlight-host --features crashdump cargo check -p hyperlight-host --features print_debug cargo check -p hyperlight-host --features gdb - cargo check -p hyperlight-host --features trace_guest,unwind_guest,mem_profile + cargo check -p hyperlight-host --features trace_guest,mem_profile @# without any driver (should fail to compile) just test-compilation-no-default-features {{config}} @@ -194,20 +194,10 @@ test-rust-crashdump target=default-target features="": test-rust-tracing target=default-target features="": # Run tests for the tracing guest and macro cargo test -p hyperlight-guest-tracing --profile={{ if target == "debug" { "dev" } else { target } }} - cargo test -p hyperlight-guest-tracing-macro --profile={{ if target == "debug" { "dev" } else { target } }} - # Prepare the tracing guest for testing + # Build the tracing guest to ensure it builds with the tracing feature just build-rust-guests {{ target }} trace_guest just move-rust-guests {{ target }} - # Run hello-world example with tracing enabled to get the trace output - TRACE_OUTPUT="$(cargo run --profile={{ if target == "debug" { "dev" } else { target } }} --example hello-world --features {{ if features =="" {"trace_guest"} else { "trace_guest," + features } }})" && \ - TRACE_FILE="$(echo "$TRACE_OUTPUT" | grep -oE 'Creating trace file at: [^ ]+' | awk -F': ' '{print $2}')" && \ - echo "$TRACE_OUTPUT" && \ - if [ -z "$TRACE_FILE" ]; then \ - echo "Error: Could not extract trace file path from output." >&2 ; \ - exit 1 ; \ - fi && \ - cargo run -p trace_dump ./{{ simpleguest_source }}/{{ target }}/simpleguest "$TRACE_FILE" list_frames # Rebuild the tracing guests without the tracing feature # This is to ensure that the tracing feature does not affect the other tests diff --git a/docs/hyperlight-metrics-logs-and-traces.md b/docs/hyperlight-metrics-logs-and-traces.md index 7b90be74e..16c64ab50 100644 --- a/docs/hyperlight-metrics-logs-and-traces.md +++ b/docs/hyperlight-metrics-logs-and-traces.md @@ -94,12 +94,11 @@ Once the container or the exe is running, the trace output can be viewed in the ## Guest Tracing, Unwinding, and Memory Profiling -Hyperlight provides advanced observability features for guest code running inside micro virtual machines. You can enable guest-side tracing, stack unwinding, and memory profiling using the `trace_guest`, `unwind_guest`, and `mem_profile` features. This section explains how to build, run, and inspect guest traces. +Hyperlight provides advanced observability features for guest code running inside micro virtual machines. You can enable guest-side tracing, stack unwinding, and memory profiling using the `trace_guest` and `mem_profile` features. This section explains how to build, run, and inspect guest traces. The following features are available for guest tracing: - `trace_guest`: Enables tracing for guest code, capturing function calls and execution time. -- `unwind_guest`: Enables stack unwinding for guest code, allowing you to capture stack traces. -- `mem_profile`: Enables memory profiling for guest code, capturing memory allocations and usage. +- `mem_profile`: Enables memory profiling for guest code with stack unwinding, capturing memory allocations and usage. ### Building a Guest with Tracing Support @@ -112,17 +111,29 @@ just move-rust-guests debug This will build the guest binaries with the `trace_guest` feature enabled and move them to the appropriate location for use by the host. +**NOTE**: To enable the tracing in your application you need to use the `trace_guest` feature on the `hyperlight-guest-bin` and `hyperlight-guest` crates. + ### Running a Hyperlight Example with Guest Tracing Once the guest is built, you can run a Hyperlight example with guest tracing enabled. For example: ```bash -cargo run --example hello-world --features trace_guest +RUST_LOG="info,hyperlight_host::sandbox=info,hyperlight_guest=trace,hyperlight_guest_bin=trace" cargo run --example tracing-otlp --features trace_guest ``` -This will execute the `hello-world` example, loading the guest with tracing enabled. During execution, trace data will be collected and written to a file in the `trace` directory. +This will execute the `tracing-otlp` example, loading the guest with tracing enabled. +During execution, trace data will be collected on the host and exported as opentelemetry spans/events. + +You can set up a collector to gather all the traces and inspect the traces from both host and guests. + +Due to the nature of execution inside a Sandbox, on a call basis, the guest tracing sets up a stack of spans to keep track of the correct parents for the incoming +guest spans. +We start with `call-to-guest` which contains all the spans coming from a guest. Additionally, for each exit into the host, we add another layer marking it with +a `call-to-host` span to follow the execution in the host and correctly set it as a child of the active span in the guest. +This logic simulates the propagation of Opentelemetry context that is usually done between two services, but cannot be done here seamlessly because the guest side +runs `no_std` which `opentelemetry` doesn't know. -### Inspecting Guest Trace Files +### Inspecting Guest memory Trace Files (for mem_profile) To inspect the trace file generated by the guest, use the `trace_dump` crate. You will need the path to the guest symbols and the trace file. Run the following command: @@ -140,7 +151,7 @@ This command will list the stack frames and tracing information captured during cargo run -p trace_dump ./src/tests/rust_guests/bin/debug/simpleguest ./trace/.trace list_frames ``` -You can use additional features such as `unwind_guest` and `mem_profile` by enabling them during the build and run steps. +You can use the `mem_profile` additional feature by enabling them during the build and run steps. > **Note:** Make sure to follow the build and run steps in order, and ensure that the guest binaries are up to date before running the host example. diff --git a/src/hyperlight_common/Cargo.toml b/src/hyperlight_common/Cargo.toml index 06f6b8472..4712f43ee 100644 --- a/src/hyperlight_common/Cargo.toml +++ b/src/hyperlight_common/Cargo.toml @@ -26,7 +26,6 @@ spin = "0.10.0" default = ["tracing"] fuzzing = ["dep:arbitrary"] trace_guest = [] -unwind_guest = [] mem_profile = [] std = [] diff --git a/src/hyperlight_common/src/outb.rs b/src/hyperlight_common/src/outb.rs index 6211c8cf1..1be3e0a37 100644 --- a/src/hyperlight_common/src/outb.rs +++ b/src/hyperlight_common/src/outb.rs @@ -90,23 +90,20 @@ impl TryFrom for Exception { /// - CallFunction: makes a call to a host function, /// - Abort: aborts the execution of the guest, /// - DebugPrint: prints a message to the host -/// - TraceRecordStack: records the stack trace of the guest +/// - TraceBatch: reports a batch of spans and vents from the guest /// - TraceMemoryAlloc: records memory allocation events /// - TraceMemoryFree: records memory deallocation events -/// - TraceRecord: records a trace event in the guest pub enum OutBAction { Log = 99, CallFunction = 101, Abort = 102, DebugPrint = 103, - #[cfg(feature = "unwind_guest")] - TraceRecordStack = 104, + #[cfg(feature = "trace_guest")] + TraceBatch = 104, #[cfg(feature = "mem_profile")] TraceMemoryAlloc = 105, #[cfg(feature = "mem_profile")] TraceMemoryFree = 106, - #[cfg(feature = "trace_guest")] - TraceRecord = 107, } impl TryFrom for OutBAction { @@ -117,14 +114,12 @@ impl TryFrom for OutBAction { 101 => Ok(OutBAction::CallFunction), 102 => Ok(OutBAction::Abort), 103 => Ok(OutBAction::DebugPrint), - #[cfg(feature = "unwind_guest")] - 104 => Ok(OutBAction::TraceRecordStack), + #[cfg(feature = "trace_guest")] + 104 => Ok(OutBAction::TraceBatch), #[cfg(feature = "mem_profile")] 105 => Ok(OutBAction::TraceMemoryAlloc), #[cfg(feature = "mem_profile")] 106 => Ok(OutBAction::TraceMemoryFree), - #[cfg(feature = "trace_guest")] - 107 => Ok(OutBAction::TraceRecord), _ => Err(anyhow::anyhow!("Invalid OutBAction value: {}", val)), } } diff --git a/src/hyperlight_guest/Cargo.toml b/src/hyperlight_guest/Cargo.toml index ecc516241..d5aa2b40a 100644 --- a/src/hyperlight_guest/Cargo.toml +++ b/src/hyperlight_guest/Cargo.toml @@ -17,6 +17,7 @@ serde_json = { version = "1.0", default-features = false, features = ["alloc"] } hyperlight-common = { workspace = true } hyperlight-guest-tracing = { workspace = true, default-features = false } flatbuffers = { version= "25.2.10", default-features = false } +tracing = { version = "0.1.41", default-features = false, features = ["attributes"] } [features] default = [] diff --git a/src/hyperlight_guest/src/exit.rs b/src/hyperlight_guest/src/exit.rs index a64ae390a..39531b46a 100644 --- a/src/hyperlight_guest/src/exit.rs +++ b/src/hyperlight_guest/src/exit.rs @@ -18,26 +18,53 @@ use core::arch::asm; use core::ffi::{CStr, c_char}; use hyperlight_common::outb::OutBAction; +use tracing::{Span, instrument}; /// Halt the execution of the guest and returns control to the host. #[inline(never)] -#[hyperlight_guest_tracing::trace_function] +#[instrument(skip_all, parent = Span::current(), level= "Trace")] pub fn halt() { - // Ensure all tracing data is flushed before halting - hyperlight_guest_tracing::flush!(); - unsafe { asm!("hlt", options(nostack)) } + #[cfg(feature = "trace_guest")] + { + // End any ongoing trace before halting + hyperlight_guest_tracing::end_trace(); + // If tracing is enabled, we need to pass the trace batch info + // along with the halt instruction so the host can retrieve it + if let Some(tbi) = hyperlight_guest_tracing::guest_trace_info() { + unsafe { + asm!("hlt", + in("r8") OutBAction::TraceBatch as u64, + in("r9") tbi.guest_start_tsc, + in("r10") tbi.spans_ptr, + in("r11") tbi.events_ptr, + options(nostack) + ) + }; + hyperlight_guest_tracing::clean_trace_state(); + } else { + // If tracing is not enabled, we can directly halt + unsafe { asm!("hlt", options(nostack)) }; + } + } + + #[cfg(not(feature = "trace_guest"))] + { + // If tracing is not enabled, we can directly halt + unsafe { asm!("hlt", options(nostack)) }; + } } /// Exits the VM with an Abort OUT action and code 0. #[unsafe(no_mangle)] -#[hyperlight_guest_tracing::trace_function] pub extern "C" fn abort() -> ! { abort_with_code(&[0, 0xFF]) } /// Exits the VM with an Abort OUT action and a specific code. -#[hyperlight_guest_tracing::trace_function] pub fn abort_with_code(code: &[u8]) -> ! { + // End any ongoing trace before aborting + #[cfg(feature = "trace_guest")] + hyperlight_guest_tracing::end_trace(); outb(OutBAction::Abort as u16, code); outb(OutBAction::Abort as u16, &[0xFF]); // send abort terminator (if not included in code) unreachable!() @@ -47,8 +74,10 @@ pub fn abort_with_code(code: &[u8]) -> ! { /// /// # Safety /// This function is unsafe because it dereferences a raw pointer. -#[hyperlight_guest_tracing::trace_function] pub unsafe fn abort_with_code_and_message(code: &[u8], message_ptr: *const c_char) -> ! { + // End any ongoing trace before aborting + #[cfg(feature = "trace_guest")] + hyperlight_guest_tracing::end_trace(); unsafe { // Step 1: Send abort code (typically 1 byte, but `code` allows flexibility) outb(OutBAction::Abort as u16, code); @@ -76,10 +105,9 @@ pub fn write_abort(code: &[u8]) { } /// OUT bytes to the host through multiple exits. -#[hyperlight_guest_tracing::trace_function] +#[instrument(skip_all, parent = Span::current(), level= "Trace")] pub(crate) fn outb(port: u16, data: &[u8]) { // Ensure all tracing data is flushed before sending OUT bytes - hyperlight_guest_tracing::flush!(); unsafe { let mut i = 0; while i < data.len() { @@ -96,8 +124,33 @@ pub(crate) fn outb(port: u16, data: &[u8]) { } /// OUT function for sending a 32-bit value to the host. -#[hyperlight_guest_tracing::trace_function] +#[instrument(skip_all, parent = Span::current(), level= "Trace")] pub(crate) unsafe fn out32(port: u16, val: u32) { + #[cfg(feature = "trace_guest")] + { + if let Some(tbi) = hyperlight_guest_tracing::guest_trace_info() { + // If tracing is enabled, send the trace batch info along with the OUT action + unsafe { + asm!("out dx, eax", + in("dx") port, + in("eax") val, + in("r8") OutBAction::TraceBatch as u64, + in("r9") tbi.guest_start_tsc, + in("r10") tbi.spans_ptr, + in("r11") tbi.events_ptr, + options(preserves_flags, nomem, nostack) + ) + }; + + hyperlight_guest_tracing::clean_trace_state(); + } else { + // If tracing is not enabled, just send the value + unsafe { + asm!("out dx, eax", in("dx") port, in("eax") val, options(preserves_flags, nomem, nostack)) + }; + } + } + #[cfg(not(feature = "trace_guest"))] unsafe { asm!("out dx, eax", in("dx") port, in("eax") val, options(preserves_flags, nomem, nostack)); } diff --git a/src/hyperlight_guest/src/guest_handle/host_comm.rs b/src/hyperlight_guest/src/guest_handle/host_comm.rs index 17b5300e5..4e1879d7b 100644 --- a/src/hyperlight_guest/src/guest_handle/host_comm.rs +++ b/src/hyperlight_guest/src/guest_handle/host_comm.rs @@ -30,6 +30,7 @@ use hyperlight_common::flatbuffer_wrappers::guest_log_level::LogLevel; use hyperlight_common::flatbuffer_wrappers::host_function_details::HostFunctionDetails; use hyperlight_common::flatbuffer_wrappers::util::estimate_flatbuffer_capacity; use hyperlight_common::outb::OutBAction; +use tracing::{Span, instrument}; use super::handle::GuestHandle; use crate::error::{HyperlightGuestError, Result}; @@ -37,7 +38,7 @@ use crate::exit::out32; impl GuestHandle { /// Get user memory region as bytes. - #[hyperlight_guest_tracing::trace_function] + #[instrument(skip_all, parent = Span::current(), level= "Trace")] pub fn read_n_bytes_from_user_memory(&self, num: u64) -> Result> { let peb_ptr = self.peb().unwrap(); let user_memory_region_ptr = unsafe { (*peb_ptr).init_data.ptr as *mut u8 }; @@ -66,7 +67,7 @@ impl GuestHandle { /// /// When calling `call_host_function`, this function is called /// internally to get the return value. - #[hyperlight_guest_tracing::trace_function] + #[instrument(skip_all, parent = Span::current(), level= "Trace")] pub fn get_host_return_value>(&self) -> Result { let return_value = self .try_pop_shared_input_data_into::() @@ -87,7 +88,7 @@ impl GuestHandle { /// /// Note: The function return value must be obtained by calling /// `get_host_return_value`. - #[hyperlight_guest_tracing::trace_function] + #[instrument(skip_all, parent = Span::current(), level= "Trace")] pub fn call_host_function_without_returning_result( &self, function_name: &str, @@ -121,7 +122,7 @@ impl GuestHandle { /// sends it to the host, and then retrieves the return value. /// /// The return value is deserialized into the specified type `T`. - #[hyperlight_guest_tracing::trace_function] + #[instrument(skip_all, parent = Span::current(), level= "Trace")] pub fn call_host_function>( &self, function_name: &str, @@ -132,7 +133,7 @@ impl GuestHandle { self.get_host_return_value::() } - #[hyperlight_guest_tracing::trace_function] + #[instrument(skip_all, parent = Span::current(), level= "Trace")] pub fn get_host_function_details(&self) -> HostFunctionDetails { let peb_ptr = self.peb().unwrap(); let host_function_details_buffer = @@ -149,7 +150,7 @@ impl GuestHandle { } /// Write an error to the shared output data buffer. - #[hyperlight_guest_tracing::trace_function] + #[instrument(skip_all, parent = Span::current(), level= "Trace")] pub fn write_error(&self, error_code: ErrorCode, message: Option<&str>) { let guest_error: GuestError = GuestError::new( error_code, @@ -165,7 +166,7 @@ impl GuestHandle { } /// Log a message with the specified log level, source, caller, source file, and line number. - #[hyperlight_guest_tracing::trace_function] + #[instrument(skip_all, parent = Span::current(), level= "Trace")] pub fn log_message( &self, log_level: LogLevel, @@ -175,24 +176,46 @@ impl GuestHandle { source_file: &str, line: u32, ) { - let guest_log_data = GuestLogData::new( - message.to_string(), - source.to_string(), - log_level, - caller.to_string(), - source_file.to_string(), - line, - ); - - let bytes: Vec = guest_log_data - .try_into() - .expect("Failed to convert GuestLogData to bytes"); - - self.push_shared_output_data(&bytes) - .expect("Unable to push log data to shared output data"); - - unsafe { - out32(OutBAction::Log as u16, 0); + // Closure to send log message to host + let send_to_host = || { + let guest_log_data = GuestLogData::new( + message.to_string(), + source.to_string(), + log_level, + caller.to_string(), + source_file.to_string(), + line, + ); + + let bytes: Vec = guest_log_data + .try_into() + .expect("Failed to convert GuestLogData to bytes"); + + self.push_shared_output_data(&bytes) + .expect("Unable to push log data to shared output data"); + + unsafe { + out32(OutBAction::Log as u16, 0); + } + }; + + #[cfg(feature = "trace_guest")] + if hyperlight_guest_tracing::is_trace_enabled() { + // If the "trace_guest" feature is enabled and tracing is initialized, log using tracing + tracing::trace!( + event = message, + level = ?log_level, + code.filepath = source, + caller = caller, + source_file = source_file, + code.lineno = line, + ); + } else { + send_to_host(); + } + #[cfg(not(feature = "trace_guest"))] + { + send_to_host(); } } } diff --git a/src/hyperlight_guest/src/guest_handle/io.rs b/src/hyperlight_guest/src/guest_handle/io.rs index d8219b270..a494033dd 100644 --- a/src/hyperlight_guest/src/guest_handle/io.rs +++ b/src/hyperlight_guest/src/guest_handle/io.rs @@ -20,13 +20,14 @@ use core::any::type_name; use core::slice::from_raw_parts_mut; use hyperlight_common::flatbuffer_wrappers::guest_error::ErrorCode; +use tracing::{Span, instrument}; use super::handle::GuestHandle; use crate::error::{HyperlightGuestError, Result}; impl GuestHandle { /// Pops the top element from the shared input data buffer and returns it as a T - #[hyperlight_guest_tracing::trace_function] + #[instrument(skip_all, parent = Span::current(), level= "Trace")] pub fn try_pop_shared_input_data_into(&self) -> Result where T: for<'a> TryFrom<&'a [u8]>, @@ -68,18 +69,15 @@ impl GuestHandle { let buffer = &idb[last_element_offset_rel as usize..]; // convert the buffer to T - let type_t = hyperlight_guest_tracing::trace!( - "convert buffer", - match T::try_from(buffer) { - Ok(t) => Ok(t), - Err(_e) => { - return Err(HyperlightGuestError::new( - ErrorCode::GuestError, - format!("Unable to convert buffer to {}", type_name::()), - )); - } + let type_t = match T::try_from(buffer) { + Ok(t) => Ok(t), + Err(_e) => { + return Err(HyperlightGuestError::new( + ErrorCode::GuestError, + format!("Unable to convert buffer to {}", type_name::()), + )); } - ); + }; // update the stack pointer to point to the element we just popped of since that is now free idb[..8].copy_from_slice(&last_element_offset_rel.to_le_bytes()); @@ -91,7 +89,7 @@ impl GuestHandle { } /// Pushes the given data onto the shared output data buffer. - #[hyperlight_guest_tracing::trace_function] + #[instrument(skip_all, parent = Span::current(), level= "Trace")] pub fn push_shared_output_data(&self, data: &[u8]) -> Result<()> { let peb_ptr = self.peb().unwrap(); let output_stack_size = unsafe { (*peb_ptr).output_stack.size as usize }; @@ -137,9 +135,7 @@ impl GuestHandle { } // write the actual data - hyperlight_guest_tracing::trace!("copy data", { - odb[stack_ptr_rel as usize..stack_ptr_rel as usize + data.len()].copy_from_slice(data); - }); + odb[stack_ptr_rel as usize..stack_ptr_rel as usize + data.len()].copy_from_slice(data); // write the offset to the newly written data, to the top of the stack let bytes: [u8; 8] = stack_ptr_rel.to_le_bytes(); diff --git a/src/hyperlight_guest_bin/Cargo.toml b/src/hyperlight_guest_bin/Cargo.toml index c21d00c91..eab39eb1a 100644 --- a/src/hyperlight_guest_bin/Cargo.toml +++ b/src/hyperlight_guest_bin/Cargo.toml @@ -18,7 +18,7 @@ default = ["libc", "printf"] libc = [] # compile musl libc printf = [ "libc" ] # compile printf trace_guest = ["hyperlight-common/trace_guest", "hyperlight-guest/trace_guest", "hyperlight-guest-tracing/trace"] -mem_profile = ["hyperlight-common/unwind_guest","hyperlight-common/mem_profile"] +mem_profile = ["hyperlight-common/mem_profile"] [dependencies] hyperlight-guest = { workspace = true, default-features = false } @@ -27,6 +27,7 @@ hyperlight-guest-tracing = { workspace = true, default-features = false } buddy_system_allocator = "0.11.0" log = { version = "0.4", default-features = false } spin = "0.10.0" +tracing = { version = "0.1.41", default-features = false, features = ["attributes"] } [lints] workspace = true diff --git a/src/hyperlight_guest_bin/src/exceptions/gdt.rs b/src/hyperlight_guest_bin/src/exceptions/gdt.rs index 38bdf183e..0a3b2cfb6 100644 --- a/src/hyperlight_guest_bin/src/exceptions/gdt.rs +++ b/src/hyperlight_guest_bin/src/exceptions/gdt.rs @@ -72,7 +72,6 @@ struct GdtPointer { } /// Load the GDT -#[hyperlight_guest_tracing::trace_function] pub unsafe fn load_gdt() { unsafe { let gdt_ptr = GdtPointer { diff --git a/src/hyperlight_guest_bin/src/exceptions/handler.rs b/src/hyperlight_guest_bin/src/exceptions/handler.rs index 838cd582b..ab0da4cfe 100644 --- a/src/hyperlight_guest_bin/src/exceptions/handler.rs +++ b/src/hyperlight_guest_bin/src/exceptions/handler.rs @@ -65,12 +65,6 @@ pub extern "C" fn hl_exception_handler( exception_number: u64, page_fault_address: u64, ) { - // When using the `trace_function` macro, it wraps the function body with create_trace_record - // call, which generates a warning because of the `abort_with_code_and_message` call which does - // not return. - // This is manually added to avoid the warning. - hyperlight_guest_tracing::trace!("> hl_exception_handler"); - let ctx = stack_pointer as *mut Context; let exn_info = (stack_pointer + size_of::() as u64) as *mut ExceptionInfo; @@ -101,7 +95,6 @@ pub extern "C" fn hl_exception_handler( )(exception_number, exn_info, ctx, page_fault_address) } { - hyperlight_guest_tracing::trace!("< hl_exception_handler"); return; } } diff --git a/src/hyperlight_guest_bin/src/exceptions/idt.rs b/src/hyperlight_guest_bin/src/exceptions/idt.rs index 91364cd95..3107c4df4 100644 --- a/src/hyperlight_guest_bin/src/exceptions/idt.rs +++ b/src/hyperlight_guest_bin/src/exceptions/idt.rs @@ -71,7 +71,6 @@ impl IdtEntry { // Architectures Software Developer's Manual). pub(crate) static mut IDT: [IdtEntry; 256] = unsafe { core::mem::zeroed() }; -#[hyperlight_guest_tracing::trace_function] pub(crate) fn init_idt() { set_idt_entry(Exception::DivideByZero as usize, _do_excp0); // Divide by zero set_idt_entry(Exception::Debug as usize, _do_excp1); // Debug diff --git a/src/hyperlight_guest_bin/src/exceptions/idtr.rs b/src/hyperlight_guest_bin/src/exceptions/idtr.rs index e79fb5dcf..d1d54830b 100644 --- a/src/hyperlight_guest_bin/src/exceptions/idtr.rs +++ b/src/hyperlight_guest_bin/src/exceptions/idtr.rs @@ -40,7 +40,6 @@ impl Idtr { } } -#[hyperlight_guest_tracing::trace_function] pub(crate) unsafe fn load_idt() { unsafe { init_idt(); diff --git a/src/hyperlight_guest_bin/src/guest_function/call.rs b/src/hyperlight_guest_bin/src/guest_function/call.rs index 7eabdeb29..973b685fe 100644 --- a/src/hyperlight_guest_bin/src/guest_function/call.rs +++ b/src/hyperlight_guest_bin/src/guest_function/call.rs @@ -22,12 +22,13 @@ use hyperlight_common::flatbuffer_wrappers::function_types::ParameterType; use hyperlight_common::flatbuffer_wrappers::guest_error::ErrorCode; use hyperlight_guest::error::{HyperlightGuestError, Result}; use hyperlight_guest::exit::halt; +use tracing::{Span, instrument}; use crate::{GUEST_HANDLE, REGISTERED_GUEST_FUNCTIONS}; type GuestFunc = fn(&FunctionCall) -> Result>; -#[hyperlight_guest_tracing::trace_function] +#[instrument(skip_all, parent = Span::current(), level= "Trace")] pub(crate) fn call_guest_function(function_call: FunctionCall) -> Result> { // Validate this is a Guest Function Call if function_call.function_call_type() != FunctionCallType::Guest { @@ -62,7 +63,7 @@ pub(crate) fn call_guest_function(function_call: FunctionCall) -> Result core::mem::transmute::(function_pointer) }; - hyperlight_guest_tracing::trace!("guest_function", p_function(&function_call)) + p_function(&function_call) } else { // The given function is not registered. The guest should implement a function called guest_dispatch_function to handle this. @@ -73,9 +74,7 @@ pub(crate) fn call_guest_function(function_call: FunctionCall) -> Result fn guest_dispatch_function(function_call: FunctionCall) -> Result>; } - hyperlight_guest_tracing::trace!("default guest function", unsafe { - guest_dispatch_function(function_call) - }) + unsafe { guest_dispatch_function(function_call) } } } @@ -83,7 +82,7 @@ pub(crate) fn call_guest_function(function_call: FunctionCall) -> Result // and we will leak memory as the epilogue will not be called as halt() is not going to return. #[unsafe(no_mangle)] #[inline(never)] -#[hyperlight_guest_tracing::trace_function] +#[instrument(skip_all, parent = Span::current(), level= "Trace")] fn internal_dispatch_function() -> Result<()> { let handle = unsafe { GUEST_HANDLE }; @@ -104,7 +103,7 @@ fn internal_dispatch_function() -> Result<()> { // This is implemented as a separate function to make sure that epilogue in the internal_dispatch_function is called before the halt() // which if it were included in the internal_dispatch_function cause the epilogue to not be called because the halt() would not return // when running in the hypervisor. -#[hyperlight_guest_tracing::trace_function] +#[instrument(skip_all, parent = Span::current(), level= "Trace")] pub(crate) extern "C" fn dispatch_function() { // The hyperlight host likes to use one partition and reset it in // various ways; if that has happened, there might stale TLB @@ -117,6 +116,15 @@ pub(crate) extern "C" fn dispatch_function() { // part of the big identity-mapped region at the base of the // guest. crate::paging::flush_tlb(); + + // 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(feature = "trace_guest")] + { + let guest_start_tsc = hyperlight_guest_tracing::invariant_tsc::read_tsc(); + hyperlight_guest_tracing::set_start_tsc(guest_start_tsc); + } + let _ = internal_dispatch_function(); halt(); } diff --git a/src/hyperlight_guest_bin/src/lib.rs b/src/hyperlight_guest_bin/src/lib.rs index 8686aab5e..d51db6654 100644 --- a/src/hyperlight_guest_bin/src/lib.rs +++ b/src/hyperlight_guest_bin/src/lib.rs @@ -32,7 +32,6 @@ use hyperlight_common::mem::HyperlightPEB; use hyperlight_common::outb::OutBAction; use hyperlight_guest::exit::{halt, write_abort}; use hyperlight_guest::guest_handle::handle::GuestHandle; -use hyperlight_guest_tracing::{trace, trace_function}; use log::LevelFilter; use spin::Once; @@ -182,8 +181,11 @@ unsafe extern "C" { static INIT: Once = Once::new(); #[unsafe(no_mangle)] -#[trace_function] pub extern "C" fn entrypoint(peb_address: u64, seed: u64, ops: u64, max_log_level: u64) { + // Save the guest start TSC for tracing + #[cfg(feature = "trace_guest")] + let guest_start_tsc = hyperlight_guest_tracing::invariant_tsc::read_tsc(); + if peb_address == 0 { panic!("PEB address is null"); } @@ -232,9 +234,13 @@ pub extern "C" fn entrypoint(peb_address: u64, seed: u64, ops: u64, max_log_leve .expect("Invalid log level"); init_logger(max_log_level); - trace!("hyperlight_main", - hyperlight_main(); - ); + // It is important that all the tracing events are produced after the tracing is initialized. + #[cfg(feature = "trace_guest")] + if max_log_level == LevelFilter::Trace { + hyperlight_guest_tracing::init_guest_tracing(guest_start_tsc); + } + + hyperlight_main(); } }); diff --git a/src/hyperlight_guest_bin/src/paging.rs b/src/hyperlight_guest_bin/src/paging.rs index a5a3d9f26..4ee3d827a 100644 --- a/src/hyperlight_guest_bin/src/paging.rs +++ b/src/hyperlight_guest_bin/src/paging.rs @@ -17,6 +17,8 @@ limitations under the License. use alloc::alloc::Layout; use core::arch::asm; +use tracing::{Span, instrument}; + use crate::OS_PAGE_SIZE; /// Convert a physical address in main memory to a virtual address @@ -61,7 +63,7 @@ struct MapResponse { /// as such do not use concurrently with any other page table operations /// - TLB invalidation is not performed, /// if previously-unmapped ranges are not being mapped, TLB invalidation may need to be performed afterwards. -#[hyperlight_guest_tracing::trace_function] +#[instrument(skip_all, parent = Span::current(), level= "Trace")] pub unsafe fn map_region(phys_base: u64, virt_base: *mut u8, len: u64) { let mut pml4_base: u64; unsafe { diff --git a/src/hyperlight_guest_tracing/Cargo.toml b/src/hyperlight_guest_tracing/Cargo.toml index 4e9bf9758..9c67daeaf 100644 --- a/src/hyperlight_guest_tracing/Cargo.toml +++ b/src/hyperlight_guest_tracing/Cargo.toml @@ -10,13 +10,15 @@ readme.workspace = true description = """Provides the tracing functionality for the hyperlight guest.""" [dependencies] +heapless = { version = "0.8.0", features = ["serde"] } hyperlight-common = { workspace = true, default-features = false } -hyperlight-guest-tracing-macro = { workspace = true } spin = "0.10.0" +tracing = { version = "0.1.41", default-features = false, features = ["attributes"] } +tracing-core = { version = "0.1.34", default-features = false } [lints] workspace = true [features] default = [] -trace = [ "hyperlight-guest-tracing-macro/trace", "hyperlight-common/trace_guest" ] +trace = [ "hyperlight-common/trace_guest" ] diff --git a/src/hyperlight_guest_tracing/src/invariant_tsc.rs b/src/hyperlight_guest_tracing/src/invariant_tsc.rs new file mode 100644 index 000000000..13521f906 --- /dev/null +++ b/src/hyperlight_guest_tracing/src/invariant_tsc.rs @@ -0,0 +1,47 @@ +/* +Copyright 2025 The Hyperlight Authors. + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +/// Module for checking invariant TSC support and reading the timestamp counter +use core::arch::x86_64::{__cpuid, _rdtsc}; + +/// Check if the processor supports invariant TSC +/// +/// Returns true if CPUID.80000007H:EDX[8] is set, indicating invariant TSC support +pub fn has_invariant_tsc() -> bool { + // Check if extended CPUID functions are available + let max_extended = unsafe { __cpuid(0x80000000) }; + if max_extended.eax < 0x80000007 { + return false; + } + + // Query CPUID.80000007H for invariant TSC support + let cpuid_result = unsafe { __cpuid(0x80000007) }; + + // Check bit 8 of EDX register for invariant TSC support + (cpuid_result.edx & (1 << 8)) != 0 +} + +/// Read the timestamp counter +/// +/// This function provides a high-performance timestamp by reading the TSC. +/// Should only be used when invariant TSC is supported for reliable timing. +/// +/// # Safety +/// This function uses unsafe assembly instructions but is safe to call. +/// However, the resulting timestamp is only meaningful if invariant TSC is supported. +pub fn read_tsc() -> u64 { + unsafe { _rdtsc() } +} diff --git a/src/hyperlight_guest_tracing/src/lib.rs b/src/hyperlight_guest_tracing/src/lib.rs index b89f88e9b..c0ce0390c 100644 --- a/src/hyperlight_guest_tracing/src/lib.rs +++ b/src/hyperlight_guest_tracing/src/lib.rs @@ -13,364 +13,212 @@ WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the License for the specific language governing permissions and limitations under the License. */ + #![no_std] +use heapless as hl; + +/// Expose invariant TSC module +pub mod invariant_tsc; -/// Re-export the tracing macros -/// This allows users to use the macros without needing to import them explicitly. -/// -/// # Tracing Macros Usage -/// -/// ## The `trace_function` macro can be used to trace function calls. -/// -/// ```rust -/// #[hyperlight_guest_tracing_macro::trace_function] -/// fn my_function() { -/// // // Function body -/// } -/// ``` -/// -/// ## The `trace!` macro can be used to create trace records with a message. -/// -/// ```rust -/// use hyperlight_guest_tracing_macro::trace; -/// trace!("message"); -/// trace!("message", { /* block of code */ }); -/// ``` -/// -/// ## Basic usage: trace with message only -/// -/// ``` -/// use hyperlight_guest_tracing_macro::trace; -/// trace!("hello"); -/// ``` -/// -/// ## Trace with a block, returning a value -/// -/// ``` -/// use hyperlight_guest_tracing_macro::trace; -/// let x = trace!("block", { 42 }); -/// assert_eq!(x, 42); -/// ``` -/// -/// ## Trace with a block using local variables -/// -/// ``` -/// use hyperlight_guest_tracing_macro::trace; -/// let y = 10; -/// let z = trace!("sum", { y + 5 }); -/// assert_eq!(z, 15); -/// ``` -/// -/// ## Trace with a block that returns a reference -/// -/// ``` -/// use hyperlight_guest_tracing_macro::trace; -/// let s = String::from("abc"); -/// let r: &str = trace!("ref", { &s }); -/// assert_eq!(r, "abc"); -/// ``` -/// -/// ## Control flow: `return` inside the block returns from the function -/// -/// ``` -/// use hyperlight_guest_tracing_macro::trace; -/// fn foo() -> i32 { -/// let _ = trace!("fail", { -/// // This return only exits the closure, not the function `foo`. -/// return 42; -/// }); -/// assert!(false, "This should not be reached"); -/// } -/// ``` -/// -/// ## Control flow: `break` inside the block exits the outer loop -/// -/// ``` -/// use hyperlight_guest_tracing_macro::trace; -/// let mut x = 0; -/// for i in 1..3 { -/// x = i; -/// let _ = trace!("msg", { -/// // This break should exit the loop. -/// break; -/// }); -/// } -/// assert_eq!(x, 1, "Loop should break after the first iteration"); -/// ``` -/// -/// ## Flush the trace buffer -/// ```rust -/// hyperlight_guest_tracing_macro::flush!(); -/// ``` -pub use hyperlight_guest_tracing_macro::*; +/// Defines internal guest state #[cfg(feature = "trace")] -pub use trace::{create_trace_record, flush_trace_buffer}; +mod state; -/// Maximum length of a trace message in bytes. -pub const MAX_TRACE_MSG_LEN: usize = 64; +/// Defines guest tracing Subscriber +#[cfg(feature = "trace")] +mod subscriber; + +/// Defines a type to iterate over spans/events fields +#[cfg(feature = "trace")] +mod visitor; +/// Type to get the relevant information from the internal state +/// and expose it to the host +#[cfg(feature = "trace")] +pub use state::TraceBatchInfo; +#[cfg(feature = "trace")] +pub use trace::{ + clean_trace_state, end_trace, guest_trace_info, init_guest_tracing, is_trace_enabled, + set_start_tsc, +}; + +/// Maximum number of spans that the guest can store +const MAX_NO_OF_SPANS: usize = 10; +/// Maximum number of events that the guest can store +const MAX_NO_OF_EVENTS: usize = 10; +/// Maximum length a name can have in a span/event +const MAX_NAME_LENGTH: usize = 64; +/// Maximum length the target can have in a span/event +const MAX_TARGET_LENGTH: usize = 64; +/// Maximum length key of a Field can have +const MAX_FIELD_KEY_LENGTH: usize = 32; +/// Maximum length value of a Field can have +const MAX_FIELD_VALUE_LENGTH: usize = 96; +/// Maximum number of fields a span/event can have +const MAX_NO_OF_FIELDS: usize = 8; + +/// Alias for the complicated heapless::Vec type for Spans +pub type Spans = hl::Vec< + GuestSpan< + MAX_NAME_LENGTH, + MAX_TARGET_LENGTH, + MAX_FIELD_KEY_LENGTH, + MAX_FIELD_VALUE_LENGTH, + MAX_NO_OF_FIELDS, + >, + MAX_NO_OF_SPANS, +>; + +/// Alias for the complicated heapless::Vec type for Events +pub type Events = hl::Vec< + GuestEvent, + MAX_NO_OF_EVENTS, +>; + +/// The trace level assigned to a span/event #[derive(Debug, Copy, Clone)] -/// Represents a trace record of a guest with a number of cycles and a message. -pub struct TraceRecord { - /// The number of CPU cycles returned by the invariant TSC. - pub cycles: u64, - /// The length of the message in bytes. - pub msg_len: usize, - /// The message associated with the trace record. - pub msg: [u8; MAX_TRACE_MSG_LEN], +pub enum TraceLevel { + Error, + Warn, + Info, + Debug, + Trace, } -/// Module for checking invariant TSC support and reading the timestamp counter -pub mod invariant_tsc { - use core::arch::x86_64::{__cpuid, _rdtsc}; - - /// Check if the processor supports invariant TSC - /// - /// Returns true if CPUID.80000007H:EDX[8] is set, indicating invariant TSC support - pub fn has_invariant_tsc() -> bool { - // Check if extended CPUID functions are available - let max_extended = unsafe { __cpuid(0x80000000) }; - if max_extended.eax < 0x80000007 { - return false; +impl From for TraceLevel { + fn from(value: tracing::Level) -> Self { + match value { + tracing::Level::ERROR => Self::Error, + tracing::Level::WARN => Self::Warn, + tracing::Level::INFO => Self::Info, + tracing::Level::DEBUG => Self::Debug, + tracing::Level::TRACE => Self::Trace, } - - // Query CPUID.80000007H for invariant TSC support - let cpuid_result = unsafe { __cpuid(0x80000007) }; - - // Check bit 8 of EDX register for invariant TSC support - (cpuid_result.edx & (1 << 8)) != 0 } - - /// Read the timestamp counter - /// - /// This function provides a high-performance timestamp by reading the TSC. - /// Should only be used when invariant TSC is supported for reliable timing. - /// - /// # Safety - /// This function uses unsafe assembly instructions but is safe to call. - /// However, the resulting timestamp is only meaningful if invariant TSC is supported. - pub fn read_tsc() -> u64 { - unsafe { _rdtsc() } +} +impl From for tracing::Level { + fn from(value: TraceLevel) -> Self { + match value { + TraceLevel::Error => Self::ERROR, + TraceLevel::Warn => Self::WARN, + TraceLevel::Info => Self::INFO, + TraceLevel::Debug => Self::DEBUG, + TraceLevel::Trace => Self::TRACE, + } } } +/// The structure in which a guest stores Span information +pub struct GuestSpan< + const N: usize, + const T: usize, + const FK: usize, + const FV: usize, + const F: usize, +> { + pub id: u64, + pub parent_id: Option, + pub level: TraceLevel, + /// Span name + pub name: hl::String, + /// Filename + pub target: hl::String, + pub start_tsc: u64, + pub end_tsc: Option, + pub fields: hl::Vec<(hl::String, hl::String), F>, +} + +/// The structure in which a guest stores Event information +pub struct GuestEvent { + pub parent_id: u64, + pub level: TraceLevel, + pub name: hl::String, + /// Event name + pub tsc: u64, + pub fields: hl::Vec<(hl::String, hl::String), F>, +} + +/// This module is gated because some of these types are also used on the host, but we want +/// only the guest to allocate and allow the functionality intended for the guest. #[cfg(feature = "trace")] mod trace { - // === Dependencies === extern crate alloc; + use alloc::sync::{Arc, Weak}; - use core::mem::MaybeUninit; - - use hyperlight_common::outb::OutBAction; use spin::Mutex; - use super::{MAX_TRACE_MSG_LEN, TraceRecord, invariant_tsc}; - - /// Type alias for the function that sends trace records to the host. - type SendToHostFn = fn(u64, &[TraceRecord]); - - /// Global trace buffer for storing trace records. - static TRACE_BUFFER: Mutex> = - Mutex::new(TraceBuffer::new(send_to_host)); - - /// Maximum number of entries in the trace buffer. - /// From local testing, 32 entries seems to be a good balance between performance and memory usage. - const MAX_NO_OF_ENTRIES: usize = 32; - - impl From<&str> for TraceRecord { - fn from(mut msg: &str) -> Self { - if msg.len() > MAX_TRACE_MSG_LEN { - // If the message is too long, truncate it to fit the maximum length - msg = &msg[..MAX_TRACE_MSG_LEN]; - } + use super::*; + use crate::state::GuestState; + use crate::subscriber::GuestSubscriber; - let cycles = invariant_tsc::read_tsc(); + /// Weak reference to the guest state so we can manually trigger flush to host + static GUEST_STATE: spin::Once>> = spin::Once::new(); - TraceRecord { - cycles, - msg: { - let mut arr = [0u8; MAX_TRACE_MSG_LEN]; - arr[..msg.len()].copy_from_slice(msg.as_bytes()); - arr - }, - msg_len: msg.len(), - } + /// Initialize the guest tracing subscriber as global default. + pub fn init_guest_tracing(guest_start_tsc: u64) { + // Set as global default if not already set. + if tracing_core::dispatcher::has_been_set() { + return; } - } + let sub = GuestSubscriber::new(guest_start_tsc); + let state = sub.state(); + // Store state Weak to use later at runtime + GUEST_STATE.call_once(|| Arc::downgrade(state)); - /// A buffer for storing trace records. - struct TraceBuffer { - /// The entries in the trace buffer. - entries: [TraceRecord; MAX_NO_OF_ENTRIES], - /// The index where the next entry will be written. - write_index: usize, - /// Function to send the trace records to the host. - send_to_host: F, + // Set global dispatcher + let _ = tracing_core::dispatcher::set_global_default(tracing_core::Dispatch::new(sub)); } - impl TraceBuffer { - /// Creates a new `TraceBuffer` with uninitialized entries. - const fn new(f: F) -> Self { - Self { - entries: unsafe { [MaybeUninit::zeroed().assume_init(); MAX_NO_OF_ENTRIES] }, - write_index: 0, - send_to_host: f, - } - } - - /// Push a new trace record into the buffer. - /// If the buffer is full, it sends the records to the host. - fn push(&mut self, entry: TraceRecord) { - let mut write_index = self.write_index; - - self.entries[write_index] = entry; - write_index = (write_index + 1) % MAX_NO_OF_ENTRIES; - - self.write_index = write_index; - - if write_index == 0 { - // If buffer is full send to host - (self.send_to_host)(MAX_NO_OF_ENTRIES as u64, &self.entries); - } - } - - /// Flush the trace buffer, sending any remaining records to the host. - fn flush(&mut self) { - if self.write_index > 0 { - (self.send_to_host)(self.write_index as u64, &self.entries); - self.write_index = 0; // Reset write index after flushing + /// Sets the guset starting timestamp reported to the host on a VMExit + pub fn set_start_tsc(guest_start_tsc: u64) { + if let Some(w) = GUEST_STATE.get() { + if let Some(state) = w.upgrade() { + state.lock().set_start_tsc(guest_start_tsc); } } } - /// Send the trace records to the host. - fn send_to_host(len: u64, records: &[TraceRecord]) { - unsafe { - core::arch::asm!("out dx, al", - in("dx") OutBAction::TraceRecord as u16, - in("rax") len, - in("rcx") records.as_ptr() as u64); - } - } - - /// Create a trace record from the message and push it to the trace buffer. + /// Ends the current trace by ending all active spans in the + /// internal state and storing the end timestamps. /// - /// **NOTE**: If the message is too long it will be truncated to fit within `MAX_TRACE_MSG_LEN`. - /// This is useful for ensuring that the trace buffer does not overflow. - #[inline(always)] - pub fn create_trace_record(msg: &str) { - let entry = TraceRecord::from(msg); - let mut buffer = TRACE_BUFFER.lock(); - - buffer.push(entry); - } - - /// Flush the trace buffer to send any remaining trace records to the host. - #[inline(always)] - pub fn flush_trace_buffer() { - let mut buffer = TRACE_BUFFER.lock(); - buffer.flush(); - } - - #[cfg(test)] - mod tests { - use alloc::format; - - use super::*; - - /// This is a mock function for testing purposes. - /// In a real scenario, this would send the trace records to the host. - fn mock_send_to_host(_len: u64, _records: &[TraceRecord]) {} - - fn create_test_entry(msg: &str) -> TraceRecord { - let cycles = invariant_tsc::read_tsc(); - - TraceRecord { - cycles, - msg: { - let mut arr = [0u8; MAX_TRACE_MSG_LEN]; - arr[..msg.len()].copy_from_slice(msg.as_bytes()); - arr - }, - msg_len: msg.len(), + /// This expects an outb call to send the spans to the host. + /// After calling this function, the internal state is marked + /// for cleaning on the next access. + pub fn end_trace() { + if let Some(w) = GUEST_STATE.get() { + if let Some(state) = w.upgrade() { + state.lock().end_trace(); } } + } - #[test] - fn test_push_trace_record() { - let mut buffer = TraceBuffer::new(mock_send_to_host); - - let msg = "Test message"; - let entry = create_test_entry(msg); - - buffer.push(entry); - assert_eq!(buffer.write_index, 1); - assert_eq!(buffer.entries[0].msg_len, msg.len()); - assert_eq!(&buffer.entries[0].msg[..msg.len()], msg.as_bytes()); - assert!(buffer.entries[0].cycles > 0); // Ensure cycles is set - } - - #[test] - fn test_flush_trace_buffer() { - let mut buffer = TraceBuffer::new(mock_send_to_host); - - let msg = "Test message"; - let entry = create_test_entry(msg); - - buffer.push(entry); - assert_eq!(buffer.write_index, 1); - assert_eq!(buffer.entries[0].msg_len, msg.len()); - assert_eq!(&buffer.entries[0].msg[..msg.len()], msg.as_bytes()); - assert!(buffer.entries[0].cycles > 0); - - // Flush the buffer - buffer.flush(); - - // After flushing, the entries should still be intact, we don't clear them - assert_eq!(buffer.write_index, 0); - assert_eq!(buffer.entries[0].msg_len, msg.len()); - assert_eq!(&buffer.entries[0].msg[..msg.len()], msg.as_bytes()); - assert!(buffer.entries[0].cycles > 0); - } - - #[test] - fn test_auto_flush_on_full() { - let mut buffer = TraceBuffer::new(mock_send_to_host); - - // Fill the buffer to trigger auto-flush - for i in 0..MAX_NO_OF_ENTRIES { - let msg = format!("Message {}", i); - let entry = create_test_entry(&msg); - buffer.push(entry); + /// Cleans the internal trace state by removing closed spans and events. + /// This ensures that after a VM exit, we keep the spans that + /// are still active (in the stack) and remove all other spans and events. + pub fn clean_trace_state() { + if let Some(w) = GUEST_STATE.get() { + if let Some(state) = w.upgrade() { + state.lock().clean(); } - - // After filling, the write index should be 0 (buffer is full) - assert_eq!(buffer.write_index, 0); - - // The first entry should still be intact - assert_eq!(buffer.entries[0].msg_len, "Message 0".len()); } + } - /// Test TraceRecord creation with a valid message - #[test] - fn test_trace_record_creation_valid() { - let msg = "Valid message"; - let entry = TraceRecord::try_from(msg).expect("Failed to create TraceRecord"); - assert_eq!(entry.msg_len, msg.len()); - assert_eq!(&entry.msg[..msg.len()], msg.as_bytes()); - assert!(entry.cycles > 0); // Ensure cycles is set + /// Returns information about the current trace state needed by the host to read the spans. + pub fn guest_trace_info() -> Option { + let mut res = None; + if let Some(w) = GUEST_STATE.get() { + if let Some(state) = w.upgrade() { + res = Some(state.lock().guest_trace_info()); + } } + res + } - /// Test TraceRecord creation with a message that exceeds the maximum length - #[test] - fn test_trace_record_creation_too_long() { - let long_msg = "A".repeat(MAX_TRACE_MSG_LEN + 1); - let result = TraceRecord::from(long_msg.as_str()); - assert_eq!(result.msg_len, MAX_TRACE_MSG_LEN); - assert_eq!( - &result.msg[..MAX_TRACE_MSG_LEN], - &long_msg.as_bytes()[..MAX_TRACE_MSG_LEN], - ); - } + /// Returns true if tracing is enabled (the guest tracing state is initialized). + pub fn is_trace_enabled() -> bool { + GUEST_STATE + .get() + .map(|w| w.upgrade().is_some()) + .unwrap_or(false) } } diff --git a/src/hyperlight_guest_tracing/src/state.rs b/src/hyperlight_guest_tracing/src/state.rs new file mode 100644 index 000000000..f7196a350 --- /dev/null +++ b/src/hyperlight_guest_tracing/src/state.rs @@ -0,0 +1,283 @@ +/* +Copyright 2025 The Hyperlight Authors. + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ +extern crate alloc; + +use core::sync::atomic::{AtomicU64, Ordering}; + +use heapless as hl; +use hyperlight_common::outb::OutBAction; +use tracing_core::Event; +use tracing_core::span::{Attributes, Id, Record}; + +use crate::visitor::FieldsVisitor; +use crate::{ + GuestEvent, GuestSpan, MAX_FIELD_KEY_LENGTH, MAX_FIELD_VALUE_LENGTH, MAX_NAME_LENGTH, + MAX_NO_OF_EVENTS, MAX_NO_OF_FIELDS, MAX_NO_OF_SPANS, MAX_TARGET_LENGTH, invariant_tsc, +}; + +pub struct TraceBatchInfo { + /// The timestamp counter at the start of the guest execution. + pub guest_start_tsc: u64, + /// Pointer to the spans in the guest memory. + pub spans_ptr: u64, + /// Pointer to the events in the guest memory. + pub events_ptr: u64, +} + +/// Helper type to define the guest state with the configured constants +pub type GuestState = TraceState< + MAX_NO_OF_SPANS, + MAX_NO_OF_EVENTS, + MAX_NAME_LENGTH, + MAX_TARGET_LENGTH, + MAX_FIELD_KEY_LENGTH, + MAX_FIELD_VALUE_LENGTH, + MAX_NO_OF_FIELDS, +>; + +/// Internal state of the tracing subscriber +pub(crate) struct TraceState< + const SP: usize, + const EV: usize, + const N: usize, + const T: usize, + const FK: usize, + const FV: usize, + const F: usize, +> { + /// Whether we need to cleanup the state on next access + cleanup_needed: bool, + /// The timestamp counter at the start of the guest execution. + guest_start_tsc: u64, + /// Next span ID to allocate + next_id: AtomicU64, + /// All spans collected + spans: hl::Vec, SP>, + /// All events collected + events: hl::Vec, EV>, + /// Stack of active spans + stack: hl::Vec, +} + +impl< + const SP: usize, + const EV: usize, + const N: usize, + const T: usize, + const FK: usize, + const FV: usize, + const F: usize, +> TraceState +{ + pub(crate) fn new(guest_start_tsc: u64) -> Self { + Self { + cleanup_needed: false, + guest_start_tsc, + next_id: AtomicU64::new(1), + spans: hl::Vec::new(), + stack: hl::Vec::new(), + events: hl::Vec::new(), + } + } + + pub(crate) fn alloc_id(&self) -> (u64, Id) { + let n = self.next_id.load(Ordering::Relaxed); + self.next_id.store(n + 1, Ordering::Relaxed); + + (n, Id::from_u64(n)) + } + + /// Cleanup internal state by removing closed spans and events + /// This ensures that after a VM exit, we keep the spans that + /// are still active (in the stack) and remove all other spans and events. + pub fn clean(&mut self) { + // Remove all spans that have an end timestamp (closed spans) + self.spans.retain(|s| s.end_tsc.is_none()); + + // Remove all events + self.events.clear(); + } + + #[inline(always)] + fn verify_and_clean(&mut self) { + if self.cleanup_needed { + self.clean(); + self.cleanup_needed = false; + } + } + + /// Triggers a VM exit to flush the current spans to the host. + /// This also clears the internal state to start fresh. + fn send_to_host(&mut self) { + let guest_start_tsc = self.guest_start_tsc; + let spans_ptr = &self.spans as *const _ as u64; + let events_ptr = &self.events as *const _ as u64; + + unsafe { + core::arch::asm!("out dx, al", + // Port value for tracing + in("dx") OutBAction::TraceBatch as u16, + // Additional magic number to identify the action + in("r8") OutBAction::TraceBatch as u64, + in("r9") guest_start_tsc, + in("r10") spans_ptr, + in("r11") events_ptr, + ); + } + + self.clean(); + } + + /// Set a new guest start tsc + pub(crate) fn set_start_tsc(&mut self, guest_start_tsc: u64) { + self.guest_start_tsc = guest_start_tsc; + } + + /// Closes the trace by ending all spans + /// NOTE: This expects an outb call to send the spans to the host. + pub(crate) fn end_trace(&mut self) { + for span in self.spans.iter_mut() { + if span.end_tsc.is_none() { + span.end_tsc = Some(invariant_tsc::read_tsc()); + } + } + + // Empty the stack + while self.stack.pop().is_some() { + // Pop all remaining spans from the stack + } + + // Mark for clearing when re-entering the VM because we might + // not enter on the same place as we exited (e.g. halt) + self.cleanup_needed = true; + } + + /// Returns information about the information needed by the host to read the spans. + pub(crate) fn guest_trace_info(&mut self) -> TraceBatchInfo { + TraceBatchInfo { + guest_start_tsc: self.guest_start_tsc, + spans_ptr: &self.spans as *const _ as u64, + events_ptr: &self.events as *const _ as u64, + } + } + + /// Create a new span and push it on the stack + pub(crate) fn new_span(&mut self, attrs: &Attributes) -> Id { + self.verify_and_clean(); + let (idn, id) = self.alloc_id(); + + let md = attrs.metadata(); + let mut name = hl::String::::new(); + let mut target = hl::String::::new(); + // Shorten name and target if they are bigger than the space allocated + let _ = name.push_str(&md.name()[..usize::min(md.name().len(), name.capacity())]); + let _ = target.push_str(&md.target()[..usize::min(md.target().len(), target.capacity())]); + + // Visit fields to collect them + let mut fields = hl::Vec::new(); + attrs.record(&mut FieldsVisitor:: { out: &mut fields }); + + // Find parent from current stack top (if any) + let parent_id = self.stack.last().copied(); + + let span = GuestSpan:: { + id: idn, + parent_id, + level: (*md.level()).into(), + name, + target, + start_tsc: invariant_tsc::read_tsc(), + end_tsc: None, + fields, + }; + + let spans = &mut self.spans; + // Should never fail because we flush when full + let _ = spans.push(span); + + // In case the spans Vec is full, we need to report them to the host + if spans.len() == spans.capacity() { + self.send_to_host(); + } + + id + } + + /// Record an event in the current span (top of the stack) + pub(crate) fn event(&mut self, event: &Event<'_>) { + self.verify_and_clean(); + let stack = &mut self.stack; + let parent_id = stack.last().copied().unwrap_or(0); + + let md = event.metadata(); + let mut name = hl::String::::new(); + // Shorten name and target if they are bigger than the space allocated + let _ = name.push_str(&md.name()[..usize::min(md.name().len(), name.capacity())]); + + let mut fields = hl::Vec::new(); + event.record(&mut FieldsVisitor:: { out: &mut fields }); + + let ev = GuestEvent { + parent_id, + level: (*md.level()).into(), + name, + tsc: invariant_tsc::read_tsc(), + fields, + }; + + // Should never fail because we flush when full + let _ = self.events.push(ev); + + // Flush buffer to host if full + if self.events.len() >= self.events.capacity() { + self.send_to_host(); + } + } + + /// Record new values for an existing span + pub(crate) fn record(&mut self, id: &Id, values: &Record<'_>) { + let spans = &mut self.spans; + if let Some(s) = spans.iter_mut().find(|s| s.id == id.into_u64()) { + let mut v = hl::Vec::new(); + values.record(&mut FieldsVisitor:: { out: &mut v }); + s.fields.extend(v); + } + } + + /// Enter a span (push it on the stack) + pub(crate) fn enter(&mut self, id: &Id) { + let st = &mut self.stack; + let _ = st.push(id.into_u64()); + } + + /// Exit a span (pop it from the stack) + pub(crate) fn exit(&mut self, _id: &Id) { + let st = &mut self.stack; + let _ = st.pop(); + } + + /// Try to close a span by ID, returning true if successful + /// Records the end timestamp for the span. + pub(crate) fn try_close(&mut self, id: Id) -> bool { + let spans = &mut self.spans; + if let Some(s) = spans.iter_mut().find(|s| s.id == id.into_u64()) { + s.end_tsc = Some(invariant_tsc::read_tsc()); + true + } else { + false + } + } +} diff --git a/src/hyperlight_guest_tracing/src/subscriber.rs b/src/hyperlight_guest_tracing/src/subscriber.rs new file mode 100644 index 000000000..fca202bb0 --- /dev/null +++ b/src/hyperlight_guest_tracing/src/subscriber.rs @@ -0,0 +1,78 @@ +/* +Copyright 2025 The Hyperlight Authors. + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ +extern crate alloc; + +use alloc::sync::Arc; + +use spin::Mutex; +use tracing_core::span::{Attributes, Id, Record}; +use tracing_core::subscriber::Subscriber; +use tracing_core::{Event, Metadata}; + +use crate::state::GuestState; + +/// The subscriber is used to collect spans and events in the guest. +pub(crate) struct GuestSubscriber { + /// Internal state that holds the spans and events + /// Protected by a Mutex for inner mutability + /// A reference to this state is stored in a static variable + state: Arc>, +} + +impl GuestSubscriber { + pub(crate) fn new(guest_start_tsc: u64) -> Self { + Self { + state: Arc::new(Mutex::new(GuestState::new(guest_start_tsc))), + } + } + pub(crate) fn state(&self) -> &Arc> { + &self.state + } +} + +impl Subscriber for GuestSubscriber { + fn enabled(&self, _md: &Metadata<'_>) -> bool { + true + } + + fn new_span(&self, attrs: &Attributes<'_>) -> Id { + self.state.lock().new_span(attrs) + } + + fn record(&self, id: &Id, values: &Record<'_>) { + self.state.lock().record(id, values) + } + + fn event(&self, event: &Event<'_>) { + self.state.lock().event(event) + } + + fn enter(&self, id: &Id) { + self.state.lock().enter(id) + } + + fn exit(&self, id: &Id) { + self.state.lock().exit(id) + } + + fn try_close(&self, id: Id) -> bool { + self.state.lock().try_close(id) + } + + fn record_follows_from(&self, _span: &Id, _follows: &Id) { + // no-op: we don't track follows-from relationships + } +} diff --git a/src/hyperlight_guest_tracing/src/visitor.rs b/src/hyperlight_guest_tracing/src/visitor.rs new file mode 100644 index 000000000..3b55af5f0 --- /dev/null +++ b/src/hyperlight_guest_tracing/src/visitor.rs @@ -0,0 +1,56 @@ +/* +Copyright 2025 The Hyperlight Authors. + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ +extern crate alloc; + +use core::fmt::Debug; + +use heapless as hl; +use tracing_core::field::{Field, Visit}; + +/// Visitor implementation to collect fields into a vector of key-value pairs +pub(crate) struct FieldsVisitor<'a, const FK: usize, const FV: usize, const F: usize> { + pub out: &'a mut hl::Vec<(hl::String, hl::String), F>, +} + +impl Visit for FieldsVisitor<'_, FK, FV, F> { + fn record_bytes(&mut self, field: &Field, value: &[u8]) { + let mut k = hl::String::::new(); + let mut val = hl::String::::new(); + // Shorten key and value if they are bigger than the space allocated + let _ = k.push_str(&field.name()[..usize::min(field.name().len(), k.capacity())]); + let _ = + val.push_str(&alloc::format!("{value:?}")[..usize::min(value.len(), val.capacity())]); + let _ = self.out.push((k, val)); + } + fn record_str(&mut self, f: &Field, v: &str) { + let mut k = heapless::String::::new(); + let mut val = heapless::String::::new(); + // Shorten key and value if they are bigger than the space allocated + let _ = k.push_str(&f.name()[..usize::min(f.name().len(), k.capacity())]); + let _ = val.push_str(&v[..usize::min(v.len(), val.capacity())]); + let _ = self.out.push((k, val)); + } + fn record_debug(&mut self, f: &Field, v: &dyn Debug) { + use heapless::String; + let mut k = String::::new(); + let mut val = String::::new(); + // Shorten key and value if they are bigger than the space allocated + let _ = k.push_str(&f.name()[..usize::min(f.name().len(), k.capacity())]); + let v = alloc::format!("{v:?}"); + let _ = val.push_str(&v[..usize::min(v.len(), val.capacity())]); + let _ = self.out.push((k, val)); + } +} diff --git a/src/hyperlight_guest_tracing_macro/Cargo.toml b/src/hyperlight_guest_tracing_macro/Cargo.toml deleted file mode 100644 index 2070e868f..000000000 --- a/src/hyperlight_guest_tracing_macro/Cargo.toml +++ /dev/null @@ -1,25 +0,0 @@ -[package] -name = "hyperlight-guest-tracing-macro" -version.workspace = true -edition.workspace = true -rust-version.workspace = true -license.workspace = true -homepage.workspace = true -repository.workspace = true -readme.workspace = true -description = """Provides the tracing macros for the hyperlight guest, enabling structured logging and tracing capabilities.""" - -[dependencies] -proc-macro2 = "1.0" -quote = "1.0.40" -syn = { version = "2.0.106", features = ["full"] } - -[features] -default = [] -trace = [] - -[lib] -proc-macro = true - -[lints] -workspace = true diff --git a/src/hyperlight_guest_tracing_macro/src/lib.rs b/src/hyperlight_guest_tracing_macro/src/lib.rs deleted file mode 100644 index 22a5cdf0e..000000000 --- a/src/hyperlight_guest_tracing_macro/src/lib.rs +++ /dev/null @@ -1,209 +0,0 @@ -/* -Copyright 2025 The Hyperlight Authors. - -Licensed under the Apache License, Version 2.0 (the "License"); -you may not use this file except in compliance with the License. -You may obtain a copy of the License at - - http://www.apache.org/licenses/LICENSE-2.0 - -Unless required by applicable law or agreed to in writing, software -distributed under the License is distributed on an "AS IS" BASIS, -WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -See the License for the specific language governing permissions and -limitations under the License. -*/ - -use proc_macro::TokenStream; -use quote::quote; -use syn::{ItemFn, parse_macro_input}; - -/// A procedural macro attribute for tracing function calls. -/// This macro will create a trace record when the function is called -/// -/// The trace record will contain the function name as a string. -/// Note: This macro is intended to be used with the `hyperlight_guest_tracing` crate. -#[proc_macro_attribute] -pub fn trace_function(_attr: TokenStream, item: TokenStream) -> TokenStream { - let input_fn = parse_macro_input!(item as ItemFn); - - let fn_name = &input_fn.sig.ident; - let fn_name_str = fn_name.to_string(); - let fn_vis = &input_fn.vis; - let fn_sig = &input_fn.sig; - let fn_block = &input_fn.block; - let fn_attrs = &input_fn.attrs; - let fn_output = &input_fn.sig.output; - - // Compose entry/exit messages - let entry_msg = format!("> {}", fn_name_str); - let _exit_msg = format!("< {}", fn_name_str); - - let expanded = match fn_output { - syn::ReturnType::Default => { - // No return value (unit) - #[cfg(feature = "trace")] - quote! { - #(#fn_attrs)* - #fn_vis #fn_sig { - const _: () = assert!( - #entry_msg.len() <= hyperlight_guest_tracing::MAX_TRACE_MSG_LEN, - "Trace message exceeds the maximum bytes length", - ); - ::hyperlight_guest_tracing::create_trace_record(#entry_msg); - // Call the original function body - #fn_block - ::hyperlight_guest_tracing::create_trace_record(#_exit_msg); - } - } - #[cfg(not(feature = "trace"))] - quote! { - #(#fn_attrs)* - #fn_vis #fn_sig { - const _: () = assert!( - #entry_msg.len() <= hyperlight_guest_tracing::MAX_TRACE_MSG_LEN, - "Trace message exceeds the maximum bytes length", - ); - #fn_block - } - } - } - syn::ReturnType::Type(_, _) => { - // Has a return value - #[cfg(feature = "trace")] - quote! { - #(#fn_attrs)* - #fn_vis #fn_sig { - const _: () = assert!( - #entry_msg.len() <= hyperlight_guest_tracing::MAX_TRACE_MSG_LEN, - "Trace message exceeds the maximum bytes length", - ); - ::hyperlight_guest_tracing::create_trace_record(#entry_msg); - let __trace_result = (|| #fn_block )(); - ::hyperlight_guest_tracing::create_trace_record(#_exit_msg); - __trace_result - } - } - #[cfg(not(feature = "trace"))] - quote! { - #(#fn_attrs)* - #fn_vis #fn_sig { - const _: () = assert!( - #entry_msg.len() <= hyperlight_guest_tracing::MAX_TRACE_MSG_LEN, - "Trace message exceeds the maximum bytes length", - ); - #fn_block - } - } - } - }; - - TokenStream::from(expanded) -} - -// Input structure for the trace macro -struct TraceMacroInput { - message: syn::Lit, - statement: Option, -} - -impl syn::parse::Parse for TraceMacroInput { - fn parse(input: syn::parse::ParseStream) -> syn::Result { - let message: syn::Lit = input.parse()?; - if !matches!(message, syn::Lit::Str(_)) { - return Err(input.error("first argument to trace! must be a string literal")); - } - if let syn::Lit::Str(ref lit_str) = message { - if lit_str.value().is_empty() { - return Err(input.error("trace message must not be empty")); - } - } - - let statement = if input.peek(syn::Token![,]) { - let _: syn::Token![,] = input.parse()?; - Some(input.parse()?) - } else { - None - }; - Ok(TraceMacroInput { message, statement }) - } -} - -/// This macro creates a trace record with a message, or traces a block with entry/exit records. -/// -/// When called with an expression or statement as the second argument, it is wrapped in a block, -/// entry and exit trace records are created at the start and end of block, and the result of the block is returned. -#[proc_macro] -pub fn trace(input: TokenStream) -> TokenStream { - let parsed = syn::parse_macro_input!(input as TraceMacroInput); - let trace_message = match parsed.message { - syn::Lit::Str(ref lit_str) => lit_str.value(), - _ => unreachable!(), - }; - if let Some(statement) = parsed.statement { - let entry_msg = format!("+ {}", trace_message); - let _exit_msg = format!("- {}", trace_message); - #[cfg(feature = "trace")] - let expanded = quote! { - { - const _: () = assert!( - #entry_msg.len() <= hyperlight_guest_tracing::MAX_TRACE_MSG_LEN, - "Trace message exceeds the maximum bytes length", - ); - ::hyperlight_guest_tracing::create_trace_record(#entry_msg); - let __trace_result = #statement; - ::hyperlight_guest_tracing::create_trace_record(#_exit_msg); - __trace_result - } - }; - #[cfg(not(feature = "trace"))] - let expanded = quote! { - { - const _: () = assert!( - #entry_msg.len() <= hyperlight_guest_tracing::MAX_TRACE_MSG_LEN, - "Trace message exceeds the maximum bytes length", - ); - #statement - } - }; - - TokenStream::from(expanded) - } else { - #[cfg(feature = "trace")] - let expanded = quote! { - { - const _: () = assert!( - #trace_message.len() <= hyperlight_guest_tracing::MAX_TRACE_MSG_LEN, - "Trace message exceeds the maximum bytes length", - ); - ::hyperlight_guest_tracing::create_trace_record(#trace_message); - } - }; - #[cfg(not(feature = "trace"))] - let expanded = quote! { - { - const _: () = assert!( - #trace_message.len() <= hyperlight_guest_tracing::MAX_TRACE_MSG_LEN, - "Trace message exceeds the maximum bytes length", - ); - } - }; - - TokenStream::from(expanded) - } -} - -/// This macro flushes the trace buffer, sending any remaining trace records to the host. -#[proc_macro] -pub fn flush(_input: TokenStream) -> TokenStream { - #[cfg(feature = "trace")] - let expanded = quote! { - { - ::hyperlight_guest_tracing::flush_trace_buffer(); - } - }; - #[cfg(not(feature = "trace"))] - let expanded = quote! {}; - - TokenStream::from(expanded) -} diff --git a/src/hyperlight_host/Cargo.toml b/src/hyperlight_host/Cargo.toml index ea934c696..eea2b1146 100644 --- a/src/hyperlight_host/Cargo.toml +++ b/src/hyperlight_host/Cargo.toml @@ -35,9 +35,11 @@ page_size = "0.6.0" termcolor = "1.2.0" bitflags = "2.9.4" log = "0.4.28" +opentelemetry = { version = "0.30.0", optional = true } tracing = { version = "0.1.41", features = ["log"] } tracing-log = "0.2.0" tracing-core = "0.1.34" +tracing-opentelemetry = { version = "0.31.0", optional = true } hyperlight-common = { workspace = true, default-features = true, features = [ "std" ] } hyperlight-guest-tracing = { workspace = true, default-features = true, optional = true } vmm-sys-util = "0.15.0" @@ -97,7 +99,7 @@ tracing = "0.1.41" tracing-subscriber = {version = "0.3.20", features = ["std", "env-filter"]} tracing-opentelemetry = "0.31.0" opentelemetry = "0.30.0" -opentelemetry-otlp = { version = "0.30.0", default-features = false, features = ["http-proto", "reqwest-blocking-client"] } +opentelemetry-otlp = { version = "0.30.0", default-features = false, features = ["http-proto", "reqwest-blocking-client", "grpc-tonic"] } opentelemetry-semantic-conventions = "0.30" opentelemetry_sdk = { version = "0.30.0", features = ["rt-tokio"] } tokio = { version = "1.47.1", features = ["full"] } @@ -131,11 +133,8 @@ executable_heap = [] print_debug = [] # Dumps the VM state to a file on unexpected errors or crashes. The path of the file will be printed on stdout and logged. crashdump = ["dep:chrono"] -trace_guest = ["hyperlight-common/trace_guest", "hyperlight-guest-tracing/trace"] -# This feature enables unwinding the guest stack from the host, in -# order to produce stack traces for debugging or profiling. -unwind_guest = [ "trace_guest", "dep:framehop", "dep:fallible-iterator", "hyperlight-common/unwind_guest" ] -mem_profile = [ "unwind_guest", "hyperlight-common/mem_profile" ] +trace_guest = ["dep:opentelemetry", "dep:tracing-opentelemetry", "dep:hyperlight-guest-tracing", "hyperlight-common/trace_guest"] +mem_profile = [ "trace_guest", "dep:framehop", "dep:fallible-iterator", "hyperlight-common/mem_profile" ] kvm = ["dep:kvm-bindings", "dep:kvm-ioctls"] # This feature is deprecated in favor of mshv3 mshv2 = ["dep:mshv-bindings2", "dep:mshv-ioctls2"] diff --git a/src/hyperlight_host/src/hypervisor/arch/mod.rs b/src/hyperlight_host/src/hypervisor/arch/mod.rs new file mode 100644 index 000000000..701bba6f3 --- /dev/null +++ b/src/hyperlight_host/src/hypervisor/arch/mod.rs @@ -0,0 +1,133 @@ +/* +Copyright 2025 The Hyperlight Authors. + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +#[cfg(mshv2)] +extern crate mshv_bindings2 as mshv_bindings; +#[cfg(mshv3)] +extern crate mshv_bindings3 as mshv_bindings; + +#[cfg(kvm)] +use kvm_bindings::kvm_regs; +#[cfg(any(mshv2, mshv3))] +use mshv_bindings::StandardRegisters; + +#[cfg(target_os = "windows")] +use crate::hypervisor::wrappers::WHvGeneralRegisters; + +/// Struct that contains the x86_64 core registers +#[allow(dead_code)] +#[derive(Debug, Default)] +pub(crate) struct X86_64Regs { + pub(crate) rax: u64, + pub(crate) rbx: u64, + pub(crate) rcx: u64, + pub(crate) rdx: u64, + pub(crate) rsi: u64, + pub(crate) rdi: u64, + pub(crate) rbp: u64, + pub(crate) rsp: u64, + pub(crate) r8: u64, + pub(crate) r9: u64, + pub(crate) r10: u64, + pub(crate) r11: u64, + pub(crate) r12: u64, + pub(crate) r13: u64, + pub(crate) r14: u64, + pub(crate) r15: u64, + pub(crate) rip: u64, + pub(crate) rflags: u64, +} + +#[cfg(kvm)] +impl From for X86_64Regs { + #[inline(always)] + fn from(regs: kvm_regs) -> Self { + X86_64Regs { + rax: regs.rax, + rbx: regs.rbx, + rcx: regs.rcx, + rdx: regs.rdx, + rdi: regs.rdi, + rsi: regs.rsi, + rsp: regs.rsp, + rbp: regs.rbp, + r8: regs.r8, + r9: regs.r9, + r10: regs.r10, + r11: regs.r11, + r12: regs.r12, + r13: regs.r13, + r14: regs.r14, + r15: regs.r15, + rip: regs.rip, + rflags: regs.rflags, + } + } +} + +#[cfg(mshv)] +impl From for X86_64Regs { + #[inline(always)] + fn from(regs: StandardRegisters) -> Self { + X86_64Regs { + rax: regs.rax, + rbx: regs.rbx, + rcx: regs.rcx, + rdx: regs.rdx, + rdi: regs.rdi, + rsi: regs.rsi, + rsp: regs.rsp, + rbp: regs.rbp, + r8: regs.r8, + r9: regs.r9, + r10: regs.r10, + r11: regs.r11, + r12: regs.r12, + r13: regs.r13, + r14: regs.r14, + r15: regs.r15, + rip: regs.rip, + rflags: regs.rflags, + } + } +} + +#[cfg(target_os = "windows")] +impl From for X86_64Regs { + #[inline(always)] + fn from(regs: WHvGeneralRegisters) -> Self { + X86_64Regs { + rax: regs.rax, + rbx: regs.rbx, + rcx: regs.rcx, + rdx: regs.rdx, + rdi: regs.rdi, + rsi: regs.rsi, + rsp: regs.rsp, + rbp: regs.rbp, + r8: regs.r8, + r9: regs.r9, + r10: regs.r10, + r11: regs.r11, + r12: regs.r12, + r13: regs.r13, + r14: regs.r14, + r15: regs.r15, + rip: regs.rip, + rflags: regs.rflags, + } + } +} diff --git a/src/hyperlight_host/src/hypervisor/gdb/hyperv_debug.rs b/src/hyperlight_host/src/hypervisor/gdb/hyperv_debug.rs index 7a902d6de..12da59de2 100644 --- a/src/hyperlight_host/src/hypervisor/gdb/hyperv_debug.rs +++ b/src/hyperlight_host/src/hypervisor/gdb/hyperv_debug.rs @@ -19,7 +19,8 @@ use std::collections::HashMap; use windows::Win32::System::Hypervisor::WHV_VP_EXCEPTION_CONTEXT; use super::arch::{MAX_NO_OF_HW_BP, vcpu_stop_reason}; -use super::{GuestDebug, SW_BP_SIZE, VcpuStopReason, X86_64Regs}; +use super::{GuestDebug, SW_BP_SIZE, VcpuStopReason}; +use crate::hypervisor::arch::X86_64Regs; use crate::hypervisor::windows_hypervisor_platform::VMProcessor; use crate::hypervisor::wrappers::{WHvDebugRegisters, WHvGeneralRegisters}; use crate::{HyperlightError, Result, new_error}; diff --git a/src/hyperlight_host/src/hypervisor/gdb/kvm_debug.rs b/src/hyperlight_host/src/hypervisor/gdb/kvm_debug.rs index c20b3b279..1fdf9fe19 100644 --- a/src/hyperlight_host/src/hypervisor/gdb/kvm_debug.rs +++ b/src/hyperlight_host/src/hypervisor/gdb/kvm_debug.rs @@ -23,7 +23,8 @@ use kvm_bindings::{ use kvm_ioctls::VcpuFd; use super::arch::{MAX_NO_OF_HW_BP, SW_BP_SIZE, vcpu_stop_reason}; -use super::{GuestDebug, VcpuStopReason, X86_64Regs}; +use super::{GuestDebug, VcpuStopReason}; +use crate::hypervisor::arch::X86_64Regs; use crate::{HyperlightError, Result, new_error}; /// KVM Debug struct diff --git a/src/hyperlight_host/src/hypervisor/gdb/mod.rs b/src/hyperlight_host/src/hypervisor/gdb/mod.rs index 118246d3c..2f485e548 100644 --- a/src/hyperlight_host/src/hypervisor/gdb/mod.rs +++ b/src/hyperlight_host/src/hypervisor/gdb/mod.rs @@ -46,6 +46,7 @@ use thiserror::Error; use x86_64_target::HyperlightSandboxTarget; use super::InterruptHandle; +use crate::hypervisor::arch::X86_64Regs; use crate::mem::layout::SandboxMemoryLayout; use crate::mem::shared_mem::HostSharedMemory; use crate::sandbox::mem_mgr::MemMgrWrapper; @@ -88,29 +89,6 @@ impl From for TargetError { } } -/// Struct that contains the x86_64 core registers -#[derive(Debug, Default)] -pub(crate) struct X86_64Regs { - pub(crate) rax: u64, - pub(crate) rbx: u64, - pub(crate) rcx: u64, - pub(crate) rdx: u64, - pub(crate) rsi: u64, - pub(crate) rdi: u64, - pub(crate) rbp: u64, - pub(crate) rsp: u64, - pub(crate) r8: u64, - pub(crate) r9: u64, - pub(crate) r10: u64, - pub(crate) r11: u64, - pub(crate) r12: u64, - pub(crate) r13: u64, - pub(crate) r14: u64, - pub(crate) r15: u64, - pub(crate) rip: u64, - pub(crate) rflags: u64, -} - /// Defines the possible reasons for which a vCPU can be stopped when debugging #[derive(Debug)] pub enum VcpuStopReason { diff --git a/src/hyperlight_host/src/hypervisor/gdb/mshv_debug.rs b/src/hyperlight_host/src/hypervisor/gdb/mshv_debug.rs index 9688d9ed1..1c44f98ee 100644 --- a/src/hyperlight_host/src/hypervisor/gdb/mshv_debug.rs +++ b/src/hyperlight_host/src/hypervisor/gdb/mshv_debug.rs @@ -33,7 +33,8 @@ use mshv_bindings::{ use mshv_ioctls::VcpuFd; use super::arch::{MAX_NO_OF_HW_BP, SW_BP_SIZE, vcpu_stop_reason}; -use super::{GuestDebug, VcpuStopReason, X86_64Regs}; +use super::{GuestDebug, VcpuStopReason}; +use crate::hypervisor::arch::X86_64Regs; use crate::{HyperlightError, Result, new_error}; #[derive(Debug, Default)] diff --git a/src/hyperlight_host/src/hypervisor/gdb/x86_64_target.rs b/src/hyperlight_host/src/hypervisor/gdb/x86_64_target.rs index 3248e6082..4b6592db7 100644 --- a/src/hyperlight_host/src/hypervisor/gdb/x86_64_target.rs +++ b/src/hyperlight_host/src/hypervisor/gdb/x86_64_target.rs @@ -31,8 +31,9 @@ use gdbstub::target::ext::section_offsets::{Offsets, SectionOffsets}; use gdbstub::target::{Target, TargetError, TargetResult}; use gdbstub_arch::x86::X86_64_SSE as GdbTargetArch; -use super::{DebugCommChannel, DebugMsg, DebugResponse, GdbTargetError, X86_64Regs}; +use super::{DebugCommChannel, DebugMsg, DebugResponse, GdbTargetError}; use crate::hypervisor::InterruptHandle; +use crate::hypervisor::arch::X86_64Regs; /// Gdbstub target used by the gdbstub crate to provide GDB protocol implementation pub(crate) struct HyperlightSandboxTarget { diff --git a/src/hyperlight_host/src/hypervisor/hyperv_linux.rs b/src/hyperlight_host/src/hypervisor/hyperv_linux.rs index 1907d8e0b..7844b71a5 100644 --- a/src/hyperlight_host/src/hypervisor/hyperv_linux.rs +++ b/src/hyperlight_host/src/hypervisor/hyperv_linux.rs @@ -48,18 +48,13 @@ use mshv_bindings::{ hv_partition_property_code_HV_PARTITION_PROPERTY_SYNTHETIC_PROC_FEATURES, hv_partition_synthetic_processor_features, }; -#[cfg(feature = "trace_guest")] -use mshv_bindings::{ - hv_register_name, hv_register_name_HV_X64_REGISTER_RAX, hv_register_name_HV_X64_REGISTER_RBP, - hv_register_name_HV_X64_REGISTER_RCX, hv_register_name_HV_X64_REGISTER_RSP, -}; use mshv_ioctls::{Mshv, VcpuFd, VmFd}; use tracing::{Span, instrument}; +#[cfg(feature = "trace_guest")] +use tracing_opentelemetry::OpenTelemetrySpanExt; #[cfg(crashdump)] use {super::crashdump, std::path::Path}; -#[cfg(feature = "trace_guest")] -use super::TraceRegister; use super::fpu::{FP_CONTROL_WORD_DEFAULT, FP_TAG_WORD_DEFAULT, MXCSR_DEFAULT}; #[cfg(gdb)] use super::gdb::{ @@ -73,16 +68,18 @@ use super::{ use super::{HyperlightExit, Hypervisor, InterruptHandle, LinuxInterruptHandle, VirtualCPU}; #[cfg(gdb)] use crate::HyperlightError; +#[cfg(feature = "trace_guest")] +use crate::hypervisor::arch::X86_64Regs; use crate::hypervisor::get_memory_access_violation; use crate::mem::memory_region::{MemoryRegion, MemoryRegionFlags}; use crate::mem::ptr::{GuestPtr, RawPtr}; use crate::mem::shared_mem::HostSharedMemory; use crate::sandbox::SandboxConfiguration; -#[cfg(feature = "trace_guest")] -use crate::sandbox::TraceInfo; use crate::sandbox::host_funcs::FunctionRegistry; use crate::sandbox::mem_mgr::MemMgrWrapper; use crate::sandbox::outb::handle_outb; +#[cfg(feature = "mem_profile")] +use crate::sandbox::trace::MemTraceInfo; #[cfg(crashdump)] use crate::sandbox::uninitialized::SandboxRuntimeConfig; use crate::{Result, log_then_return, new_error}; @@ -93,7 +90,8 @@ mod debug { use super::mshv_bindings::hv_x64_exception_intercept_message; use super::{HypervLinuxDriver, *}; - use crate::hypervisor::gdb::{DebugMsg, DebugResponse, VcpuStopReason, X86_64Regs}; + use crate::hypervisor::arch::X86_64Regs; + use crate::hypervisor::gdb::{DebugMsg, DebugResponse, VcpuStopReason}; use crate::mem::shared_mem::HostSharedMemory; use crate::sandbox::mem_mgr::MemMgrWrapper; use crate::{Result, new_error}; @@ -324,9 +322,8 @@ pub(crate) struct HypervLinuxDriver { gdb_conn: Option>, #[cfg(crashdump)] rt_cfg: SandboxRuntimeConfig, - #[cfg(feature = "trace_guest")] - #[allow(dead_code)] - trace_info: TraceInfo, + #[cfg(feature = "mem_profile")] + trace_info: MemTraceInfo, } impl HypervLinuxDriver { @@ -349,7 +346,7 @@ impl HypervLinuxDriver { config: &SandboxConfiguration, #[cfg(gdb)] gdb_conn: Option>, #[cfg(crashdump)] rt_cfg: SandboxRuntimeConfig, - #[cfg(feature = "trace_guest")] trace_info: TraceInfo, + #[cfg(feature = "mem_profile")] trace_info: MemTraceInfo, ) -> Result { let mshv = Mshv::new()?; let pr = Default::default(); @@ -460,7 +457,7 @@ impl HypervLinuxDriver { gdb_conn, #[cfg(crashdump)] rt_cfg, - #[cfg(feature = "trace_guest")] + #[cfg(feature = "mem_profile")] trace_info, }; @@ -564,19 +561,6 @@ impl Debug for HypervLinuxDriver { } } -#[cfg(feature = "trace_guest")] -impl From for hv_register_name { - fn from(r: TraceRegister) -> Self { - match r { - TraceRegister::RAX => hv_register_name_HV_X64_REGISTER_RAX, - TraceRegister::RCX => hv_register_name_HV_X64_REGISTER_RCX, - TraceRegister::RIP => hv_register_name_HV_X64_REGISTER_RIP, - TraceRegister::RSP => hv_register_name_HV_X64_REGISTER_RSP, - TraceRegister::RBP => hv_register_name_HV_X64_REGISTER_RBP, - } - } -} - impl Hypervisor for HypervLinuxDriver { #[instrument(err(Debug), skip_all, parent = Span::current(), level = "Trace")] fn initialise( @@ -702,7 +686,7 @@ impl Hypervisor for HypervLinuxDriver { padded[..copy_len].copy_from_slice(&data[..copy_len]); let val = u32::from_le_bytes(padded); - #[cfg(feature = "trace_guest")] + #[cfg(feature = "mem_profile")] { // We need to handle the borrow checker issue where we need both: // - &mut MemMgrWrapper (from self.mem_mgr.as_mut()) @@ -723,7 +707,7 @@ impl Hypervisor for HypervLinuxDriver { self.mem_mgr = Some(mem_mgr); } - #[cfg(not(feature = "trace_guest"))] + #[cfg(not(feature = "mem_profile"))] { let mem_mgr = self .mem_mgr @@ -750,7 +734,10 @@ impl Hypervisor for HypervLinuxDriver { } #[instrument(err(Debug), skip_all, parent = Span::current(), level = "Trace")] - fn run(&mut self) -> Result { + fn run( + &mut self, + #[cfg(feature = "trace_guest")] tc: &mut crate::sandbox::trace::TraceContext, + ) -> Result { const HALT_MESSAGE: hv_message_type = hv_message_type_HVMSG_X64_HALT; const IO_PORT_INTERCEPT_MESSAGE: hv_message_type = hv_message_type_HVMSG_X64_IO_PORT_INTERCEPT; @@ -793,13 +780,8 @@ impl Hypervisor for HypervLinuxDriver { Err(mshv_ioctls::MshvError::from(libc::EINTR)) } else { #[cfg(feature = "trace_guest")] - if self.trace_info.guest_start_epoch.is_none() { - // Store the guest start epoch and cycles to trace the guest execution time - crate::debug!("MSHV - Guest Start Epoch set"); - self.trace_info.guest_start_tsc = - Some(hyperlight_guest_tracing::invariant_tsc::read_tsc()); - self.trace_info.guest_start_epoch = Some(std::time::Instant::now()); - } + tc.setup_guest_trace(Span::current().context()); + // Note: if a `InterruptHandle::kill()` called while this thread is **here** // Then the vcpu will run, but we will keep sending signals to this thread // to interrupt it until `running` is set to false. The `vcpu_fd::run()` call will @@ -1161,22 +1143,23 @@ impl Hypervisor for HypervLinuxDriver { } #[cfg(feature = "trace_guest")] - fn read_trace_reg(&self, reg: TraceRegister) -> Result { - let mut assoc = [hv_register_assoc { - name: reg.into(), - ..Default::default() - }]; - self.vcpu_fd.get_reg(&mut assoc)?; - // safety: all registers that we currently support are 64-bit - unsafe { Ok(assoc[0].value.reg64) } + fn read_regs(&self) -> Result { + Ok(X86_64Regs::from(self.vcpu_fd.get_regs()?)) } #[cfg(feature = "trace_guest")] - fn trace_info_as_ref(&self) -> &TraceInfo { - &self.trace_info + fn handle_trace(&mut self, tc: &mut crate::sandbox::trace::TraceContext) -> Result<()> { + let regs = self.read_regs()?; + tc.handle_trace( + ®s, + self.mem_mgr.as_ref().ok_or_else(|| { + new_error!("Memory manager is not initialized before handling trace") + })?, + ) } - #[cfg(feature = "trace_guest")] - fn trace_info_as_mut(&mut self) -> &mut TraceInfo { + + #[cfg(feature = "mem_profile")] + fn trace_info_mut(&mut self) -> &mut MemTraceInfo { &mut self.trace_info } } @@ -1198,7 +1181,7 @@ impl Drop for HypervLinuxDriver { #[cfg(test)] mod tests { use super::*; - #[cfg(feature = "unwind_guest")] + #[cfg(feature = "mem_profile")] use crate::mem::exe::DummyUnwindInfo; use crate::mem::memory_region::MemoryRegionVecBuilder; use crate::mem::shared_mem::{ExclusiveSharedMemory, SharedMemory}; @@ -1267,12 +1250,8 @@ mod tests { #[cfg(crashdump)] guest_core_dump: true, }, - #[cfg(feature = "trace_guest")] - TraceInfo::new( - #[cfg(feature = "unwind_guest")] - Arc::new(DummyUnwindInfo {}), - ) - .unwrap(), + #[cfg(feature = "mem_profile")] + MemTraceInfo::new(Arc::new(DummyUnwindInfo {})).unwrap(), ) .unwrap(); } diff --git a/src/hyperlight_host/src/hypervisor/hyperv_windows.rs b/src/hyperlight_host/src/hypervisor/hyperv_windows.rs index f8b4727d1..06f18712b 100644 --- a/src/hyperlight_host/src/hypervisor/hyperv_windows.rs +++ b/src/hyperlight_host/src/hypervisor/hyperv_windows.rs @@ -22,6 +22,8 @@ use std::sync::{Arc, Mutex}; use log::LevelFilter; use tracing::{Span, instrument}; +#[cfg(feature = "trace_guest")] +use tracing_opentelemetry::OpenTelemetrySpanExt; use windows::Win32::System::Hypervisor::{ WHV_MEMORY_ACCESS_TYPE, WHV_PARTITION_HANDLE, WHV_REGISTER_VALUE, WHV_RUN_VP_EXIT_CONTEXT, WHV_RUN_VP_EXIT_REASON, WHV_X64_SEGMENT_REGISTER, WHV_X64_SEGMENT_REGISTER_0, @@ -41,8 +43,6 @@ use { crate::HyperlightError, }; -#[cfg(feature = "trace_guest")] -use super::TraceRegister; use super::fpu::{FP_TAG_WORD_DEFAULT, MXCSR_DEFAULT}; use super::surrogate_process::SurrogateProcess; use super::surrogate_process_manager::*; @@ -54,17 +54,19 @@ use super::{ EFER_LMA, EFER_LME, EFER_NX, EFER_SCE, }; use super::{HyperlightExit, Hypervisor, InterruptHandle, VirtualCPU}; +#[cfg(feature = "trace_guest")] +use crate::hypervisor::arch::X86_64Regs; use crate::hypervisor::fpu::FP_CONTROL_WORD_DEFAULT; use crate::hypervisor::get_memory_access_violation; use crate::hypervisor::wrappers::WHvGeneralRegisters; use crate::mem::memory_region::{MemoryRegion, MemoryRegionFlags}; use crate::mem::ptr::{GuestPtr, RawPtr}; use crate::mem::shared_mem::HostSharedMemory; -#[cfg(feature = "trace_guest")] -use crate::sandbox::TraceInfo; use crate::sandbox::host_funcs::FunctionRegistry; use crate::sandbox::mem_mgr::MemMgrWrapper; use crate::sandbox::outb::handle_outb; +#[cfg(feature = "mem_profile")] +use crate::sandbox::trace::MemTraceInfo; #[cfg(crashdump)] use crate::sandbox::uninitialized::SandboxRuntimeConfig; use crate::{Result, debug, log_then_return, new_error}; @@ -77,7 +79,8 @@ mod debug { use super::{HypervWindowsDriver, *}; use crate::Result; - use crate::hypervisor::gdb::{DebugMsg, DebugResponse, VcpuStopReason, X86_64Regs}; + use crate::hypervisor::arch::X86_64Regs; + use crate::hypervisor::gdb::{DebugMsg, DebugResponse, VcpuStopReason}; use crate::mem::shared_mem::HostSharedMemory; use crate::sandbox::mem_mgr::MemMgrWrapper; @@ -291,9 +294,8 @@ pub(crate) struct HypervWindowsDriver { gdb_conn: Option>, #[cfg(crashdump)] rt_cfg: SandboxRuntimeConfig, - #[cfg(feature = "trace_guest")] - #[allow(dead_code)] - trace_info: TraceInfo, + #[cfg(feature = "mem_profile")] + trace_info: MemTraceInfo, } /* This does not automatically impl Send because the host * address of the shared memory region is a raw pointer, which are @@ -315,7 +317,7 @@ impl HypervWindowsDriver { mmap_file_handle: HandleWrapper, #[cfg(gdb)] gdb_conn: Option>, #[cfg(crashdump)] rt_cfg: SandboxRuntimeConfig, - #[cfg(feature = "trace_guest")] trace_info: TraceInfo, + #[cfg(feature = "mem_profile")] trace_info: MemTraceInfo, ) -> Result { // create and setup hypervisor partition let mut partition = VMPartition::new(1)?; @@ -369,7 +371,7 @@ impl HypervWindowsDriver { gdb_conn, #[cfg(crashdump)] rt_cfg, - #[cfg(feature = "trace_guest")] + #[cfg(feature = "mem_profile")] trace_info, }; @@ -693,7 +695,7 @@ impl Hypervisor for HypervWindowsDriver { padded[..copy_len].copy_from_slice(&data[..copy_len]); let val = u32::from_le_bytes(padded); - #[cfg(feature = "trace_guest")] + #[cfg(feature = "mem_profile")] { // We need to handle the borrow checker issue where we need both: // - &mut MemMgrWrapper (from self.mem_mgr.as_mut()) @@ -714,7 +716,7 @@ impl Hypervisor for HypervWindowsDriver { self.mem_mgr = Some(mem_mgr); } - #[cfg(not(feature = "trace_guest"))] + #[cfg(not(feature = "mem_profile"))] { let mem_mgr = self .mem_mgr @@ -735,7 +737,10 @@ impl Hypervisor for HypervWindowsDriver { } #[instrument(err(Debug), skip_all, parent = Span::current(), level = "Trace")] - fn run(&mut self) -> Result { + fn run( + &mut self, + #[cfg(feature = "trace_guest")] tc: &mut crate::sandbox::trace::TraceContext, + ) -> Result { self.interrupt_handle.running.store(true, Ordering::Relaxed); #[cfg(not(gdb))] @@ -761,13 +766,8 @@ impl Hypervisor for HypervWindowsDriver { } } else { #[cfg(feature = "trace_guest")] - if self.trace_info.guest_start_epoch.is_none() { - // Store the guest start epoch and cycles to trace the guest execution time - crate::debug!("HyperV - Guest Start Epoch set"); - self.trace_info.guest_start_tsc = - Some(hyperlight_guest_tracing::invariant_tsc::read_tsc()); - self.trace_info.guest_start_epoch = Some(std::time::Instant::now()); - } + tc.setup_guest_trace(Span::current().context()); + self.processor.run()? }; self.interrupt_handle @@ -1094,23 +1094,19 @@ impl Hypervisor for HypervWindowsDriver { } #[cfg(feature = "trace_guest")] - fn read_trace_reg(&self, reg: TraceRegister) -> Result { + fn read_regs(&self) -> Result { let regs = self.processor.get_regs()?; - match reg { - TraceRegister::RAX => Ok(regs.rax), - TraceRegister::RCX => Ok(regs.rcx), - TraceRegister::RIP => Ok(regs.rip), - TraceRegister::RSP => Ok(regs.rsp), - TraceRegister::RBP => Ok(regs.rbp), - } + Ok(X86_64Regs::from(regs)) } #[cfg(feature = "trace_guest")] - fn trace_info_as_ref(&self) -> &TraceInfo { - &self.trace_info + fn handle_trace(&mut self, tc: &mut crate::sandbox::trace::TraceContext) -> Result<()> { + let regs = self.read_regs()?; + tc.handle_trace(®s, self.mem_mgr.as_ref().unwrap()) } - #[cfg(feature = "trace_guest")] - fn trace_info_as_mut(&mut self) -> &mut TraceInfo { + + #[cfg(feature = "mem_profile")] + fn trace_info_mut(&mut self) -> &mut MemTraceInfo { &mut self.trace_info } } diff --git a/src/hyperlight_host/src/hypervisor/kvm.rs b/src/hyperlight_host/src/hypervisor/kvm.rs index be76129fb..3d5cadc57 100644 --- a/src/hyperlight_host/src/hypervisor/kvm.rs +++ b/src/hyperlight_host/src/hypervisor/kvm.rs @@ -24,11 +24,11 @@ use kvm_ioctls::Cap::UserMemory; use kvm_ioctls::{Kvm, VcpuExit, VcpuFd, VmFd}; use log::LevelFilter; use tracing::{Span, instrument}; +#[cfg(feature = "trace_guest")] +use tracing_opentelemetry::OpenTelemetrySpanExt; #[cfg(crashdump)] use {super::crashdump, std::path::Path}; -#[cfg(feature = "trace_guest")] -use super::TraceRegister; use super::fpu::{FP_CONTROL_WORD_DEFAULT, FP_TAG_WORD_DEFAULT, MXCSR_DEFAULT}; #[cfg(gdb)] use super::gdb::{DebugCommChannel, DebugMsg, DebugResponse, GuestDebug, KvmDebug, VcpuStopReason}; @@ -40,16 +40,18 @@ use super::{ use super::{HyperlightExit, Hypervisor, InterruptHandle, LinuxInterruptHandle, VirtualCPU}; #[cfg(gdb)] use crate::HyperlightError; +#[cfg(feature = "trace_guest")] +use crate::hypervisor::arch::X86_64Regs; use crate::hypervisor::get_memory_access_violation; use crate::mem::memory_region::{MemoryRegion, MemoryRegionFlags}; use crate::mem::ptr::{GuestPtr, RawPtr}; use crate::mem::shared_mem::HostSharedMemory; use crate::sandbox::SandboxConfiguration; -#[cfg(feature = "trace_guest")] -use crate::sandbox::TraceInfo; use crate::sandbox::host_funcs::FunctionRegistry; use crate::sandbox::mem_mgr::MemMgrWrapper; use crate::sandbox::outb::handle_outb; +#[cfg(feature = "mem_profile")] +use crate::sandbox::trace::MemTraceInfo; #[cfg(crashdump)] use crate::sandbox::uninitialized::SandboxRuntimeConfig; use crate::{Result, log_then_return, new_error}; @@ -83,9 +85,8 @@ mod debug { use kvm_bindings::kvm_debug_exit_arch; use super::KVMDriver; - use crate::hypervisor::gdb::{ - DebugMsg, DebugResponse, GuestDebug, KvmDebug, VcpuStopReason, X86_64Regs, - }; + use crate::hypervisor::arch::X86_64Regs; + use crate::hypervisor::gdb::{DebugMsg, DebugResponse, GuestDebug, KvmDebug, VcpuStopReason}; use crate::mem::shared_mem::HostSharedMemory; use crate::sandbox::mem_mgr::MemMgrWrapper; use crate::{Result, new_error}; @@ -306,9 +307,8 @@ pub(crate) struct KVMDriver { gdb_conn: Option>, #[cfg(crashdump)] rt_cfg: SandboxRuntimeConfig, - #[cfg(feature = "trace_guest")] - #[allow(dead_code)] - trace_info: TraceInfo, + #[cfg(feature = "mem_profile")] + trace_info: MemTraceInfo, } impl KVMDriver { @@ -326,7 +326,7 @@ impl KVMDriver { config: &SandboxConfiguration, #[cfg(gdb)] gdb_conn: Option>, #[cfg(crashdump)] rt_cfg: SandboxRuntimeConfig, - #[cfg(feature = "trace_guest")] trace_info: TraceInfo, + #[cfg(feature = "mem_profile")] trace_info: MemTraceInfo, ) -> Result { let kvm = Kvm::new()?; @@ -399,7 +399,7 @@ impl KVMDriver { gdb_conn, #[cfg(crashdump)] rt_cfg, - #[cfg(feature = "trace_guest")] + #[cfg(feature = "mem_profile")] trace_info, }; @@ -620,7 +620,7 @@ impl Hypervisor for KVMDriver { padded[..copy_len].copy_from_slice(&data[..copy_len]); let value = u32::from_le_bytes(padded); - #[cfg(feature = "trace_guest")] + #[cfg(feature = "mem_profile")] { // We need to handle the borrow checker issue where we need both: // - &mut MemMgrWrapper (from self.mem_mgr.as_mut()) @@ -641,7 +641,7 @@ impl Hypervisor for KVMDriver { self.mem_mgr = Some(mem_mgr); } - #[cfg(not(feature = "trace_guest"))] + #[cfg(not(feature = "mem_profile"))] { let mem_mgr = self .mem_mgr @@ -661,7 +661,10 @@ impl Hypervisor for KVMDriver { } #[instrument(err(Debug), skip_all, parent = Span::current(), level = "Trace")] - fn run(&mut self) -> Result { + fn run( + &mut self, + #[cfg(feature = "trace_guest")] tc: &mut crate::sandbox::trace::TraceContext, + ) -> Result { self.interrupt_handle .tid .store(unsafe { libc::pthread_self() as u64 }, Ordering::Relaxed); @@ -695,13 +698,7 @@ impl Hypervisor for KVMDriver { Err(kvm_ioctls::Error::new(libc::EINTR)) } else { #[cfg(feature = "trace_guest")] - if self.trace_info.guest_start_epoch.is_none() { - // Store the guest start epoch and cycles to trace the guest execution time - crate::debug!("KVM - Guest Start Epoch set"); - self.trace_info.guest_start_epoch = Some(std::time::Instant::now()); - self.trace_info.guest_start_tsc = - Some(hyperlight_guest_tracing::invariant_tsc::read_tsc()); - } + tc.setup_guest_trace(Span::current().context()); // Note: if a `InterruptHandle::kill()` called while this thread is **here** // Then the vcpu will run, but we will keep sending signals to this thread @@ -1038,23 +1035,23 @@ impl Hypervisor for KVMDriver { } #[cfg(feature = "trace_guest")] - fn read_trace_reg(&self, reg: TraceRegister) -> Result { - let regs = self.vcpu_fd.get_regs()?; - Ok(match reg { - TraceRegister::RAX => regs.rax, - TraceRegister::RCX => regs.rcx, - TraceRegister::RIP => regs.rip, - TraceRegister::RSP => regs.rsp, - TraceRegister::RBP => regs.rbp, - }) + fn read_regs(&self) -> Result { + Ok(X86_64Regs::from(self.vcpu_fd.get_regs()?)) } #[cfg(feature = "trace_guest")] - fn trace_info_as_ref(&self) -> &TraceInfo { - &self.trace_info + fn handle_trace(&mut self, tc: &mut crate::sandbox::trace::TraceContext) -> Result<()> { + let regs = self.read_regs()?; + tc.handle_trace( + ®s, + self.mem_mgr.as_ref().ok_or_else(|| { + new_error!("Memory manager is not initialized before handling trace") + })?, + ) } - #[cfg(feature = "trace_guest")] - fn trace_info_as_mut(&mut self) -> &mut TraceInfo { + + #[cfg(feature = "mem_profile")] + fn trace_info_mut(&mut self) -> &mut MemTraceInfo { &mut self.trace_info } } diff --git a/src/hyperlight_host/src/hypervisor/mod.rs b/src/hyperlight_host/src/hypervisor/mod.rs index 4e55e7ac5..7742aa386 100644 --- a/src/hyperlight_host/src/hypervisor/mod.rs +++ b/src/hyperlight_host/src/hypervisor/mod.rs @@ -21,10 +21,12 @@ use crate::HyperlightError::StackOverflow; use crate::error::HyperlightError::ExecutionCanceledByHost; use crate::mem::memory_region::{MemoryRegion, MemoryRegionFlags}; use crate::metrics::METRIC_GUEST_CANCELLATION; -#[cfg(feature = "trace_guest")] -use crate::sandbox::TraceInfo; +#[cfg(feature = "mem_profile")] +use crate::sandbox::trace::MemTraceInfo; use crate::{HyperlightError, Result, log_then_return}; +/// Architecture-specific code for the hypervisor. +pub(crate) mod arch; /// Util for handling x87 fpu state #[cfg(any(kvm, mshv, target_os = "windows"))] pub mod fpu; @@ -116,21 +118,6 @@ pub enum HyperlightExit { Retry(), } -/// Registers which may be useful for tracing/stack unwinding -#[cfg(feature = "trace_guest")] -pub enum TraceRegister { - /// RAX - RAX, - /// RCX - RCX, - /// RIP - RIP, - /// RSP - RSP, - /// RBP - RBP, -} - /// A common set of hypervisor functionality pub(crate) trait Hypervisor: Debug + Send { /// Initialise the internally stored vCPU with the given PEB address and @@ -184,7 +171,10 @@ pub(crate) trait Hypervisor: Debug + Send { ) -> Result<()>; /// Run the vCPU - fn run(&mut self) -> Result; + fn run( + &mut self, + #[cfg(feature = "trace_guest")] tc: &mut crate::sandbox::trace::TraceContext, + ) -> Result; /// Get InterruptHandle to underlying VM fn interrupt_handle(&self) -> Arc; @@ -246,15 +236,16 @@ pub(crate) trait Hypervisor: Debug + Send { fn check_stack_guard(&self) -> Result; /// Read a register for trace/unwind purposes + #[allow(dead_code)] #[cfg(feature = "trace_guest")] - fn read_trace_reg(&self, reg: TraceRegister) -> Result; + fn read_regs(&self) -> Result; - /// Get a reference of the trace info for the guest #[cfg(feature = "trace_guest")] - fn trace_info_as_ref(&self) -> &TraceInfo; + fn handle_trace(&mut self, tc: &mut crate::sandbox::trace::TraceContext) -> Result<()>; + /// Get a mutable reference of the trace info for the guest - #[cfg(feature = "trace_guest")] - fn trace_info_as_mut(&mut self) -> &mut TraceInfo; + #[cfg(feature = "mem_profile")] + fn trace_info_mut(&mut self) -> &mut MemTraceInfo; } /// Returns a Some(HyperlightExit::AccessViolation(..)) if the given gpa doesn't have @@ -291,8 +282,31 @@ impl VirtualCPU { hv: &mut dyn Hypervisor, #[cfg(gdb)] dbg_mem_access_fn: Arc>>, ) -> Result<()> { + // Keeps the trace context and open spans + #[cfg(feature = "trace_guest")] + let mut tc = crate::sandbox::trace::TraceContext::new(); + loop { - match hv.run() { + #[cfg(feature = "trace_guest")] + let result = { + let result = hv.run(&mut tc); + // End current host trace by closing the current span that captures traces + // happening when a guest exits and re-enters. + tc.end_host_trace(); + + // Handle the guest trace data if any + if let Err(e) = hv.handle_trace(&mut tc) { + // If no trace data is available, we just log a message and continue + // Is this the right thing to do? + log::debug!("Error handling guest trace: {:?}", e); + } + + result + }; + #[cfg(not(feature = "trace_guest"))] + let result = hv.run(); + + match result { #[cfg(gdb)] Ok(HyperlightExit::Debug(stop_reason)) => { if let Err(e) = hv.handle_debug(dbg_mem_access_fn.clone(), stop_reason) { diff --git a/src/hyperlight_host/src/mem/elf.rs b/src/hyperlight_host/src/mem/elf.rs index ff83d42c8..3a30354ef 100644 --- a/src/hyperlight_host/src/mem/elf.rs +++ b/src/hyperlight_host/src/mem/elf.rs @@ -14,7 +14,7 @@ See the License for the specific language governing permissions and limitations under the License. */ -#[cfg(feature = "unwind_guest")] +#[cfg(feature = "mem_profile")] use std::sync::Arc; #[cfg(target_arch = "aarch64")] @@ -29,7 +29,7 @@ use goblin::elf64::program_header::PT_LOAD; use crate::{Result, log_then_return, new_error}; -#[cfg(feature = "unwind_guest")] +#[cfg(feature = "mem_profile")] struct ResolvedSectionHeader { name: String, addr: u64, @@ -40,13 +40,13 @@ struct ResolvedSectionHeader { pub(crate) struct ElfInfo { payload: Vec, phdrs: ProgramHeaders, - #[cfg(feature = "unwind_guest")] + #[cfg(feature = "mem_profile")] shdrs: Vec, entry: u64, relocs: Vec, } -#[cfg(feature = "unwind_guest")] +#[cfg(feature = "mem_profile")] struct UnwindInfo { payload: Vec, load_addr: u64, @@ -55,7 +55,7 @@ struct UnwindInfo { shdrs: Vec, } -#[cfg(feature = "unwind_guest")] +#[cfg(feature = "mem_profile")] impl super::exe::UnwindInfo for UnwindInfo { fn as_module(&self) -> framehop::Module> { framehop::Module::new( @@ -72,7 +72,7 @@ impl super::exe::UnwindInfo for UnwindInfo { } } -#[cfg(feature = "unwind_guest")] +#[cfg(feature = "mem_profile")] impl UnwindInfo { fn resolved_section_header(&self, name: &[u8]) -> Option<&ResolvedSectionHeader> { self.shdrs @@ -81,7 +81,7 @@ impl UnwindInfo { } } -#[cfg(feature = "unwind_guest")] +#[cfg(feature = "mem_profile")] impl framehop::ModuleSectionInfo> for &UnwindInfo { fn base_svma(&self) -> u64 { self.base_svma @@ -122,7 +122,7 @@ impl ElfInfo { Ok(ElfInfo { payload: bytes.to_vec(), phdrs: elf.program_headers, - #[cfg(feature = "unwind_guest")] + #[cfg(feature = "mem_profile")] shdrs: elf .section_headers .iter() @@ -206,7 +206,7 @@ impl ElfInfo { } } cfg_if::cfg_if! { - if #[cfg(feature = "unwind_guest")] { + if #[cfg(feature = "mem_profile")] { let va_size = self.get_va_size() as u64; let base_svma = self.get_base_va(); Ok(Arc::new(UnwindInfo { diff --git a/src/hyperlight_host/src/mem/exe.rs b/src/hyperlight_host/src/mem/exe.rs index 064d58cde..19b6a9f41 100644 --- a/src/hyperlight_host/src/mem/exe.rs +++ b/src/hyperlight_host/src/mem/exe.rs @@ -16,7 +16,7 @@ limitations under the License. use std::fs::File; use std::io::Read; -#[cfg(feature = "unwind_guest")] +#[cfg(feature = "mem_profile")] use std::sync::Arc; use std::vec::Vec; @@ -39,15 +39,15 @@ pub enum ExeInfo { const DEFAULT_ELF_STACK_RESERVE: u64 = 65536; const DEFAULT_ELF_HEAP_RESERVE: u64 = 131072; -#[cfg(feature = "unwind_guest")] +#[cfg(feature = "mem_profile")] pub(crate) trait UnwindInfo: Send + Sync { fn as_module(&self) -> framehop::Module>; fn hash(&self) -> blake3::Hash; } -#[cfg(feature = "unwind_guest")] +#[cfg(feature = "mem_profile")] pub(crate) struct DummyUnwindInfo {} -#[cfg(feature = "unwind_guest")] +#[cfg(feature = "mem_profile")] impl UnwindInfo for DummyUnwindInfo { fn as_module(&self) -> framehop::Module> { framehop::Module::new("unsupported".to_string(), 0..0, 0, self) @@ -56,7 +56,7 @@ impl UnwindInfo for DummyUnwindInfo { blake3::Hash::from_bytes([0; 32]) } } -#[cfg(feature = "unwind_guest")] +#[cfg(feature = "mem_profile")] impl framehop::ModuleSectionInfo for &DummyUnwindInfo { fn base_svma(&self) -> u64 { 0 @@ -69,9 +69,9 @@ impl framehop::ModuleSectionInfo for &DummyUnwindInfo { } } -#[cfg(feature = "unwind_guest")] +#[cfg(feature = "mem_profile")] pub(crate) type LoadInfo = Arc; -#[cfg(not(feature = "unwind_guest"))] +#[cfg(not(feature = "mem_profile"))] pub(crate) type LoadInfo = (); impl ExeInfo { diff --git a/src/hyperlight_host/src/mem/mgr.rs b/src/hyperlight_host/src/mem/mgr.rs index 787f095e2..7eb1df6c0 100644 --- a/src/hyperlight_host/src/mem/mgr.rs +++ b/src/hyperlight_host/src/mem/mgr.rs @@ -327,7 +327,7 @@ impl SandboxMemoryManager { } // The load method returns a LoadInfo which can also be a different type once the - // `unwind_guest` feature is enabled. + // `mem_profile` feature is enabled. #[allow(clippy::let_unit_value)] let load_info = exe_info.load( load_addr.clone().try_into()?, diff --git a/src/hyperlight_host/src/sandbox/mod.rs b/src/hyperlight_host/src/sandbox/mod.rs index b3f54e738..e2bf30c8d 100644 --- a/src/hyperlight_host/src/sandbox/mod.rs +++ b/src/hyperlight_host/src/sandbox/mod.rs @@ -40,17 +40,14 @@ pub mod snapshot; /// Trait used by the macros to paper over the differences between hyperlight and hyperlight-wasm mod callable; -#[cfg(feature = "unwind_guest")] -use std::io::Write; +/// Module for tracing guest execution #[cfg(feature = "trace_guest")] -use std::sync::{Arc, Mutex}; +pub(crate) mod trace; /// Trait used by the macros to paper over the differences between hyperlight and hyperlight-wasm pub use callable::Callable; /// Re-export for `SandboxConfiguration` type pub use config::SandboxConfiguration; -#[cfg(feature = "unwind_guest")] -use framehop::Unwinder; /// Re-export for the `MultiUseSandbox` type pub use initialized_multi_use::MultiUseSandbox; use tracing::{Span, instrument}; @@ -93,140 +90,6 @@ pub fn is_hypervisor_present() -> bool { hypervisor::get_available_hypervisor().is_some() } -#[cfg(feature = "trace_guest")] -#[derive(Clone)] -/// The information that trace collection requires in order to write -/// an accurate trace. -pub(crate) struct TraceInfo { - /// The epoch against which trace events are timed; at least as - /// early as the creation of the sandbox being traced. - pub epoch: std::time::Instant, - /// The frequency of the timestamp counter. - pub tsc_freq: Option, - /// The epoch at which the guest started, if it has started. - /// This is used to calculate the time spent in the guest relative to the - /// time when the host started. - pub guest_start_epoch: Option, - /// The start guest time, in TSC cycles, for the current guest has a double purpose. - /// This field is used in two ways: - /// 1. It contains the TSC value recorded on the host when the guest started. - /// This is used to calculate the TSC frequency which is the same on the host and guest. - /// The TSC frequency is used to convert TSC values to timestamps in the trace. - /// **NOTE**: This is only used until the TSC frequency is calculated, when the first - /// records are received. - /// 2. To store the TSC value at recorded on the guest when the guest started (first record - /// received) - /// This is used to calculate the records timestamps relative to when guest started. - pub guest_start_tsc: Option, - /// The file to which the trace is being written - #[allow(dead_code)] - pub file: Arc>, - /// The unwind information for the current guest - #[cfg(feature = "unwind_guest")] - #[allow(dead_code)] - pub unwind_module: Arc, - /// The framehop unwinder for the current guest - #[cfg(feature = "unwind_guest")] - pub unwinder: framehop::x86_64::UnwinderX86_64>, - /// The framehop cache - #[cfg(feature = "unwind_guest")] - pub unwind_cache: Arc>, -} -#[cfg(feature = "trace_guest")] -impl TraceInfo { - /// Create a new TraceInfo by saving the current time as the epoch - /// and generating a random filename. - pub fn new( - #[cfg(feature = "unwind_guest")] unwind_module: Arc, - ) -> crate::Result { - let mut path = std::env::current_dir()?; - path.push("trace"); - - // create directory if it does not exist - if !path.exists() { - std::fs::create_dir(&path)?; - } - path.push(uuid::Uuid::new_v4().to_string()); - path.set_extension("trace"); - - log::info!("Creating trace file at: {}", path.display()); - println!("Creating trace file at: {}", path.display()); - - #[cfg(feature = "unwind_guest")] - let hash = unwind_module.hash(); - #[cfg(feature = "unwind_guest")] - let (unwinder, unwind_cache) = { - let mut unwinder = framehop::x86_64::UnwinderX86_64::new(); - unwinder.add_module(unwind_module.clone().as_module()); - let cache = framehop::x86_64::CacheX86_64::new(); - (unwinder, Arc::new(Mutex::new(cache))) - }; - if !hyperlight_guest_tracing::invariant_tsc::has_invariant_tsc() { - // If the platform does not support invariant TSC, warn the user. - // On Azure nested virtualization, the TSC invariant bit is not correctly reported, this is a known issue. - log::warn!( - "Invariant TSC is not supported on this platform, trace timestamps may be inaccurate" - ); - } - - let ret = Self { - epoch: std::time::Instant::now(), - tsc_freq: None, - guest_start_epoch: None, - guest_start_tsc: None, - file: Arc::new(Mutex::new(std::fs::File::create_new(path)?)), - #[cfg(feature = "unwind_guest")] - unwind_module, - #[cfg(feature = "unwind_guest")] - unwinder, - #[cfg(feature = "unwind_guest")] - unwind_cache, - }; - /* write a frame identifying the binary */ - #[cfg(feature = "unwind_guest")] - self::outb::record_trace_frame(&ret, 0, |f| { - let _ = f.write_all(hash.as_bytes()); - })?; - Ok(ret) - } - - /// Calculate the TSC frequency based on the RDTSC instruction on the host. - fn calculate_tsc_freq(&mut self) -> crate::Result<()> { - let (start, start_time) = match ( - self.guest_start_tsc.as_ref(), - self.guest_start_epoch.as_ref(), - ) { - (Some(start), Some(start_time)) => (*start, *start_time), - _ => { - // If the guest start TSC and time are not set, we use the current time and TSC. - // This is not ideal, but it allows us to calculate the TSC frequency without - // failing. - // This is a fallback mechanism to ensure that we can still calculate, however it - // should be noted that this may lead to inaccuracies in the TSC frequency. - // The start time should be already set before running the guest for each sandbox. - log::error!( - "Guest start TSC and time are not set. Calculating TSC frequency will use current time and TSC." - ); - ( - hyperlight_guest_tracing::invariant_tsc::read_tsc(), - std::time::Instant::now(), - ) - } - }; - - let end_time = std::time::Instant::now(); - let end = hyperlight_guest_tracing::invariant_tsc::read_tsc(); - - let elapsed = end_time.duration_since(start_time).as_secs_f64(); - let tsc_freq = ((end - start) as f64 / elapsed) as u64; - - log::info!("Calculated TSC frequency: {} Hz", tsc_freq); - self.tsc_freq = Some(tsc_freq); - - Ok(()) - } -} - pub(crate) trait WrapperGetter { #[allow(dead_code)] fn get_mgr_wrapper(&self) -> &MemMgrWrapper; diff --git a/src/hyperlight_host/src/sandbox/outb.rs b/src/hyperlight_host/src/sandbox/outb.rs index 20a5d8f94..7df6548cf 100644 --- a/src/hyperlight_host/src/sandbox/outb.rs +++ b/src/hyperlight_host/src/sandbox/outb.rs @@ -14,34 +14,22 @@ See the License for the specific language governing permissions and limitations under the License. */ -#[cfg(feature = "trace_guest")] -use std::io::Write; use std::sync::{Arc, Mutex}; -#[cfg(feature = "unwind_guest")] -use fallible_iterator::FallibleIterator; -#[cfg(feature = "unwind_guest")] -use framehop::Unwinder; use hyperlight_common::flatbuffer_wrappers::function_types::ParameterValue; use hyperlight_common::flatbuffer_wrappers::guest_error::ErrorCode; use hyperlight_common::flatbuffer_wrappers::guest_log_data::GuestLogData; use hyperlight_common::outb::{Exception, OutBAction}; -#[cfg(feature = "trace_guest")] -use hyperlight_guest_tracing::TraceRecord; use log::{Level, Record}; use tracing::{Span, instrument}; use tracing_log::format_trace; use super::host_funcs::FunctionRegistry; use super::mem_mgr::MemMgrWrapper; -#[cfg(feature = "trace_guest")] +#[cfg(feature = "mem_profile")] use crate::hypervisor::Hypervisor; -#[cfg(feature = "trace_guest")] -use crate::mem::layout::SandboxMemoryLayout; use crate::mem::mgr::SandboxMemoryManager; use crate::mem::shared_mem::HostSharedMemory; -#[cfg(feature = "trace_guest")] -use crate::sandbox::TraceInfo; use crate::{HyperlightError, Result, new_error}; #[instrument(err(Debug), skip_all, parent = Span::current(), level="Trace")] @@ -156,122 +144,12 @@ fn outb_abort(mem_mgr: &mut MemMgrWrapper, data: u32) -> Resul Ok(()) } -#[cfg(feature = "unwind_guest")] -fn unwind( - hv: &dyn Hypervisor, - mem: &SandboxMemoryManager, - trace_info: &TraceInfo, -) -> Result> { - let mut read_stack = |addr| { - mem.shared_mem - .read::((addr - SandboxMemoryLayout::BASE_ADDRESS as u64) as usize) - .map_err(|_| ()) - }; - let mut cache = trace_info - .unwind_cache - .try_lock() - .map_err(|e| new_error!("could not lock unwinder cache {}\n", e))?; - let iter = trace_info.unwinder.iter_frames( - hv.read_trace_reg(crate::hypervisor::TraceRegister::RIP)?, - framehop::x86_64::UnwindRegsX86_64::new( - hv.read_trace_reg(crate::hypervisor::TraceRegister::RIP)?, - hv.read_trace_reg(crate::hypervisor::TraceRegister::RSP)?, - hv.read_trace_reg(crate::hypervisor::TraceRegister::RBP)?, - ), - &mut *cache, - &mut read_stack, - ); - iter.map(|f| Ok(f.address() - mem.layout.get_guest_code_address() as u64)) - .collect() - .map_err(|e| new_error!("couldn't unwind: {}", e)) -} - -#[cfg(feature = "unwind_guest")] -fn write_stack(out: &mut std::fs::File, stack: &[u64]) { - let _ = out.write_all(&stack.len().to_ne_bytes()); - for frame in stack { - let _ = out.write_all(&frame.to_ne_bytes()); - } -} - -#[cfg(feature = "unwind_guest")] -pub(super) fn record_trace_frame( - trace_info: &TraceInfo, - frame_id: u64, - write_frame: F, -) -> Result<()> { - let Ok(mut out) = trace_info.file.lock() else { - return Ok(()); - }; - // frame structure: - // 16 bytes timestamp - let now = std::time::Instant::now().saturating_duration_since(trace_info.epoch); - let _ = out.write_all(&now.as_micros().to_ne_bytes()); - // 8 bytes frame type id - let _ = out.write_all(&frame_id.to_ne_bytes()); - // frame data - write_frame(&mut out); - Ok(()) -} - -#[cfg(feature = "trace_guest")] -pub(super) fn record_guest_trace_frame( - trace_info: &TraceInfo, - frame_id: u64, - cycles: u64, - write_frame: F, -) -> Result<()> { - let Ok(mut out) = trace_info.file.lock() else { - return Ok(()); - }; - // frame structure: - // 16 bytes timestamp - - // The number of cycles spent in the guest relative to the first received trace record - let cycles_spent = cycles - - trace_info - .guest_start_tsc - .as_ref() - .map_or_else(|| 0, |c| *c); - - // Convert cycles to microseconds based on the TSC frequency - let tsc_freq = trace_info - .tsc_freq - .as_ref() - .ok_or_else(|| new_error!("TSC frequency not set in TraceInfo"))?; - let micros = cycles_spent as f64 / *tsc_freq as f64 * 1_000_000f64; - - // Convert to a Duration - let guest_duration = std::time::Duration::from_micros(micros as u64); - - // Calculate the time when the guest started execution relative to the host epoch - // Note: This is relative to the time saved when the `TraceInfo` was created (before the - // Hypervisor is created). - let guest_start_time = trace_info - .guest_start_epoch - .as_ref() - .unwrap_or(&trace_info.epoch) - .saturating_duration_since(trace_info.epoch); - - // Calculate the timestamp when the actual frame was recorded relative to the host epoch - let timestamp = guest_start_time - .checked_add(guest_duration) - .unwrap_or(guest_duration); - - let _ = out.write_all(×tamp.as_micros().to_ne_bytes()); - // 8 bytes frame type id - let _ = out.write_all(&frame_id.to_ne_bytes()); - // frame data - write_frame(&mut out); - Ok(()) -} - /// Handles OutB operations from the guest. #[instrument(err(Debug), skip_all, parent = Span::current(), level= "Trace")] pub(crate) fn handle_outb( mem_mgr: &mut MemMgrWrapper, host_funcs: Arc>, - #[cfg(feature = "trace_guest")] _hv: &mut dyn Hypervisor, + #[cfg(feature = "mem_profile")] _hv: &mut dyn Hypervisor, port: u16, data: u32, ) -> Result<()> { @@ -303,103 +181,19 @@ pub(crate) fn handle_outb( eprint!("{}", ch); Ok(()) } - #[cfg(feature = "unwind_guest")] - OutBAction::TraceRecordStack => { - let Ok(stack) = unwind(_hv, mem_mgr.as_ref(), _hv.trace_info_as_ref()) else { - return Ok(()); - }; - record_trace_frame(_hv.trace_info_as_ref(), 1u64, |f| { - write_stack(f, &stack); - }) - } + #[cfg(feature = "trace_guest")] + OutBAction::TraceBatch => Ok(()), #[cfg(feature = "mem_profile")] OutBAction::TraceMemoryAlloc => { - let Ok(stack) = unwind(_hv, mem_mgr.as_ref(), _hv.trace_info_as_ref()) else { - return Ok(()); - }; - let Ok(amt) = _hv.read_trace_reg(crate::hypervisor::TraceRegister::RAX) else { - return Ok(()); - }; - let Ok(ptr) = _hv.read_trace_reg(crate::hypervisor::TraceRegister::RCX) else { - return Ok(()); - }; - record_trace_frame(_hv.trace_info_as_ref(), 2u64, |f| { - let _ = f.write_all(&ptr.to_ne_bytes()); - let _ = f.write_all(&amt.to_ne_bytes()); - write_stack(f, &stack); - }) + let regs = _hv.read_regs()?; + let trace_info = _hv.trace_info_mut(); + trace_info.handle_trace_mem_alloc(®s, mem_mgr.as_ref()) } #[cfg(feature = "mem_profile")] OutBAction::TraceMemoryFree => { - let Ok(stack) = unwind(_hv, mem_mgr.as_ref(), _hv.trace_info_as_ref()) else { - return Ok(()); - }; - let Ok(ptr) = _hv.read_trace_reg(crate::hypervisor::TraceRegister::RCX) else { - return Ok(()); - }; - record_trace_frame(_hv.trace_info_as_ref(), 3u64, |f| { - let _ = f.write_all(&ptr.to_ne_bytes()); - write_stack(f, &stack); - }) - } - #[cfg(feature = "trace_guest")] - OutBAction::TraceRecord => { - let Ok(len) = _hv.read_trace_reg(crate::hypervisor::TraceRegister::RAX) else { - return Ok(()); - }; - let Ok(ptr) = _hv.read_trace_reg(crate::hypervisor::TraceRegister::RCX) else { - return Ok(()); - }; - let mut buffer = vec![0u8; len as usize * std::mem::size_of::()]; - let buffer = &mut buffer[..]; - - // Read the trace records from the guest memory - mem_mgr - .as_ref() - .shared_mem - .copy_to_slice(buffer, ptr as usize - SandboxMemoryLayout::BASE_ADDRESS) - .map_err(|e| { - new_error!( - "Failed to copy trace records from guest memory to host: {:?}", - e - ) - })?; - - let traces = unsafe { - std::slice::from_raw_parts(buffer.as_ptr() as *const TraceRecord, len as usize) - }; - - { - let trace_info = _hv.trace_info_as_mut(); - - // Calculate the TSC frequency based on the current TSC reading - // This is done only once, when the first trace record is received - // Ideally, we should use a timer or a clock to measure the time elapsed, - // but that adds delays. - // To avoid that we store the TSC value and a timestamp right - // before starting the guest execution and then calculate the TSC frequency when - // the first trace record is received, based on the current TSC value and clock. - if trace_info.tsc_freq.is_none() { - trace_info.calculate_tsc_freq()?; - - // After the TSC frequency is calculated, we no longer need the value of TSC - // recorded on the host when the guest started, so we can set the guest_start_tsc field - // to store the TSC value recorded on the guest when the guest started executing. - // This is used to calculate the records timestamps relative to the first trace record. - if !traces.is_empty() { - trace_info.guest_start_tsc = Some(traces[0].cycles); - } - } - } - - for record in traces { - record_guest_trace_frame(_hv.trace_info_as_ref(), 4u64, record.cycles, |f| { - let _ = f.write_all(&record.msg_len.to_ne_bytes()); - let _ = f.write_all(&record.msg[..record.msg_len]); - })? - } - - Ok(()) + let regs = _hv.read_regs()?; + let trace_info = _hv.trace_info_mut(); + trace_info.handle_trace_mem_free(®s, mem_mgr.as_ref()) } } } diff --git a/src/hyperlight_host/src/sandbox/trace/context.rs b/src/hyperlight_host/src/sandbox/trace/context.rs new file mode 100644 index 000000000..1603e33fb --- /dev/null +++ b/src/hyperlight_host/src/sandbox/trace/context.rs @@ -0,0 +1,353 @@ +/* +Copyright 2025 The Hyperlight Authors. + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +use std::collections::HashMap; +use std::time::{Duration, Instant, SystemTime}; + +use hyperlight_common::outb::OutBAction; +use hyperlight_guest_tracing::{Events, Spans}; +use opentelemetry::global::BoxedSpan; +use opentelemetry::trace::{Span as _, TraceContextExt, Tracer as _}; +use opentelemetry::{Context, KeyValue, global}; +use tracing::span::{EnteredSpan, Span}; +use tracing_opentelemetry::OpenTelemetrySpanExt; + +use crate::hypervisor::arch::X86_64Regs; +use crate::mem::layout::SandboxMemoryLayout; +use crate::mem::shared_mem::HostSharedMemory; +use crate::sandbox::mem_mgr::MemMgrWrapper; +use crate::{HyperlightError, Result, new_error}; + +/// Type that helps get the data from the guest provided the registers and memory access +struct TraceBatch { + pub guest_start_tsc: u64, + pub spans: Spans, + pub events: Events, +} + +impl TryFrom<(&X86_64Regs, &MemMgrWrapper)> for TraceBatch { + type Error = HyperlightError; + fn try_from((regs, mem_mgr): (&X86_64Regs, &MemMgrWrapper)) -> Result { + let magic_no = regs.r8; + let guest_start_tsc = regs.r9; + let spans_ptr = regs.r10 as usize; + let events_ptr = regs.r11 as usize; + + if magic_no != OutBAction::TraceBatch as u64 { + return Err(new_error!("A TraceBatch is not present")); + } + + // Transmute spans_ptr to Spans type + let mut spans = vec![0u8; std::mem::size_of::()]; + mem_mgr + .as_ref() + .shared_mem + .copy_to_slice(&mut spans, spans_ptr - SandboxMemoryLayout::BASE_ADDRESS) + .map_err(|e| { + new_error!( + "Failed to copy guest trace batch from guest memory to host: {:?}", + e + ) + })?; + + let spans: Spans = unsafe { + let raw = spans.as_slice() as *const _ as *const Spans; + raw.read_unaligned() + }; + + // Transmute events_ptr to Events type + let mut events = vec![0u8; std::mem::size_of::()]; + mem_mgr + .as_ref() + .shared_mem + .copy_to_slice(&mut events, events_ptr - SandboxMemoryLayout::BASE_ADDRESS) + .map_err(|e| { + new_error!( + "Failed to copy guest trace batch from guest memory to host: {:?}", + e + ) + })?; + + let events: Events = unsafe { + let raw = events.as_slice() as *const _ as *const Events; + raw.read_unaligned() + }; + + Ok(TraceBatch { + guest_start_tsc, + spans, + events, + }) + } +} + +/// This structure handles the guest tracing information. +pub struct TraceContext { + host_spans: Vec, + guest_spans: HashMap, + in_host_call: bool, + + // Lazily initialized members + start_wall: Option, + /// The epoch at which the call into the guest started, if it has started. + /// This is used to calculate the time spent in the guest relative to the + /// time when the call into the guest was first made. + start_instant: Option, + /// The start guest time, in TSC cycles, for the current guest measured on the host. + /// It contains the TSC value recorded on the host before a call is made into the guest. + /// This is used to calculate the TSC frequency which is the same on the host and guest. + /// The TSC frequency is used to convert TSC values to timestamps in the trace. + /// **NOTE**: This is only used until the TSC frequency is calculated, when the first + /// records are received. + start_tsc: Option, + /// The frequency of the timestamp counter. + tsc_freq: Option, + current_parent_ctx: Option, +} + +impl TraceContext { + /// Initialize with current context + pub fn new() -> Self { + if !hyperlight_guest_tracing::invariant_tsc::has_invariant_tsc() { + // If the platform does not support invariant TSC, warn the user. + // On Azure nested virtualization, the TSC invariant bit is not correctly reported, this is a known issue. + log::warn!( + "Invariant TSC is not supported on this platform, trace timestamps may be inaccurate" + ); + } + + let current_ctx = Span::current().context(); + + let span = tracing::trace_span!("call-to-guest"); + span.set_parent(current_ctx); + let entered = span.entered(); + + Self { + host_spans: vec![entered], + guest_spans: HashMap::new(), + in_host_call: false, + + start_wall: None, + start_instant: None, + start_tsc: None, + tsc_freq: None, + current_parent_ctx: None, + } + } + + /// Calculate the frequency of the TimeStamp Counter. + /// This is done by: + /// - first reading a timestamp and an `Instant` + /// - secondly reading another timestamp and `Instant` + /// - calculate the frequency based on the `Duration` between + /// the two `Instant`s read. + fn calculate_tsc_freq(&mut self) -> Result<()> { + let (start, start_time) = match (self.start_tsc.as_ref(), self.start_instant.as_ref()) { + (Some(start), Some(start_time)) => (*start, *start_time), + _ => { + // If the guest start TSC and time are not set, we use the current time and TSC. + // This is not ideal, but it allows us to calculate the TSC frequency without + // failing. + // This is a fallback mechanism to ensure that we can still calculate, however it + // should be noted that this may lead to inaccuracies in the TSC frequency. + // The start time should be already set before running the guest for each sandbox. + log::error!( + "Guest start TSC and time are not set. Calculating TSC frequency will use current time and TSC." + ); + ( + hyperlight_guest_tracing::invariant_tsc::read_tsc(), + std::time::Instant::now(), + ) + } + }; + + let end_time = std::time::Instant::now(); + let end = hyperlight_guest_tracing::invariant_tsc::read_tsc(); + + let elapsed = end_time.duration_since(start_time).as_secs_f64(); + let tsc_freq = ((end - start) as f64 / elapsed) as u64; + + log::info!("Calculated TSC frequency: {} Hz", tsc_freq); + self.tsc_freq = Some(tsc_freq); + + Ok(()) + } + + /// Calculate timestamp relative to wall time stored on host + fn calculate_guest_time_relative_to_host( + &self, + guest_start_tsc: u64, + tsc: u64, + ) -> Result { + // Should never fail as it is extracted after it is set + let tsc_freq = self.tsc_freq.ok_or(new_error!("TSC frequency not set"))?; + + // Number of cycles relative to guest start + let rel_cycles = tsc.saturating_sub(guest_start_tsc); + + // Number of micro seconds from guest start to `tsc` argument + let rel_start_us = rel_cycles as f64 / tsc_freq as f64 * 1_000_000f64; + + // Final timestamp is calculated by: + // - starting from the wall time when the sandbox was created + // - adding the Duration to the guest start + // - adding the Duration from the guest start to the provided `tsc` + Ok(self.start_wall.ok_or(new_error!("start_wall not set"))? + + Duration::from_micros(rel_start_us as u64)) + } + + pub fn handle_trace( + &mut self, + regs: &X86_64Regs, + mem_mgr: &MemMgrWrapper, + ) -> Result<()> { + if self.tsc_freq.is_none() { + self.calculate_tsc_freq()?; + } + + // Get the guest sent info + let trace_batch = TraceBatch::try_from((regs, mem_mgr))?; + + let tracer = global::tracer("guest-tracer"); + let mut spans_to_remove = vec![]; + + let mut current_active_span = None; + + // Update the spans map + for s in trace_batch.spans.iter() { + let start_ts = self + .calculate_guest_time_relative_to_host(trace_batch.guest_start_tsc, s.start_tsc)?; + let end_ts = s.end_tsc.map(|tsc| { + self.calculate_guest_time_relative_to_host(trace_batch.guest_start_tsc, tsc) + }); + let parent_id = s.parent_id; + let parent_ctx = if let Some(parent_id) = parent_id { + if let Some(span) = self.guest_spans.get(&parent_id) { + Context::new().with_remote_span_context(span.span_context().clone()) + } else if let Some(parent_ctx) = self.current_parent_ctx.as_ref() { + parent_ctx.clone() + } else { + Span::current().context().clone() + } + } else if let Some(parent_ctx) = self.current_parent_ctx.as_ref() { + parent_ctx.clone() + } else { + Span::current().context().clone() + }; + + // Get the saved span, modify it and set it back to avoid borrow checker + let mut span = self.guest_spans.remove(&s.id).unwrap_or_else(|| { + let mut sb = tracer + .span_builder(s.name.to_string()) + .with_start_time(start_ts); + sb.attributes = Some(vec![KeyValue::new("target", s.target.to_string())]); + let mut span = sb.start_with_context(&tracer, &parent_ctx); + + for (k, v) in s.fields.iter() { + span.set_attribute(KeyValue::new( + k.as_str().to_string(), + v.as_str().to_string(), + )); + } + + span + }); + + // If we find an end timestamp it means the span has been closed + // otherwise store it for later + if let Some(ts) = end_ts { + span.end_with_timestamp(ts?); + spans_to_remove.push(s.id); + } else { + current_active_span = + Some(Context::current().with_remote_span_context(span.span_context().clone())); + } + + self.guest_spans.insert(s.id, span); + } + + // Create the events + for ev in trace_batch.events.iter() { + let ts = + self.calculate_guest_time_relative_to_host(trace_batch.guest_start_tsc, ev.tsc)?; + let mut attributes: Vec = ev + .fields + .iter() + .map(|(k, v)| KeyValue::new(k.to_string(), v.to_string())) + .collect(); + + attributes.push(KeyValue::new( + "level", + tracing::Level::from(ev.level).to_string(), + )); + + // Add the event to the parent span + // It should always have a parent span + if let Some(span) = self.guest_spans.get_mut(&ev.parent_id) { + span.add_event_with_timestamp(ev.name.to_string(), ts, attributes); + } + } + + // Remove the spans that have been closed + for id in spans_to_remove.into_iter() { + self.guest_spans.remove(&id); + } + + if let Some(ctx) = current_active_span { + self.new_host_trace(ctx); + }; + + Ok(()) + } + + pub(crate) fn setup_guest_trace(&mut self, ctx: Context) { + if self.start_instant.is_none() { + crate::debug!("Guest Start Epoch set"); + self.start_wall = Some(SystemTime::now()); + self.start_tsc = Some(hyperlight_guest_tracing::invariant_tsc::read_tsc()); + self.start_instant = Some(std::time::Instant::now()); + } + self.current_parent_ctx = Some(ctx); + } + + pub fn new_host_trace(&mut self, ctx: Context) { + let span = tracing::trace_span!("call-to-host"); + span.set_parent(ctx); + let entered = span.entered(); + self.host_spans.push(entered); + self.in_host_call = true; + } + + pub fn end_host_trace(&mut self) { + if self.in_host_call { + if let Some(entered) = self.host_spans.pop() { + entered.exit(); + } + } + } +} + +impl Drop for TraceContext { + fn drop(&mut self) { + for (k, mut v) in self.guest_spans.drain() { + v.end(); + log::debug!("Dropped guest span with id {}", k); + } + while let Some(entered) = self.host_spans.pop() { + entered.exit(); + } + } +} diff --git a/src/hyperlight_host/src/sandbox/trace/mem_profile.rs b/src/hyperlight_host/src/sandbox/trace/mem_profile.rs new file mode 100644 index 000000000..ed2668839 --- /dev/null +++ b/src/hyperlight_host/src/sandbox/trace/mem_profile.rs @@ -0,0 +1,182 @@ +/* +Copyright 2025 The Hyperlight Authors. + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ +use std::io::Write; +use std::sync::{Arc, Mutex}; + +use fallible_iterator::FallibleIterator; +use framehop::Unwinder; + +use crate::hypervisor::arch::X86_64Regs; +use crate::mem::layout::SandboxMemoryLayout; +use crate::mem::mgr::SandboxMemoryManager; +use crate::mem::shared_mem::HostSharedMemory; +use crate::{Result, new_error}; + +/// The type of trace frame being recorded. +/// This is used to identify the type of frame being recorded in the trace file. +enum TraceFrameType { + /// A frame that records a memory allocation. + MemAlloc = 2, + /// A frame that records a memory free. + MemFree = 3, +} + +/// This structure handles the memory profiling trace information. +pub(crate) struct MemTraceInfo { + /// The epoch against which trace events are timed; at least as + /// early as the creation of the sandbox being traced. + epoch: std::time::Instant, + /// The file to which the trace is being written + pub file: Arc>, + /// The unwind information for the current guest + #[allow(dead_code)] + pub unwind_module: Arc, + /// The framehop unwinder for the current guest + pub unwinder: framehop::x86_64::UnwinderX86_64>, + /// The framehop cache + pub unwind_cache: Arc>, +} + +impl MemTraceInfo { + pub fn new(unwind_module: Arc) -> Result { + let mut path = std::env::current_dir()?; + path.push("trace"); + + // create directory if it does not exist + if !path.exists() { + std::fs::create_dir(&path)?; + } + path.push(uuid::Uuid::new_v4().to_string()); + path.set_extension("trace"); + + log::info!("Creating trace file at: {}", path.display()); + println!("Creating trace file at: {}", path.display()); + + let hash = unwind_module.hash(); + let (unwinder, unwind_cache) = { + let mut unwinder = framehop::x86_64::UnwinderX86_64::new(); + unwinder.add_module(unwind_module.clone().as_module()); + let cache = framehop::x86_64::CacheX86_64::new(); + (unwinder, Arc::new(Mutex::new(cache))) + }; + + let ret = Self { + epoch: std::time::Instant::now(), + file: Arc::new(Mutex::new(std::fs::File::create_new(path)?)), + unwind_module, + unwinder, + unwind_cache, + }; + + /* write a frame identifying the binary */ + ret.record_trace_frame(ret.epoch, 0, |f| { + let _ = f.write_all(hash.as_bytes()); + })?; + + Ok(ret) + } + + fn unwind( + &self, + regs: &X86_64Regs, + mem_mgr: &SandboxMemoryManager, + ) -> Result> { + let mut read_stack = |addr| { + mem_mgr + .shared_mem + .read::((addr - SandboxMemoryLayout::BASE_ADDRESS as u64) as usize) + .map_err(|_| ()) + }; + let mut cache = self + .unwind_cache + .try_lock() + .map_err(|e| new_error!("could not lock unwinder cache {}\n", e))?; + let iter = self.unwinder.iter_frames( + regs.rip, + framehop::x86_64::UnwindRegsX86_64::new(regs.rip, regs.rsp, regs.rbp), + &mut *cache, + &mut read_stack, + ); + iter.map(|f| Ok(f.address() - mem_mgr.layout.get_guest_code_address() as u64)) + .collect() + .map_err(|e| new_error!("couldn't unwind: {}", e)) + } + + fn write_stack(&self, out: &mut std::fs::File, stack: &[u64]) { + let _ = out.write_all(&stack.len().to_ne_bytes()); + for frame in stack { + let _ = out.write_all(&frame.to_ne_bytes()); + } + } + + fn record_trace_frame( + &self, + start_instant: std::time::Instant, + frame_id: u64, + write_frame: F, + ) -> Result<()> { + let Ok(mut out) = self.file.lock() else { + return Ok(()); + }; + // frame structure: + // 16 bytes timestamp + let now = std::time::Instant::now().saturating_duration_since(start_instant); + let _ = out.write_all(&now.as_micros().to_ne_bytes()); + // 8 bytes frame type id + let _ = out.write_all(&frame_id.to_ne_bytes()); + // frame data + write_frame(&mut out); + Ok(()) + } + + fn handle_trace( + &self, + regs: &X86_64Regs, + mem_mgr: &SandboxMemoryManager, + trace_identifier: TraceFrameType, + ) -> Result<()> { + let Ok(stack) = self.unwind(regs, mem_mgr) else { + return Ok(()); + }; + + let amt = regs.rax; + let ptr = regs.rcx; + + self.record_trace_frame(self.epoch, trace_identifier as u64, |f| { + let _ = f.write_all(&ptr.to_ne_bytes()); + let _ = f.write_all(&amt.to_ne_bytes()); + self.write_stack(f, &stack); + }) + } + + #[inline(always)] + pub(crate) fn handle_trace_mem_alloc( + &self, + regs: &X86_64Regs, + mem_mgr: &SandboxMemoryManager, + ) -> Result<()> { + self.handle_trace(regs, mem_mgr, TraceFrameType::MemAlloc) + } + + #[inline(always)] + pub(crate) fn handle_trace_mem_free( + &self, + regs: &X86_64Regs, + mem_mgr: &SandboxMemoryManager, + ) -> Result<()> { + self.handle_trace(regs, mem_mgr, TraceFrameType::MemFree) + } +} diff --git a/src/hyperlight_host/src/sandbox/trace/mod.rs b/src/hyperlight_host/src/sandbox/trace/mod.rs new file mode 100644 index 000000000..f955a6d76 --- /dev/null +++ b/src/hyperlight_host/src/sandbox/trace/mod.rs @@ -0,0 +1,25 @@ +/* +Copyright 2025 The Hyperlight Authors. + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +/// Tracing context support for sandboxes. +mod context; +pub(crate) use context::TraceContext; + +/// Tracing and profiling support for sandboxes. +#[cfg(feature = "mem_profile")] +mod mem_profile; +#[cfg(feature = "mem_profile")] +pub(crate) use mem_profile::MemTraceInfo; diff --git a/src/hyperlight_host/src/sandbox/uninitialized_evolve.rs b/src/hyperlight_host/src/sandbox/uninitialized_evolve.rs index e3334fb3e..a5ea4ed78 100644 --- a/src/hyperlight_host/src/sandbox/uninitialized_evolve.rs +++ b/src/hyperlight_host/src/sandbox/uninitialized_evolve.rs @@ -33,11 +33,11 @@ use crate::mem::ptr_offset::Offset; use crate::mem::shared_mem::GuestSharedMemory; #[cfg(any(feature = "init-paging", target_os = "windows"))] use crate::mem::shared_mem::SharedMemory; -#[cfg(feature = "trace_guest")] -use crate::sandbox::TraceInfo; #[cfg(gdb)] use crate::sandbox::config::DebugInfo; use crate::sandbox::host_funcs::FunctionRegistry; +#[cfg(feature = "mem_profile")] +use crate::sandbox::trace::MemTraceInfo; use crate::sandbox::{HostSharedMemory, MemMgrWrapper}; #[cfg(target_os = "linux")] use crate::signal_handlers::setup_signal_handlers; @@ -196,11 +196,8 @@ pub(crate) fn set_up_hypervisor_partition( None }; - #[cfg(feature = "trace_guest")] - let trace_info = TraceInfo::new( - #[cfg(feature = "unwind_guest")] - _load_info, - )?; + #[cfg(feature = "mem_profile")] + let trace_info = MemTraceInfo::new(_load_info)?; match *get_available_hypervisor() { #[cfg(mshv)] @@ -215,7 +212,7 @@ pub(crate) fn set_up_hypervisor_partition( gdb_conn, #[cfg(crashdump)] rt_cfg.clone(), - #[cfg(feature = "trace_guest")] + #[cfg(feature = "mem_profile")] trace_info, )?; Ok(Box::new(hv)) @@ -233,7 +230,7 @@ pub(crate) fn set_up_hypervisor_partition( gdb_conn, #[cfg(crashdump)] rt_cfg.clone(), - #[cfg(feature = "trace_guest")] + #[cfg(feature = "mem_profile")] trace_info, )?; Ok(Box::new(hv)) @@ -257,7 +254,7 @@ pub(crate) fn set_up_hypervisor_partition( gdb_conn, #[cfg(crashdump)] rt_cfg.clone(), - #[cfg(feature = "trace_guest")] + #[cfg(feature = "mem_profile")] trace_info, )?; Ok(Box::new(hv)) diff --git a/src/tests/rust_guests/dummyguest/Cargo.lock b/src/tests/rust_guests/dummyguest/Cargo.lock index fa3de189b..9db9d6db4 100644 --- a/src/tests/rust_guests/dummyguest/Cargo.lock +++ b/src/tests/rust_guests/dummyguest/Cargo.lock @@ -29,6 +29,12 @@ dependencies = [ "spin 0.9.8", ] +[[package]] +name = "byteorder" +version = "1.5.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "1fd0f2584146f6f2ef48085050886acf353beff7305ebd1ae69500e27c67f64b" + [[package]] name = "cc" version = "1.2.34" @@ -68,6 +74,26 @@ version = "0.3.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "0cc23270f6e1808e30a928bdc84dea0b9b4136a8bc82338574f23baf47bbd280" +[[package]] +name = "hash32" +version = "0.3.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "47d60b12902ba28e2730cd37e95b8c9223af2808df9e902d4df49588d1470606" +dependencies = [ + "byteorder", +] + +[[package]] +name = "heapless" +version = "0.8.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "0bfb9eb618601c89945a70e254898da93b13be0388091d42117462b265bb3fad" +dependencies = [ + "hash32", + "serde", + "stable_deref_trait", +] + [[package]] name = "hyperlight-common" version = "0.9.0" @@ -87,6 +113,7 @@ dependencies = [ "hyperlight-common", "hyperlight-guest-tracing", "serde_json", + "tracing", ] [[package]] @@ -102,24 +129,18 @@ dependencies = [ "hyperlight-guest-tracing", "log", "spin 0.10.0", + "tracing", ] [[package]] name = "hyperlight-guest-tracing" version = "0.9.0" dependencies = [ + "heapless", "hyperlight-common", - "hyperlight-guest-tracing-macro", "spin 0.10.0", -] - -[[package]] -name = "hyperlight-guest-tracing-macro" -version = "0.9.0" -dependencies = [ - "proc-macro2", - "quote", - "syn", + "tracing", + "tracing-core", ] [[package]] @@ -150,6 +171,12 @@ version = "2.7.5" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "32a282da65faaf38286cf3be983213fcf1d2e2a58700e808f83f4ea9a4804bc0" +[[package]] +name = "pin-project-lite" +version = "0.2.16" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3b3cff922bd51709b605d9ead9aa71031d81447142d828eb4a6eba76fe619f9b" + [[package]] name = "proc-macro2" version = "1.0.101" @@ -251,6 +278,12 @@ dependencies = [ "lock_api", ] +[[package]] +name = "stable_deref_trait" +version = "1.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a8f112729512f8e442d81f95a8a7ddf2b7c6b8a1a6f509a95864142b30cab2d3" + [[package]] name = "syn" version = "2.0.106" @@ -262,6 +295,34 @@ dependencies = [ "unicode-ident", ] +[[package]] +name = "tracing" +version = "0.1.41" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "784e0ac535deb450455cbfa28a6f0df145ea1bb7ae51b821cf5e7927fdcfbdd0" +dependencies = [ + "pin-project-lite", + "tracing-attributes", + "tracing-core", +] + +[[package]] +name = "tracing-attributes" +version = "0.1.30" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "81383ab64e72a7a8b8e13130c49e3dab29def6d0c7d76a03087b3cf71c5c6903" +dependencies = [ + "proc-macro2", + "quote", + "syn", +] + +[[package]] +name = "tracing-core" +version = "0.1.34" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b9d12581f227e93f094d3af2ae690a574abb8a2b9b7a96e7cfe9647b2b617678" + [[package]] name = "unicode-ident" version = "1.0.18" diff --git a/src/tests/rust_guests/dummyguest/Cargo.toml b/src/tests/rust_guests/dummyguest/Cargo.toml index 9a35944ec..fb1a63cb2 100644 --- a/src/tests/rust_guests/dummyguest/Cargo.toml +++ b/src/tests/rust_guests/dummyguest/Cargo.toml @@ -11,5 +11,4 @@ hyperlight-common = { path = "../../../hyperlight_common", default-features = fa [features] default = [] trace_guest = ["hyperlight-guest-bin/trace_guest"] -unwind_guest = ["hyperlight-common/unwind_guest"] mem_profile = ["hyperlight-common/mem_profile", "hyperlight-guest-bin/mem_profile"] diff --git a/src/tests/rust_guests/simpleguest/Cargo.lock b/src/tests/rust_guests/simpleguest/Cargo.lock index 9081da46b..e692ac0f5 100644 --- a/src/tests/rust_guests/simpleguest/Cargo.lock +++ b/src/tests/rust_guests/simpleguest/Cargo.lock @@ -29,6 +29,12 @@ dependencies = [ "spin 0.9.8", ] +[[package]] +name = "byteorder" +version = "1.5.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "1fd0f2584146f6f2ef48085050886acf353beff7305ebd1ae69500e27c67f64b" + [[package]] name = "cc" version = "1.2.34" @@ -60,6 +66,26 @@ version = "0.3.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "0cc23270f6e1808e30a928bdc84dea0b9b4136a8bc82338574f23baf47bbd280" +[[package]] +name = "hash32" +version = "0.3.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "47d60b12902ba28e2730cd37e95b8c9223af2808df9e902d4df49588d1470606" +dependencies = [ + "byteorder", +] + +[[package]] +name = "heapless" +version = "0.8.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "0bfb9eb618601c89945a70e254898da93b13be0388091d42117462b265bb3fad" +dependencies = [ + "hash32", + "serde", + "stable_deref_trait", +] + [[package]] name = "hyperlight-common" version = "0.9.0" @@ -79,6 +105,7 @@ dependencies = [ "hyperlight-common", "hyperlight-guest-tracing", "serde_json", + "tracing", ] [[package]] @@ -94,24 +121,18 @@ dependencies = [ "hyperlight-guest-tracing", "log", "spin 0.10.0", + "tracing", ] [[package]] name = "hyperlight-guest-tracing" version = "0.9.0" dependencies = [ + "heapless", "hyperlight-common", - "hyperlight-guest-tracing-macro", "spin 0.10.0", -] - -[[package]] -name = "hyperlight-guest-tracing-macro" -version = "0.9.0" -dependencies = [ - "proc-macro2", - "quote", - "syn", + "tracing", + "tracing-core", ] [[package]] @@ -142,6 +163,12 @@ version = "2.7.5" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "32a282da65faaf38286cf3be983213fcf1d2e2a58700e808f83f4ea9a4804bc0" +[[package]] +name = "pin-project-lite" +version = "0.2.16" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3b3cff922bd51709b605d9ead9aa71031d81447142d828eb4a6eba76fe619f9b" + [[package]] name = "proc-macro2" version = "1.0.101" @@ -234,6 +261,7 @@ dependencies = [ "hyperlight-guest-bin", "hyperlight-guest-tracing", "log", + "tracing", ] [[package]] @@ -254,6 +282,12 @@ dependencies = [ "lock_api", ] +[[package]] +name = "stable_deref_trait" +version = "1.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a8f112729512f8e442d81f95a8a7ddf2b7c6b8a1a6f509a95864142b30cab2d3" + [[package]] name = "syn" version = "2.0.106" @@ -265,6 +299,34 @@ dependencies = [ "unicode-ident", ] +[[package]] +name = "tracing" +version = "0.1.41" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "784e0ac535deb450455cbfa28a6f0df145ea1bb7ae51b821cf5e7927fdcfbdd0" +dependencies = [ + "pin-project-lite", + "tracing-attributes", + "tracing-core", +] + +[[package]] +name = "tracing-attributes" +version = "0.1.30" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "81383ab64e72a7a8b8e13130c49e3dab29def6d0c7d76a03087b3cf71c5c6903" +dependencies = [ + "proc-macro2", + "quote", + "syn", +] + +[[package]] +name = "tracing-core" +version = "0.1.34" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b9d12581f227e93f094d3af2ae690a574abb8a2b9b7a96e7cfe9647b2b617678" + [[package]] name = "unicode-ident" version = "1.0.18" diff --git a/src/tests/rust_guests/simpleguest/Cargo.toml b/src/tests/rust_guests/simpleguest/Cargo.toml index 34925b9fc..868711dcd 100644 --- a/src/tests/rust_guests/simpleguest/Cargo.toml +++ b/src/tests/rust_guests/simpleguest/Cargo.toml @@ -9,10 +9,10 @@ hyperlight-guest-bin = { path = "../../../hyperlight_guest_bin" } hyperlight-common = { path = "../../../hyperlight_common", default-features = false } hyperlight-guest-tracing = { path = "../../../hyperlight_guest_tracing" } log = {version = "0.4", default-features = false } +tracing = { version = "0.1.41", default-features = false, features = ["attributes"] } [features] default = [] trace_guest = ["hyperlight-guest-bin/trace_guest", "hyperlight-guest/trace_guest", "hyperlight-guest-tracing/trace"] -unwind_guest = ["hyperlight-common/unwind_guest"] mem_profile = ["hyperlight-common/mem_profile", "hyperlight-guest-bin/mem_profile"] diff --git a/src/tests/rust_guests/simpleguest/src/main.rs b/src/tests/rust_guests/simpleguest/src/main.rs index aabe74dc5..f71b0ee4d 100644 --- a/src/tests/rust_guests/simpleguest/src/main.rs +++ b/src/tests/rust_guests/simpleguest/src/main.rs @@ -53,12 +53,12 @@ use hyperlight_guest_bin::host_comm::{ use hyperlight_guest_bin::memory::malloc; use hyperlight_guest_bin::{MIN_STACK_ADDRESS, guest_logger}; use log::{LevelFilter, error}; +use tracing::{Span, instrument}; extern crate hyperlight_guest; static mut BIGARRAY: [i32; 1024 * 1024] = [0; 1024 * 1024]; -#[hyperlight_guest_tracing::trace_function] fn set_static(_: &FunctionCall) -> Result> { unsafe { #[allow(static_mut_refs)] @@ -70,7 +70,6 @@ fn set_static(_: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn echo_double(function_call: &FunctionCall) -> Result> { if let ParameterValue::Double(value) = function_call.parameters.clone().unwrap()[0].clone() { Ok(get_flatbuffer_result(value)) @@ -82,7 +81,6 @@ fn echo_double(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn echo_float(function_call: &FunctionCall) -> Result> { if let ParameterValue::Float(value) = function_call.parameters.clone().unwrap()[0].clone() { Ok(get_flatbuffer_result(value)) @@ -94,7 +92,7 @@ fn echo_float(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] +#[instrument(skip_all, parent = Span::current(), level= "Trace")] fn print_output(message: &str) -> Result> { let res = call_host_function::( "HostPrint", @@ -105,7 +103,7 @@ fn print_output(message: &str) -> Result> { Ok(get_flatbuffer_result(res)) } -#[hyperlight_guest_tracing::trace_function] +#[instrument(skip_all, parent = Span::current(), level= "Trace")] fn simple_print_output(function_call: &FunctionCall) -> Result> { if let ParameterValue::String(message) = function_call.parameters.clone().unwrap()[0].clone() { print_output(&message) @@ -117,7 +115,6 @@ fn simple_print_output(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn set_byte_array_to_zero(function_call: &FunctionCall) -> Result> { if let ParameterValue::VecBytes(mut vec) = function_call.parameters.clone().unwrap()[0].clone() { @@ -131,7 +128,6 @@ fn set_byte_array_to_zero(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn print_two_args(function_call: &FunctionCall) -> Result> { if let (ParameterValue::String(arg1), ParameterValue::Int(arg2)) = ( function_call.parameters.clone().unwrap()[0].clone(), @@ -147,7 +143,6 @@ fn print_two_args(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn print_three_args(function_call: &FunctionCall) -> Result> { if let (ParameterValue::String(arg1), ParameterValue::Int(arg2), ParameterValue::Long(arg3)) = ( function_call.parameters.clone().unwrap()[0].clone(), @@ -164,7 +159,6 @@ fn print_three_args(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn print_four_args(function_call: &FunctionCall) -> Result> { if let ( ParameterValue::String(arg1), @@ -190,7 +184,6 @@ fn print_four_args(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn print_five_args(function_call: &FunctionCall) -> Result> { if let ( ParameterValue::String(arg1), @@ -218,7 +211,6 @@ fn print_five_args(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn print_six_args(function_call: &FunctionCall) -> Result> { if let ( ParameterValue::String(arg1), @@ -248,7 +240,6 @@ fn print_six_args(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn print_seven_args(function_call: &FunctionCall) -> Result> { if let ( ParameterValue::String(arg1), @@ -280,7 +271,6 @@ fn print_seven_args(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn print_eight_args(function_call: &FunctionCall) -> Result> { if let ( ParameterValue::String(arg1), @@ -314,7 +304,6 @@ fn print_eight_args(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn print_nine_args(function_call: &FunctionCall) -> Result> { if let ( ParameterValue::String(arg1), @@ -350,7 +339,6 @@ fn print_nine_args(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn print_ten_args(function_call: &FunctionCall) -> Result> { if let ( ParameterValue::String(arg1), @@ -388,7 +376,6 @@ fn print_ten_args(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn print_eleven_args(function_call: &FunctionCall) -> Result> { if let ( ParameterValue::String(arg1), @@ -428,7 +415,6 @@ fn print_eleven_args(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn buffer_overrun(function_call: &FunctionCall) -> Result> { if let ParameterValue::String(value) = function_call.parameters.clone().unwrap()[0].clone() { let c_str = value.as_str(); @@ -451,7 +437,6 @@ fn buffer_overrun(function_call: &FunctionCall) -> Result> { } #[allow(unconditional_recursion)] -#[hyperlight_guest_tracing::trace_function] fn infinite_recursion(_a: &FunctionCall) -> Result> { // blackbox is needed so something //is written to the stack in release mode, @@ -461,7 +446,6 @@ fn infinite_recursion(_a: &FunctionCall) -> Result> { infinite_recursion(_a) } -#[hyperlight_guest_tracing::trace_function] fn stack_overflow(function_call: &FunctionCall) -> Result> { if let ParameterValue::Int(i) = function_call.parameters.clone().unwrap()[0].clone() { loop_stack_overflow(i); @@ -474,7 +458,6 @@ fn stack_overflow(function_call: &FunctionCall) -> Result> { } } // This function will allocate i * (8KiB + 1B) on the stack -#[hyperlight_guest_tracing::trace_function] fn loop_stack_overflow(i: i32) { if i > 0 { let _nums = black_box([0u8; 0x2000 + 1]); // chkstk guaranteed to be called for > 8KiB @@ -482,19 +465,16 @@ fn loop_stack_overflow(i: i32) { } } -#[hyperlight_guest_tracing::trace_function] fn large_var(_: &FunctionCall) -> Result> { let _buffer = black_box([0u8; (DEFAULT_GUEST_STACK_SIZE + 1) as usize]); Ok(get_flatbuffer_result(DEFAULT_GUEST_STACK_SIZE + 1)) } -#[hyperlight_guest_tracing::trace_function] fn small_var(_: &FunctionCall) -> Result> { let _buffer = black_box([0u8; 1024]); Ok(get_flatbuffer_result(1024)) } -#[hyperlight_guest_tracing::trace_function] fn call_malloc(function_call: &FunctionCall) -> Result> { if let ParameterValue::Int(size) = function_call.parameters.clone().unwrap()[0].clone() { // will panic if OOM, and we need blackbox to avoid optimizing away this test @@ -509,7 +489,6 @@ fn call_malloc(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] unsafe fn exhaust_heap(_: &FunctionCall) -> ! { let layout: Layout = Layout::new::(); let mut ptr = alloc::alloc::alloc_zeroed(layout); @@ -526,7 +505,6 @@ unsafe fn exhaust_heap(_: &FunctionCall) -> ! { panic!("function should have panicked before due to OOM") } -#[hyperlight_guest_tracing::trace_function] fn malloc_and_free(function_call: &FunctionCall) -> Result> { if let ParameterValue::Int(size) = function_call.parameters.clone().unwrap()[0].clone() { let alloc_length = if size < DEFAULT_GUEST_STACK_SIZE { @@ -546,7 +524,6 @@ fn malloc_and_free(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn echo(function_call: &FunctionCall) -> Result> { if let ParameterValue::String(value) = function_call.parameters.clone().unwrap()[0].clone() { Ok(get_flatbuffer_result(&*value)) @@ -558,7 +535,6 @@ fn echo(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn get_size_prefixed_buffer(function_call: &FunctionCall) -> Result> { if let ParameterValue::VecBytes(data) = function_call.parameters.clone().unwrap()[0].clone() { Ok(get_flatbuffer_result(&*data)) @@ -583,7 +559,6 @@ fn spin(_: &FunctionCall) -> Result> { Ok(get_flatbuffer_result(())) } -#[hyperlight_guest_tracing::trace_function] fn test_abort(function_call: &FunctionCall) -> Result> { if let ParameterValue::Int(code) = function_call.parameters.clone().unwrap()[0].clone() { abort_with_code(&[code as u8]); @@ -591,7 +566,6 @@ fn test_abort(function_call: &FunctionCall) -> Result> { Ok(get_flatbuffer_result(())) } -#[hyperlight_guest_tracing::trace_function] fn test_abort_with_code_and_message(function_call: &FunctionCall) -> Result> { if let (ParameterValue::Int(code), ParameterValue::String(message)) = ( function_call.parameters.clone().unwrap()[0].clone(), @@ -604,7 +578,6 @@ fn test_abort_with_code_and_message(function_call: &FunctionCall) -> Result Result> { if let ParameterValue::String(message) = function_call.parameters.clone().unwrap()[0].clone() { panic!("{}", message); @@ -612,7 +585,6 @@ fn test_guest_panic(function_call: &FunctionCall) -> Result> { Ok(get_flatbuffer_result(())) } -#[hyperlight_guest_tracing::trace_function] fn test_write_raw_ptr(function_call: &FunctionCall) -> Result> { if let ParameterValue::Long(offset) = function_call.parameters.clone().unwrap()[0].clone() { let min_stack_addr = unsafe { MIN_STACK_ADDRESS }; @@ -636,7 +608,6 @@ fn test_write_raw_ptr(function_call: &FunctionCall) -> Result> { Ok(get_flatbuffer_result("fail")) } -#[hyperlight_guest_tracing::trace_function] fn execute_on_stack(_function_call: &FunctionCall) -> Result> { unsafe { let mut noop: u8 = 0x90; @@ -646,7 +617,6 @@ fn execute_on_stack(_function_call: &FunctionCall) -> Result> { Ok(get_flatbuffer_result("fail")) } -#[hyperlight_guest_tracing::trace_function] fn execute_on_heap(_function_call: &FunctionCall) -> Result> { unsafe { // NO-OP followed by RET @@ -659,7 +629,6 @@ fn execute_on_heap(_function_call: &FunctionCall) -> Result> { Ok(get_flatbuffer_result("fail")) } -#[hyperlight_guest_tracing::trace_function] fn test_rust_malloc(function_call: &FunctionCall) -> Result> { if let ParameterValue::Int(code) = function_call.parameters.clone().unwrap()[0].clone() { let ptr = unsafe { malloc(code as usize) }; @@ -672,7 +641,6 @@ fn test_rust_malloc(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn log_message(function_call: &FunctionCall) -> Result> { if let (ParameterValue::String(message), ParameterValue::Int(level)) = ( function_call.parameters.clone().unwrap()[0].clone(), @@ -695,7 +663,6 @@ fn log_message(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn trigger_exception(_: &FunctionCall) -> Result> { unsafe { core::arch::asm!("ud2"); @@ -705,7 +672,6 @@ fn trigger_exception(_: &FunctionCall) -> Result> { static mut COUNTER: i32 = 0; -#[hyperlight_guest_tracing::trace_function] fn add_to_static(function_call: &FunctionCall) -> Result> { if let ParameterValue::Int(i) = function_call.parameters.clone().unwrap()[0].clone() { let res = unsafe { @@ -721,7 +687,6 @@ fn add_to_static(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn get_static(function_call: &FunctionCall) -> Result> { if function_call.parameters.is_none() { Ok(get_flatbuffer_result(unsafe { COUNTER })) @@ -733,7 +698,6 @@ fn get_static(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn add_to_static_and_fail(_: &FunctionCall) -> Result> { unsafe { COUNTER += 10; @@ -744,7 +708,6 @@ fn add_to_static_and_fail(_: &FunctionCall) -> Result> { )) } -#[hyperlight_guest_tracing::trace_function] fn twenty_four_k_in_eight_k_out(function_call: &FunctionCall) -> Result> { if let ParameterValue::VecBytes(input) = &function_call.parameters.as_ref().unwrap()[0] { assert!(input.len() == 24 * 1024, "Input must be 24K bytes"); @@ -757,7 +720,6 @@ fn twenty_four_k_in_eight_k_out(function_call: &FunctionCall) -> Result> } } -#[hyperlight_guest_tracing::trace_function] fn violate_seccomp_filters(function_call: &FunctionCall) -> Result> { if function_call.parameters.is_none() { let res = call_host_function::("MakeGetpidSyscall", None, ReturnType::ULong)?; @@ -771,7 +733,6 @@ fn violate_seccomp_filters(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn call_given_paramless_hostfunc_that_returns_i64(function_call: &FunctionCall) -> Result> { if let ParameterValue::String(hostfuncname) = function_call.parameters.clone().unwrap()[0].clone() @@ -787,7 +748,6 @@ fn call_given_paramless_hostfunc_that_returns_i64(function_call: &FunctionCall) } } -#[hyperlight_guest_tracing::trace_function] fn add(function_call: &FunctionCall) -> Result> { if let (ParameterValue::Int(a), ParameterValue::Int(b)) = ( function_call.parameters.clone().unwrap()[0].clone(), @@ -808,7 +768,6 @@ fn add(function_call: &FunctionCall) -> Result> { } // Does nothing, but used for testing large parameters -#[hyperlight_guest_tracing::trace_function] fn large_parameters(function_call: &FunctionCall) -> Result> { if let (ParameterValue::VecBytes(v), ParameterValue::String(s)) = ( function_call.parameters.clone().unwrap()[0].clone(), @@ -824,7 +783,6 @@ fn large_parameters(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn read_from_user_memory(function_call: &FunctionCall) -> Result> { if let (ParameterValue::ULong(num), ParameterValue::VecBytes(expected)) = ( function_call.parameters.clone().unwrap()[0].clone(), @@ -850,7 +808,6 @@ fn read_from_user_memory(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn read_mapped_buffer(function_call: &FunctionCall) -> Result> { if let (ParameterValue::ULong(base), ParameterValue::ULong(len)) = ( function_call.parameters.clone().unwrap()[0].clone(), @@ -874,7 +831,6 @@ fn read_mapped_buffer(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn write_mapped_buffer(function_call: &FunctionCall) -> Result> { if let (ParameterValue::ULong(base), ParameterValue::ULong(len)) = ( function_call.parameters.clone().unwrap()[0].clone(), @@ -902,7 +858,6 @@ fn write_mapped_buffer(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn exec_mapped_buffer(function_call: &FunctionCall) -> Result> { if let (ParameterValue::ULong(base), ParameterValue::ULong(len)) = ( function_call.parameters.clone().unwrap()[0].clone(), @@ -931,7 +886,7 @@ fn exec_mapped_buffer(function_call: &FunctionCall) -> Result> { } #[no_mangle] -#[hyperlight_guest_tracing::trace_function] +#[instrument(skip_all, parent = Span::current(), level= "Trace")] pub extern "C" fn hyperlight_main() { let twenty_four_k_in_def = GuestFunctionDefinition::new( "24K_in_8K_out".to_string(), @@ -1479,7 +1434,6 @@ pub extern "C" fn hyperlight_main() { register_function(call_given_hostfunc_def); } -#[hyperlight_guest_tracing::trace_function] fn send_message_to_host_method( method_name: &str, guest_message: &str, @@ -1495,7 +1449,6 @@ fn send_message_to_host_method( Ok(get_flatbuffer_result(res)) } -#[hyperlight_guest_tracing::trace_function] fn guest_function(function_call: &FunctionCall) -> Result> { if let ParameterValue::String(message) = &function_call.parameters.as_ref().unwrap()[0] { send_message_to_host_method("HostMethod", "Hello from GuestFunction, ", message) @@ -1507,7 +1460,6 @@ fn guest_function(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn guest_function1(function_call: &FunctionCall) -> Result> { if let ParameterValue::String(message) = &function_call.parameters.as_ref().unwrap()[0] { send_message_to_host_method("HostMethod1", "Hello from GuestFunction1, ", message) @@ -1519,7 +1471,6 @@ fn guest_function1(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn guest_function2(function_call: &FunctionCall) -> Result> { if let ParameterValue::String(message) = &function_call.parameters.as_ref().unwrap()[0] { send_message_to_host_method("HostMethod1", "Hello from GuestFunction2, ", message) @@ -1531,7 +1482,6 @@ fn guest_function2(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn guest_function3(function_call: &FunctionCall) -> Result> { if let ParameterValue::String(message) = &function_call.parameters.as_ref().unwrap()[0] { send_message_to_host_method("HostMethod1", "Hello from GuestFunction3, ", message) @@ -1543,7 +1493,6 @@ fn guest_function3(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn guest_function4(_: &FunctionCall) -> Result> { call_host_function::<()>( "HostMethod4", @@ -1556,7 +1505,6 @@ fn guest_function4(_: &FunctionCall) -> Result> { Ok(get_flatbuffer_result(())) } -#[hyperlight_guest_tracing::trace_function] fn guest_log_message(function_call: &FunctionCall) -> Result> { if let ( ParameterValue::String(message), @@ -1590,7 +1538,6 @@ fn guest_log_message(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn call_error_method(function_call: &FunctionCall) -> Result> { if let ParameterValue::String(message) = &function_call.parameters.as_ref().unwrap()[0] { send_message_to_host_method("ErrorMethod", "Error From Host: ", message) @@ -1602,13 +1549,11 @@ fn call_error_method(function_call: &FunctionCall) -> Result> { } } -#[hyperlight_guest_tracing::trace_function] fn call_host_spin(_: &FunctionCall) -> Result> { call_host_function::<()>("Spin", None, ReturnType::Void)?; Ok(get_flatbuffer_result(())) } -#[hyperlight_guest_tracing::trace_function] fn host_call_loop(function_call: &FunctionCall) -> Result> { if let ParameterValue::String(message) = &function_call.parameters.as_ref().unwrap()[0] { loop { @@ -1623,7 +1568,6 @@ fn host_call_loop(function_call: &FunctionCall) -> Result> { } // Interprets the given guest function call as a host function call and dispatches it to the host. -#[hyperlight_guest_tracing::trace_function] fn fuzz_host_function(func: FunctionCall) -> Result> { let mut params = func.parameters.unwrap(); // first parameter must be string (the name of the host function to call) @@ -1653,7 +1597,7 @@ fn fuzz_host_function(func: FunctionCall) -> Result> { } #[no_mangle] -#[hyperlight_guest_tracing::trace_function] +#[instrument(skip_all, parent = Span::current(), level= "Trace")] pub fn guest_dispatch_function(function_call: FunctionCall) -> Result> { // This test checks the stack behavior of the input/output buffer // by calling the host before serializing the function call. diff --git a/src/tests/rust_guests/witguest/Cargo.lock b/src/tests/rust_guests/witguest/Cargo.lock index 6a33cb503..340707c32 100644 --- a/src/tests/rust_guests/witguest/Cargo.lock +++ b/src/tests/rust_guests/witguest/Cargo.lock @@ -88,6 +88,12 @@ dependencies = [ "spin 0.9.8", ] +[[package]] +name = "byteorder" +version = "1.5.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "1fd0f2584146f6f2ef48085050886acf353beff7305ebd1ae69500e27c67f64b" + [[package]] name = "cc" version = "1.2.34" @@ -166,6 +172,15 @@ version = "0.3.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "0cc23270f6e1808e30a928bdc84dea0b9b4136a8bc82338574f23baf47bbd280" +[[package]] +name = "hash32" +version = "0.3.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "47d60b12902ba28e2730cd37e95b8c9223af2808df9e902d4df49588d1470606" +dependencies = [ + "byteorder", +] + [[package]] name = "hashbrown" version = "0.15.5" @@ -176,6 +191,17 @@ dependencies = [ "serde", ] +[[package]] +name = "heapless" +version = "0.8.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "0bfb9eb618601c89945a70e254898da93b13be0388091d42117462b265bb3fad" +dependencies = [ + "hash32", + "serde", + "stable_deref_trait", +] + [[package]] name = "hyperlight-common" version = "0.9.0" @@ -222,6 +248,7 @@ dependencies = [ "hyperlight-common", "hyperlight-guest-tracing", "serde_json", + "tracing", ] [[package]] @@ -237,24 +264,18 @@ dependencies = [ "hyperlight-guest-tracing", "log", "spin 0.10.0", + "tracing", ] [[package]] name = "hyperlight-guest-tracing" version = "0.9.0" dependencies = [ + "heapless", "hyperlight-common", - "hyperlight-guest-tracing-macro", "spin 0.10.0", -] - -[[package]] -name = "hyperlight-guest-tracing-macro" -version = "0.9.0" -dependencies = [ - "proc-macro2", - "quote", - "syn", + "tracing", + "tracing-core", ] [[package]] @@ -341,6 +362,12 @@ version = "1.70.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "a4895175b425cb1f87721b59f0f286c2092bd4af812243672510e1ac53e2e0ad" +[[package]] +name = "pin-project-lite" +version = "0.2.16" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3b3cff922bd51709b605d9ead9aa71031d81447142d828eb4a6eba76fe619f9b" + [[package]] name = "portable-atomic" version = "1.11.1" @@ -496,6 +523,12 @@ dependencies = [ "lock_api", ] +[[package]] +name = "stable_deref_trait" +version = "1.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a8f112729512f8e442d81f95a8a7ddf2b7c6b8a1a6f509a95864142b30cab2d3" + [[package]] name = "syn" version = "2.0.106" @@ -507,6 +540,34 @@ dependencies = [ "unicode-ident", ] +[[package]] +name = "tracing" +version = "0.1.41" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "784e0ac535deb450455cbfa28a6f0df145ea1bb7ae51b821cf5e7927fdcfbdd0" +dependencies = [ + "pin-project-lite", + "tracing-attributes", + "tracing-core", +] + +[[package]] +name = "tracing-attributes" +version = "0.1.30" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "81383ab64e72a7a8b8e13130c49e3dab29def6d0c7d76a03087b3cf71c5c6903" +dependencies = [ + "proc-macro2", + "quote", + "syn", +] + +[[package]] +name = "tracing-core" +version = "0.1.34" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b9d12581f227e93f094d3af2ae690a574abb8a2b9b7a96e7cfe9647b2b617678" + [[package]] name = "unicode-ident" version = "1.0.18" diff --git a/src/tests/rust_guests/witguest/Cargo.toml b/src/tests/rust_guests/witguest/Cargo.toml index 82f87b9f5..769d2e322 100644 --- a/src/tests/rust_guests/witguest/Cargo.toml +++ b/src/tests/rust_guests/witguest/Cargo.toml @@ -13,5 +13,4 @@ spin = "0.10.0" [features] default = [] trace_guest = ["hyperlight-guest-bin/trace_guest", "hyperlight-guest/trace_guest"] -unwind_guest = ["hyperlight-common/unwind_guest"] mem_profile = ["hyperlight-common/mem_profile", "hyperlight-guest-bin/mem_profile"] diff --git a/src/trace_dump/main.rs b/src/trace_dump/main.rs index 4f8416769..6f4c062b5 100644 --- a/src/trace_dump/main.rs +++ b/src/trace_dump/main.rs @@ -25,19 +25,6 @@ use std::time::Duration; use piet_common::{Color, RenderContext, Text, TextLayout, TextLayoutBuilder, kurbo}; -fn read_u8_vec(inf: &mut File) -> Option> { - let len = read_u64(inf)?; - let mut vec = Vec::with_capacity(len as usize); - for _ in 0..len { - vec.push(read_u8(inf)?); - } - Some(vec) -} -fn read_u8(inf: &mut File) -> Option { - let mut bytes: [u8; 1] = [0; 1]; - inf.read_exact(&mut bytes).ok()?; - Some(u8::from_ne_bytes(bytes)) -} fn read_u128(inf: &mut File) -> Result { let mut bytes: [u8; 16] = [0; 16]; inf.read_exact(&mut bytes)?; @@ -105,53 +92,6 @@ fn dump_free( Some(()) } -fn dump_trace_record( - _state: &mut State, - _rs: &mut (), - indent: &mut u64, - now: Duration, - msg: Rc<[u8]>, -) -> Option<()> { - let msg = String::from_utf8_lossy(&msg); - - // Pretty-printing of trace records to show indentation based on the trace depth. - // Indentation is increased for messages starting with `>`, and decreased for messages starting - // with `<`. - // With the exception of `> halt`, which decreases the indent (because `> entrypoint` does not - // have a corresponding `< entrypoint`) - let msg = if msg.starts_with('>') { - if msg == "> halt" { - if *indent > 0 { - *indent -= 1; - } - } - let indent_str = " ".repeat(*indent as usize); - let msg = format!("{}{}", indent_str, &msg); - if msg != "> halt" { - // If the message is not `> halt`, increment the indent. - // This is to ensure that the next message is indented correctly. - *indent += 1; - } - - msg - } else if msg.starts_with('<') { - if *indent > 0 { - *indent -= 1; - } - let indent_str = " ".repeat(*indent as usize); - let msg = format!("{}{}", indent_str, msg); - - msg - } else { - let indent_str = " ".repeat(*indent as usize); - format!("{}{}", indent_str, msg) - }; - - println!("\n[{:9?}] {}", now, msg); - - Some(()) -} - // todo: this should use something more reasonable than a hash table // for each node. let's measure the out-degree and see if a small // array is better, to start. @@ -602,33 +542,20 @@ fn render_free( Some(()) } -fn render_trace_record( - _state: &mut State, - _rs: &mut RenderState, - _indent: &mut u64, - _now: Duration, - _msg: Rc<[u8]>, -) -> Option<()> { - Some(()) -} - -fn read_file( +fn read_file( state: &mut State, mut handle_state: S, handle_ident: I, handle_unwind: U, handle_alloc: A, handle_free: F, - handle_trace_record: T, ) -> Option<()> where I: Fn(&mut State, &mut S, Duration, blake3::Hash) -> Option<()>, U: Fn(&mut State, &mut S, Duration, Rc<[u64]>) -> Option<()>, A: Fn(&mut State, &mut S, Duration, u64, u64, Rc<[u64]>) -> Option<()>, F: Fn(&mut State, &mut S, Duration, u64, u64, Rc<[u64]>) -> Option<()>, - T: Fn(&mut State, &mut S, &mut u64, Duration, Rc<[u8]>) -> Option<()>, { - let mut indent = 0; loop { let time = match read_u128(&mut state.inf) { Ok(t) => t, @@ -673,9 +600,6 @@ where let trace = amt_trace.1.clone(); state.total -= amt; handle_free(state, &mut handle_state, now, ptr, amt, trace)?; - } else if frame_id == 4 { - let msg = read_u8_vec(&mut state.inf)?.into(); - handle_trace_record(state, &mut handle_state, &mut indent, now, msg)?; } else { return None; } @@ -775,7 +699,6 @@ fn spawn_render_thread( render_unwind, render_alloc, render_free, - render_trace_record, )?; bar_ffmpeg.wait().ok()?; flame_ffmpeg.wait().ok()?; @@ -832,7 +755,6 @@ fn dump_trace(mut state: State) { dump_unwind, dump_alloc, dump_free, - dump_trace_record, ); } @@ -849,7 +771,6 @@ fn plot_mem(args: Vec, mut state: State) { |_, _, _, _| Some(()), |_, _, _, _, _, _| Some(()), |_, _, _, _, _, _| Some(()), - |_, _, _, _, _| Some(()), ) { Some(()) => (), None => { @@ -889,7 +810,6 @@ fn plot_mem(args: Vec, mut state: State) { |_, _, _, _| Some(()), count_frame, count_frame, - |_, _, _, _, _| Some(()), ); if state.num_durations > 0 { (*jobs.lock().unwrap()).push((*start_duration.lock().unwrap(), state.max_duration));