Guest tracing improvements to use `tracing` crate #844

dblnz · 2025-08-31T13:46:42Z

Description

This PR closes #723, #704 and partially addresses #318.
These changes modify the way we perform guest tracing to use the tracing crate and its macros (instrument, trace).

How it works

Guest

What makes this possible is the implementation of the Subscriber trait in the hyperlight-guest-tracing crate. By implementing it, we can now handle the capturing of spans and events and choose how to store them and when to export them to the host.

The GuestSubscriber type that implements Subscriber keeps an internal TraceState that holds all the needed information.
Whenever a new span is created, entered or exited, a callback on the subscriber is called so that we can handle the functionality. The same happens with the events also.

Each time a new span or event is added to the internal state, we check whether the buffer got full and send them to the host to process.

Host

When the host detects a VM exit from the guest, it checks whether it contains tracing information in the OutB instruction.
When tracing information is found, the host starts going through it and check against the local storage of spans.

If the spans have previously been created, just update the end timestamp (if present) and add new events (if any).
If they haven't been created, create and store them.

The spans parents are set based on the information got from the host.

TODO

The current issue is with the guest calls that end up calling back into the host.
These do not correctly set the parents of the spans created in the host to the last one created in the guest before doing the VM exit
I need to find a way to propagate the context into the guest and back whenever it is needed. But using the Opentelemetry propagators needs std support which we do not have in the guest.
There is a corner case with calculating the timestamp for the span that is open when a VM exit is done

Jaeger picture of a Guest call that calls back into the host

jprendes

I made a high level review, and what I've seen looks good :-)

jprendes · 2025-09-01T08:37:30Z

src/hyperlight_host/src/hypervisor/hyperv_windows.rs

@@ -1094,15 +1095,9 @@ impl Hypervisor for HypervWindowsDriver {
    }

    #[cfg(feature = "trace_guest")]
