[hyperlight_guest] Add traces in the guest to track the execution timing

- Add traces wherever we think it might be of use to help us better
  profile the codebase.
- Add flush instructions before halting or running an `OutB` instruction
  to ensure the records are sent before the guest exits due to an error
  or a normal exit

Signed-off-by: Doru Blânzeanu <dblnz@pm.me>

Author: dblnz

src/hyperlight_guest/Cargo.toml

@@ -15,3 +15,9 @@ Provides only the essential building blocks for interacting with the host enviro
 anyhow = { version = "1.0.98", default-features = false }
 serde_json = { version = "1.0", default-features = false, features = ["alloc"] }
 hyperlight-common = { workspace = true }
+hyperlight-guest-tracing = { workspace = true, optional = true }
+hyperlight-guest-tracing-macro = { workspace = true}
+
+[features]
+default = []
+trace_guest = ["dep:hyperlight-guest-tracing"]

src/hyperlight_guest/src/exit.rs

@@ -21,17 +21,22 @@ use hyperlight_common::outb::OutBAction;
 
 /// Halt the execution of the guest and returns control to the host.
 #[inline(never)]
+#[hyperlight_guest_tracing_macro::trace_function]
 pub fn halt() {
+    // Ensure all tracing data is flushed before halting
+    hyperlight_guest_tracing_macro::flush!();
     unsafe { asm!("hlt", options(nostack)) }
 }
 
 /// Exits the VM with an Abort OUT action and code 0.
 #[unsafe(no_mangle)]
