[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 <[email protected]>

Author: dblnz

Cargo.lock

@@ -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/Cargo.toml

@@ -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)
@@ -62,7 +68,10 @@ pub unsafe fn abort_with_code_and_message(code: &[u8], message_ptr: *const c_cha
 }
 
 /// OUT bytes to the host through multiple exits.
+#[hyperlight_guest_tracing_macro::trace_function]
 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() {
@@ -79,6 +88,7 @@ pub(crate) fn outb(port: u16, data: &[u8]) {
 }
 
 /// OUT function for sending a 32-bit value to the host.
+#[hyperlight_guest_tracing_macro::trace_function]
 pub(crate) unsafe fn out32(port: u16, val: u32) {
     unsafe {
         asm!("out dx, eax", in("dx") port, in("eax") val, options(preserves_flags, nomem, nostack));

src/hyperlight_guest/src/exit.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,
@@ -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/host_comm.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]>,
@@ -68,15 +69,18 @@ impl GuestHandle {
         let buffer = &idb[last_element_offset_rel as usize..];
 
         // convert the buffer to T
-        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::<T>()),
-                ));
+        let type_t = hyperlight_guest_tracing_macro::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::<T>()),
+                    ));
+                }
             }
-        };
+        );
 
         // 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());
@@ -88,6 +92,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 +138,9 @@ impl GuestHandle {
         }
 
         // write the actual data
-        odb[stack_ptr_rel as usize..stack_ptr_rel as usize + data.len()].copy_from_slice(&data);
+        hyperlight_guest_tracing_macro::trace!("copy 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();

src/hyperlight_guest/src/guest_handle/io.rs

@@ -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/Cargo.toml

@@ -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/gdt.rs

@@ -65,6 +65,12 @@ 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_macro::trace!("> hl_exception_handler");
+
     let ctx = stack_pointer as *mut Context;
     let exn_info = (stack_pointer + size_of::<Context>() as u64) as *mut ExceptionInfo;
 
@@ -95,6 +101,7 @@ pub extern "C" fn hl_exception_handler(
                 )(exception_number, exn_info, ctx, page_fault_address)
             }
         {
+            hyperlight_guest_tracing_macro::trace!("< hl_exception_handler");
             return;
         }
     }

src/hyperlight_guest_bin/src/exceptions/handler.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/idt.rs

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