-    fn read_trace_reg(&self, reg: TraceRegister) -> Result<u64> {
+    fn read_trace_reg(&self) -> Result<X86_64Regs> {


should this be read_regs(&self)?

jprendes · 2025-09-01T08:50:10Z

src/hyperlight_host/src/hypervisor/hyperv_linux.rs

-    }
-    #[cfg(feature = "trace_guest")]
-    fn trace_info_as_mut(&mut self) -> &mut TraceInfo {
+    fn trace_info_mut(&mut self) -> &mut TraceInfo {


<rant>
Ah, I never understand this pattern, why isn't trace_info directly a public member?
But we have that all over the codebase, so... it's ok here
</rant>

Because in this case, I need to retrieve the TraceInfo through the &dyn Hypervisor which doesn't know about the KvmDriver's member field.

I don't like it either, to be honest, I think this will look a lot better when we unify the Hypervisors into a single struct. A lot of duplicated code will go also

jprendes · 2025-09-01T09:27:24Z

Cargo.toml

@@ -11,7 +11,6 @@ members = [
    "src/hyperlight_host",
    "src/hyperlight_guest_capi",
    "src/hyperlight_guest_tracing",
-    "src/hyperlight_guest_tracing_macro",


Should we keep it around, but as deprecated, shimming the new API? so that we don't break anyone who was already using this?

Yes, I think this is the way to go. But I don't think we'll ever use it again

jprendes · 2025-09-01T09:29:40Z

src/hyperlight_common/src/outb.rs

-            #[cfg(feature = "trace_guest")]
-            104 => Ok(OutBAction::TraceRecord),


I haven't though about this before, but, does this mean that a guest compiled with an older hyperlight_guest doesn't run in a newer hyperlight_host?
We should think about this more carefully, not particularly in this PR, but I think in general we haven't been too diligent on paying attention to that.

I've created #845 to track that.

Yes, and in this case, Ideally we should keep that 104 value reserved

jprendes · 2025-09-01T09:54:17Z

src/hyperlight_host/src/hypervisor/hyperv_linux.rs

+            HyperlightExit::Halt()
+            | HyperlightExit::IoOut(_, _, _, _)
+            | HyperlightExit::Mmio(_) => {
+                // If the result is not a halt, io out, mmio or debug exit, we need to process the trace batch


Is the comment wrong? the logic wrong? or my understanding wrong?

Suggested change

// If the result is not a halt, io out, mmio or debug exit, we need to process the trace batch

// If the result is a halt, io out, mmio or debug exit, we need to process the trace batch

jprendes · 2025-09-01T10:03:58Z

src/hyperlight_host/src/hypervisor/hyperv_windows.rs

+            HyperlightExit::Halt()
+            | HyperlightExit::IoOut(_, _, _, _)
+            | HyperlightExit::Mmio(_) => {
+                // If the result is not a halt, io out, mmio or debug exit, we need to process the trace batch


jprendes · 2025-09-01T10:04:08Z

src/hyperlight_host/src/hypervisor/kvm.rs

+            HyperlightExit::Halt()
+            | HyperlightExit::IoOut(_, _, _, _)
+            | HyperlightExit::Mmio(_) => {
+                // If the result is not a halt, io out, mmio or debug exit, we need to process the trace batch


- This feature is not used separate from the mem_profile - All the unwind logic is now gated by mem_profile Signed-off-by: Doru Blânzeanu <[email protected]>

- The guest side does not use this type of OutBAction - The stack unwinding is done either way when the mem_profile feature is enabled Signed-off-by: Doru Blânzeanu <[email protected]>

ludfjig

First round review looks good to me. I am curious what the performance looks like with tracing vs without, maybe we could add a benchmark or something for this?

Also, is there any possibility that we don't flush spans/records after exiting the guest, and that some end up not being emitted?

Another thing to consider is log crate vs tracing crate. Should we ditch one? Or is there some mechanism that allows regular logs to be consumed by tracing crate: And should we expose any of these in guest C-api?

Also is the tracing buffer sizes configurable? Maybe it should be if it isn't, so users can tweak it in case it affects performance.

ludfjig · 2025-09-11T18:28:52Z

src/hyperlight_common/Cargo.toml

@@ -26,7 +26,6 @@ spin = "0.10.0"
 default = ["tracing"]
 fuzzing = ["dep:arbitrary"]
 trace_guest = []
-unwind_guest = []


What happened to this feature?

I merged it into the mem_profile one as it is only used there and it increases the number of combinations we need to test in CI

ludfjig · 2025-09-11T21:16:12Z

src/hyperlight_guest/src/exit.rs


 /// 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")]


I know we have parent = Span::current() in host as well, but I was wondering if we can leave this out if it's already the default?

We could do that

ludfjig · 2025-09-11T21:19:08Z

src/hyperlight_guest/src/guest_handle/host_comm.rs

+        #[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();


Is this logic correct? Would there be any differences in logging when tracing is enabled and using trace! vs disabled?

Yes.
So the current mechanism we have is doing a VM Exit for each log we emit on the guest so that the host receives the info and does the emitting on behalf of the guest. We do not want those kind of interruptions if we can batch the traces, right?

ludfjig · 2025-09-11T21:22:12Z

src/hyperlight_guest_tracing/src/invariant_tsc.rs

+/// # 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 {


Maybe we don't need this safety comment if it's safe?

jsturtevant · 2025-09-11T23:17:46Z

I am curious what the performance looks like with tracing vs without, maybe we could add a benchmark or something for this?

+1

dblnz · 2025-09-12T15:27:26Z

First round review looks good to me. I am curious what the performance looks like with tracing vs without, maybe we could add a benchmark or something for this?

Ok, I can do that.

Also, is there any possibility that we don't flush spans/records after exiting the guest, and that some end up not being emitted?

Hmm, in my limited testing I haven't seen this case, but I wouldn't exclude the possibility.
One scenario that comes to mind is cancellation, where the vCPU forced to stop, so no out instruction to deliver the info.
Any ideas how we can treat these scenarios?

Another thing to consider is log crate vs tracing crate. Should we ditch one? Or is there some mechanism that allows regular logs to be consumed by tracing crate: And should we expose any of these in guest C-api?

I am not sure about the best approach is.
The solution I added for guest spans/events only works with opentelemetry Subscribers on the host, so if no opentelemetry subscribers, the they won't be captured (haven't tried it yet, but this is how it should work)

Also is the tracing buffer sizes configurable? Maybe it should be if it isn't, so users can tweak it in case it affects performance.

The tracing buffer is compile time configurable, which I agree is not ideal for customers.
But I needed a fixed size buffer so that I could reliably give the pointer to the host to access memory (current approach, I don't know if it is the best, but it is certainly faster than using the input/output buffer which copies data twice. This way we only copy once, on the host).

Signed-off-by: Doru Blânzeanu <[email protected]>

- This helps with keeping code separate and easily gating it out Signed-off-by: Doru Blânzeanu <[email protected]>

- This steps cleans up codebase for the new way of tracing guests - The current method involves custom macros and logic that are not the best for maintainability Signed-off-by: Doru Blânzeanu <[email protected]>

- Define a separate struct that holds the functionality related to memory profiling of the guest Signed-off-by: Doru Blânzeanu <[email protected]>

- Rename TraceInfo to reflect only being used by mem_profile Signed-off-by: Doru Blânzeanu <[email protected]>

Signed-off-by: Doru Blânzeanu <[email protected]>

- Adds a type that implements the Subscriber trait of the tracing_core crate that allows the type to be set as the global Subscriber of the crate - This way we can handle the adding of new spans and events and store them where/how we want Signed-off-by: Doru Blânzeanu <[email protected]>

- implement add_span and event methods that store the info and report it to the host when the buffer gets full Signed-off-by: Doru Blânzeanu <[email protected]>

Signed-off-by: Doru Blânzeanu <[email protected]>

- Parse the spans and events coming from the guest and create corresponding spans and events from the host that mimics a single call from host - Create a `TraceContext` that handles a call into a guest Signed-off-by: Doru Blânzeanu <[email protected]>

- conditionally handle logs either through tracing or the dedicated VM exit based on whether tracing is initialized on the guest Signed-off-by: Doru Blânzeanu <[email protected]>

Signed-off-by: Doru Blânzeanu <[email protected]>

dblnz requested review from danbugs, ludfjig, devigned, syntactically, marosset, jprendes and simongdavies as code owners August 31, 2025 13:46

dblnz added the kind/enhancement For PRs adding features, improving functionality, docs, tests, etc. label Aug 31, 2025

dblnz changed the title ~~Tracing improvements~~ Guest tracing improvements to use tracing crate Aug 31, 2025

dblnz marked this pull request as draft August 31, 2025 13:48

jprendes reviewed Sep 1, 2025

View reviewed changes

dblnz added 2 commits September 11, 2025 01:39

[trace-guest] remove unwind_guest feature

7f3e623

- This feature is not used separate from the mem_profile - All the unwind logic is now gated by mem_profile Signed-off-by: Doru Blânzeanu <[email protected]>

[trace-host] remove unused OutBAction::TraceRecordStack

7084845

- The guest side does not use this type of OutBAction - The stack unwinding is done either way when the mem_profile feature is enabled Signed-off-by: Doru Blânzeanu <[email protected]>

dblnz force-pushed the tracing-improvements branch 2 times, most recently from d4327a8 to ccaa14e Compare September 10, 2025 22:45

dblnz marked this pull request as ready for review September 10, 2025 22:45

dblnz force-pushed the tracing-improvements branch from ccaa14e to cceb069 Compare September 10, 2025 22:47

ludfjig reviewed Sep 11, 2025

View reviewed changes

dblnz added 2 commits September 12, 2025 18:58

[trace-host] remove TraceRegister and use X86_64Regs instead

74bdb61

Signed-off-by: Doru Blânzeanu <[email protected]>

[trace-host] move trace related logic to separate module

46ed93f

- This helps with keeping code separate and easily gating it out Signed-off-by: Doru Blânzeanu <[email protected]>

dblnz force-pushed the tracing-improvements branch from cceb069 to b55e36c Compare September 12, 2025 15:59

dblnz added 5 commits September 12, 2025 19:20

[trace] remove old tracing functionality

37f66c3

- This steps cleans up codebase for the new way of tracing guests - The current method involves custom macros and logic that are not the best for maintainability Signed-off-by: Doru Blânzeanu <[email protected]>

[trace-host] refactor mem_profile logic

c30e6c7

- Define a separate struct that holds the functionality related to memory profiling of the guest Signed-off-by: Doru Blânzeanu <[email protected]>

[trace-host] move mem_profile logic to different file

a97d729

- Rename TraceInfo to reflect only being used by mem_profile Signed-off-by: Doru Blânzeanu <[email protected]>

[trace-guest] move invariant_tsc logic to separate module

65f8dc0

Signed-off-by: Doru Blânzeanu <[email protected]>

dblnz force-pushed the tracing-improvements branch from b55e36c to 186a34d Compare September 12, 2025 16:20

[trace-guest] add span and event storage logic

588260a

- implement add_span and event methods that store the info and report it to the host when the buffer gets full Signed-off-by: Doru Blânzeanu <[email protected]>

dblnz added 5 commits September 12, 2025 19:32

[trace-guest] update outb instructions to include trace info

99d35a7

Signed-off-by: Doru Blânzeanu <[email protected]>

[trace-guest] update guest crates to add trace instrumentation

7329249

- conditionally handle logs either through tracing or the dedicated VM exit based on whether tracing is initialized on the guest Signed-off-by: Doru Blânzeanu <[email protected]>

[trace-guest] add spans in simpleguest sample

c426661

Signed-off-by: Doru Blânzeanu <[email protected]>

update tracing docs

d527f19

Signed-off-by: Doru Blânzeanu <[email protected]>

dblnz force-pushed the tracing-improvements branch from 186a34d to d527f19 Compare September 12, 2025 16:32

		#[cfg(feature = "trace_guest")]
		104 => Ok(OutBAction::TraceRecord),

	// If the result is not a halt, io out, mmio or debug exit, we need to process the trace batch
	// If the result is a halt, io out, mmio or debug exit, we need to process the trace batch

Guest tracing improvements to use tracing crate #844

Are you sure you want to change the base?

Guest tracing improvements to use tracing crate #844

Uh oh!

Conversation

dblnz commented Aug 31, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Description

How it works

Guest

Host

TODO

Uh oh!

jprendes left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ludfjig left a comment • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

dblnz Sep 12, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jsturtevant commented Sep 11, 2025

Uh oh!

dblnz commented Sep 12, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Uh oh!

Guest tracing improvements to use `tracing` crate #844

Guest tracing improvements to use `tracing` crate #844

dblnz commented Aug 31, 2025 •

edited

Loading

ludfjig left a comment •

edited

Loading

dblnz Sep 12, 2025 •

edited

Loading

dblnz commented Sep 12, 2025 •

edited

Loading