+#[hyperlight_guest_tracing_macro::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_macro::trace_function]
 pub fn abort_with_code(code: &[u8]) -> ! {
     outb(OutBAction::Abort as u16, code);
     outb(OutBAction::Abort as u16, &[0xFF]); // send abort terminator (if not included in code)
@@ -42,6 +47,7 @@ pub fn abort_with_code(code: &[u8]) -> ! {
 ///
 /// # Safety
 /// This function is unsafe because it dereferences a raw pointer.
+#[hyperlight_guest_tracing_macro::trace_function]
 pub unsafe fn abort_with_code_and_message(code: &[u8], message_ptr: *const c_char) -> ! {
     unsafe {
         // Step 1: Send abort code (typically 1 byte, but `code` allows flexibility)
@@ -63,6 +69,8 @@ pub unsafe fn abort_with_code_and_message(code: &[u8], message_ptr: *const c_cha
 
 /// OUT bytes to the host through multiple exits.
 pub(crate) fn outb(port: u16, data: &[u8]) {
+    // Ensure all tracing data is flushed before sending OUT bytes
+    hyperlight_guest_tracing_macro::flush!();
     unsafe {
         let mut i = 0;
         while i < data.len() {

src/hyperlight_guest/src/guest_handle/host_comm.rs

@@ -35,6 +35,7 @@ use crate::exit::out32;
 
 impl GuestHandle {
     /// Get user memory region as bytes.
+    #[hyperlight_guest_tracing_macro::trace_function]
     pub fn read_n_bytes_from_user_memory(&self, num: u64) -> Result<Vec<u8>> {
         let peb_ptr = self.peb().unwrap();
         let user_memory_region_ptr = unsafe { (*peb_ptr).init_data.ptr as *mut u8 };
@@ -63,6 +64,7 @@ impl GuestHandle {
     ///
     /// When calling `call_host_function<T>`, this function is called
     /// internally to get the return value.
+    #[hyperlight_guest_tracing_macro::trace_function]
     pub fn get_host_return_value<T: TryFrom<ReturnValue>>(&self) -> Result<T> {
         let return_value = self
             .try_pop_shared_input_data_into::<ReturnValue>()
@@ -83,6 +85,7 @@ impl GuestHandle {
     ///
     /// Note: The function return value must be obtained by calling
     /// `get_host_return_value`.
+    #[hyperlight_guest_tracing_macro::trace_function]
     pub fn call_host_function_without_returning_result(
         &self,
         function_name: &str,
@@ -114,6 +117,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_macro::trace_function]
     pub fn call_host_function<T: TryFrom<ReturnValue>>(
         &self,
         function_name: &str,
@@ -124,6 +128,7 @@ impl GuestHandle {
         self.get_host_return_value::<T>()
     }
 
+    #[hyperlight_guest_tracing_macro::trace_function]
     pub fn get_host_function_details(&self) -> HostFunctionDetails {
         let peb_ptr = self.peb().unwrap();
         let host_function_details_buffer =
@@ -140,6 +145,7 @@ impl GuestHandle {
     }
 
     /// Write an error to the shared output data buffer.
+    #[hyperlight_guest_tracing_macro::trace_function]
     pub fn write_error(&self, error_code: ErrorCode, message: Option<&str>) {
         let guest_error: GuestError = GuestError::new(
             error_code.clone(),
@@ -155,6 +161,7 @@ impl GuestHandle {
     }
 
     /// Log a message with the specified log level, source, caller, source file, and line number.
+    #[hyperlight_guest_tracing_macro::trace_function]
     pub fn log_message(
         &self,
         log_level: LogLevel,

src/hyperlight_guest/src/guest_handle/io.rs

@@ -27,6 +27,7 @@ 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_macro::trace_function]
     pub fn try_pop_shared_input_data_into<T>(&self) -> Result<T>
     where
         T: for<'a> TryFrom<&'a [u8]>,
@@ -78,8 +79,10 @@ impl GuestHandle {
             }
         };
 
+        hyperlight_guest_tracing_macro::trace!("Start copy of data");
         // 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());
+        hyperlight_guest_tracing_macro::trace!("Finish copy of data");
 
         // zero out popped off buffer
         idb[last_element_offset_rel as usize..stack_ptr_rel as usize].fill(0);
@@ -88,6 +91,7 @@ impl GuestHandle {
     }
 
     /// Pushes the given data onto the shared output data buffer.
+    #[hyperlight_guest_tracing_macro::trace_function]
     pub fn push_shared_output_data(&self, data: Vec<u8>) -> Result<()> {
         let peb_ptr = self.peb().unwrap();
         let output_stack_size = unsafe { (*peb_ptr).output_stack.size as usize };
@@ -133,7 +137,9 @@ impl GuestHandle {
         }
 
         // write the actual data
+        hyperlight_guest_tracing_macro::trace!("Start copy of data");
         odb[stack_ptr_rel as usize..stack_ptr_rel as usize + data.len()].copy_from_slice(&data);
+        hyperlight_guest_tracing_macro::trace!("Finish copy of 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();

src/hyperlight_guest_bin/Cargo.toml

@@ -17,11 +17,14 @@ and third-party code used by our C-API needed to build a native hyperlight-guest
 default = ["libc", "printf"]
 libc = [] # compile musl libc
 printf = [] # compile printf
+trace_guest = ["hyperlight-common/trace_guest", "dep:hyperlight-guest-tracing", "hyperlight-guest/trace_guest"]
 mem_profile = ["hyperlight-common/unwind_guest","hyperlight-common/mem_profile"]
 
 [dependencies]
 hyperlight-guest = { workspace = true, default-features = false }
 hyperlight-common = { workspace = true, default-features = false }
+hyperlight-guest-tracing = { workspace = true, optional = true }
+hyperlight-guest-tracing-macro = { workspace = true }
 buddy_system_allocator = "0.11.0"
 log = { version = "0.4", default-features = false }
 spin = "0.10.0"

src/hyperlight_guest_bin/src/exceptions/gdt.rs

@@ -72,6 +72,7 @@ struct GdtPointer {
 }
 
 /// Load the GDT
+#[hyperlight_guest_tracing_macro::trace_function]
 pub unsafe fn load_gdt() {
     unsafe {
         let gdt_ptr = GdtPointer {

src/hyperlight_guest_bin/src/exceptions/handler.rs

@@ -23,6 +23,7 @@ use hyperlight_guest::exit::abort_with_code_and_message;
 
 /// Exception handler
 #[unsafe(no_mangle)]
+#[hyperlight_guest_tracing_macro::trace_function]
 pub extern "C" fn hl_exception_handler(
     stack_pointer: u64,
     exception_number: u64,

src/hyperlight_guest_bin/src/exceptions/idt.rs

@@ -71,6 +71,7 @@ impl IdtEntry {
 // Architectures Software Developer's Manual).
 pub(crate) static mut IDT: [IdtEntry; 256] = unsafe { core::mem::zeroed() };
 
+#[hyperlight_guest_tracing_macro::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

src/hyperlight_guest_bin/src/exceptions/idtr.rs

@@ -40,6 +40,7 @@ impl Idtr {
     }
 }
 
+#[hyperlight_guest_tracing_macro::trace_function]
 pub(crate) unsafe fn load_idt() {
     unsafe {
         init_idt();

src/hyperlight_guest_bin/src/guest_function/call.rs

@@ -27,6 +27,7 @@ use crate::{GUEST_HANDLE, REGISTERED_GUEST_FUNCTIONS};
 
 type GuestFunc = fn(&FunctionCall) -> Result<Vec<u8>>;
 
+#[hyperlight_guest_tracing_macro::trace_function]
 pub(crate) fn call_guest_function(function_call: FunctionCall) -> Result<Vec<u8>> {
     // Validate this is a Guest Function Call
     if function_call.function_call_type() != FunctionCallType::Guest {
@@ -60,6 +61,7 @@ pub(crate) fn call_guest_function(function_call: FunctionCall) -> Result<Vec<u8>
             core::mem::transmute::<usize, GuestFunc>(function_pointer)
         };
 
+        hyperlight_guest_tracing_macro::trace!("Calling guest function");
         p_function(&function_call)
     } else {
         // The given function is not registered. The guest should implement a function called guest_dispatch_function to handle this.
@@ -71,6 +73,7 @@ pub(crate) fn call_guest_function(function_call: FunctionCall) -> Result<Vec<u8>
             fn guest_dispatch_function(function_call: FunctionCall) -> Result<Vec<u8>>;
         }
 
+        hyperlight_guest_tracing_macro::trace!("Guest function {} not found");
         unsafe { guest_dispatch_function(function_call) }
     }
 }
@@ -79,6 +82,7 @@ pub(crate) fn call_guest_function(function_call: FunctionCall) -> Result<Vec<u8>
 // 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_macro::trace_function]
 fn internal_dispatch_function() -> Result<()> {
     let handle = unsafe { GUEST_HANDLE };
 
@@ -99,6 +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_macro::trace_function]
 pub(crate) extern "C" fn dispatch_function() {
     let _ = internal_dispatch_function();
     halt();