Skip to content

Commit 40a22eb

Browse files
committed
[hyperlight-host/trace] Fixup: update the way the TSC frequency is calculated
- Rely on TSC readings on the host from when the guest is started and when the first records are received. Use these two moments in time and TSC readings to calculate the TSC frequency. - Afterwards we store the TSC reading from inside the guest and calculate all incoming TSC readings relative to the first one and using the frequency we can calculate the amount of time it took. Signed-off-by: Doru Blânzeanu <[email protected]>
1 parent 2199c90 commit 40a22eb

File tree

5 files changed

+96
-35
lines changed

5 files changed

+96
-35
lines changed

src/hyperlight_host/src/hypervisor/hyperv_linux.rs

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -763,8 +763,10 @@ impl Hypervisor for HypervLinuxDriver {
763763
} else {
764764
#[cfg(feature = "trace_guest")]
765765
if self.trace_info.guest_start_epoch.is_none() {
766-
// Set the guest start epoch to the current time, before running the vcpu
767-
crate::debug!("HyperV - Guest Start Epoch set");
766+
// Store the guest start epoch and cycles to trace the guest execution time
767+
crate::debug!("MSHV - Guest Start Epoch set");
768+
self.trace_info.guest_start_tsc =
769+
Some(hyperlight_guest_tracing::invariant_tsc::read_tsc());
768770
self.trace_info.guest_start_epoch = Some(std::time::Instant::now());
769771
}
770772
// Note: if a `InterruptHandle::kill()` called while this thread is **here**

src/hyperlight_host/src/hypervisor/hyperv_windows.rs

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -734,8 +734,10 @@ impl Hypervisor for HypervWindowsDriver {
734734
} else {
735735
#[cfg(feature = "trace_guest")]
736736
if self.trace_info.guest_start_epoch.is_none() {
737-
// Set the guest start epoch to the current time, before running the vcpu
738-
crate::debug!("MSHV - Guest Start Epoch set");
737+
// Store the guest start epoch and cycles to trace the guest execution time
738+
crate::debug!("HyperV - Guest Start Epoch set");
739+
self.trace_info.guest_start_tsc =
740+
Some(hyperlight_guest_tracing::invariant_tsc::read_tsc());
739741
self.trace_info.guest_start_epoch = Some(std::time::Instant::now());
740742
}
741743
self.processor.run()?

src/hyperlight_host/src/hypervisor/kvm.rs

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -645,9 +645,11 @@ impl Hypervisor for KVMDriver {
645645
} else {
646646
#[cfg(feature = "trace_guest")]
647647
if self.trace_info.guest_start_epoch.is_none() {
648-
// Set the guest start epoch to the current time, before running the vcpu
648+
// Store the guest start epoch and cycles to trace the guest execution time
649649
crate::debug!("KVM - Guest Start Epoch set");
650650
self.trace_info.guest_start_epoch = Some(std::time::Instant::now());
651+
self.trace_info.guest_start_tsc =
652+
Some(hyperlight_guest_tracing::invariant_tsc::read_tsc());
651653
}
652654

653655
// Note: if a `InterruptHandle::kill()` called while this thread is **here**

src/hyperlight_host/src/sandbox/mod.rs

Lines changed: 61 additions & 23 deletions
Original file line numberDiff line numberDiff line change
@@ -90,7 +90,7 @@ pub type ExtraAllowedSyscall = i64;
9090
/// Determine whether a suitable hypervisor is available to run
9191
/// this sandbox.
9292
///
93-
// Returns a boolean indicating whether a suitable hypervisor is present.
93+
/// Returns a boolean indicating whether a suitable hypervisor is present.
9494
#[instrument(skip_all, parent = Span::current())]
9595
pub fn is_hypervisor_present() -> bool {
9696
hypervisor::get_available_hypervisor().is_some()
@@ -103,18 +103,23 @@ pub fn is_hypervisor_present() -> bool {
103103
pub(crate) struct TraceInfo {
104104
/// The epoch against which trace events are timed; at least as
105105
/// early as the creation of the sandbox being traced.
106-
#[allow(dead_code)]
107106
pub epoch: std::time::Instant,
108107
/// The frequency of the timestamp counter.
109-
#[allow(dead_code)]
110-
pub tsc_freq: u64,
108+
pub tsc_freq: Option<u64>,
111109
/// The epoch at which the guest started, if it has started.
112110
/// This is used to calculate the time spent in the guest relative to the
113-
/// time of the host.
114-
#[allow(dead_code)]
111+
/// time when the host started.
115112
pub guest_start_epoch: Option<std::time::Instant>,
116-
/// The start guest time, in TSC cycles, for the current guest.
117-
#[allow(dead_code)]
113+
/// The start guest time, in TSC cycles, for the current guest has a double purpose.
114+
/// This field is used in two ways:
115+
/// 1. It contains the TSC value recorded on the host when the guest started.
116+
/// This is used to calculate the TSC frequency which is the same on the host and guest.
117+
/// The TSC frequency is used to convert TSC values to timestamps in the trace.
118+
/// **NOTE**: This is only used until the TSC frequency is calculated, when the first
119+
/// records are received.
120+
/// 2. To store the TSC value at recorded on the guest when the guest started (first record
121+
/// received)
122+
/// This is used to calculate the records timestamps relative to when guest started.
118123
pub guest_start_tsc: Option<u64>,
119124
/// The file to which the trace is being written
120125
#[allow(dead_code)]
@@ -139,8 +144,17 @@ impl TraceInfo {
139144
) -> crate::Result<Self> {
140145
let mut path = std::env::current_dir()?;
141146
path.push("trace");
147+
148+
// create directory if it does not exist
149+
if !path.exists() {
150+
std::fs::create_dir(&path)?;
151+
}
142152
path.push(uuid::Uuid::new_v4().to_string());
143153
path.set_extension("trace");
154+
155+
log::info!("Creating trace file at: {}", path.display());
156+
println!("Creating trace file at: {}", path.display());
157+
144158
#[cfg(feature = "unwind_guest")]
145159
let hash = unwind_module.hash();
146160
#[cfg(feature = "unwind_guest")]
@@ -150,11 +164,17 @@ impl TraceInfo {
150164
let cache = framehop::x86_64::CacheX86_64::new();
151165
(unwinder, Arc::new(Mutex::new(cache)))
152166
};
153-
let tsc_freq = Self::calculate_tsc_freq()?;
167+
if !hyperlight_guest_tracing::invariant_tsc::has_invariant_tsc() {
168+
// If the platform does not support invariant TSC, warn the user.
169+
// On Azure nested virtualization, the TSC invariant bit is not correctly reported, this is a known issue.
170+
log::warn!(
171+
"Invariant TSC is not supported on this platform, trace timestamps may be inaccurate"
172+
);
173+
}
154174

155175
let ret = Self {
156176
epoch: std::time::Instant::now(),
157-
tsc_freq,
177+
tsc_freq: None,
158178
guest_start_epoch: None,
159179
guest_start_tsc: None,
160180
file: Arc::new(Mutex::new(std::fs::File::create_new(path)?)),
@@ -173,22 +193,40 @@ impl TraceInfo {
173193
Ok(ret)
174194
}
175195

176-
/// Calculate the TSC frequency based on the RDTSC instruction.
177-
fn calculate_tsc_freq() -> crate::Result<u64> {
178-
if !hyperlight_guest_tracing::invariant_tsc::has_invariant_tsc() {
179-
return Err(crate::new_error!(
180-
"Invariant TSC is not supported on this platform"
181-
));
182-
}
183-
let start = hyperlight_guest_tracing::invariant_tsc::read_tsc();
184-
let start_time = std::time::Instant::now();
185-
// Sleep for 1 second to get a good sample
186-
std::thread::sleep(std::time::Duration::from_secs(1));
187-
let end = hyperlight_guest_tracing::invariant_tsc::read_tsc();
196+
/// Calculate the TSC frequency based on the RDTSC instruction on the host.
197+
fn calculate_tsc_freq(&mut self) -> crate::Result<()> {
198+
let (start, start_time) = match (
199+
self.guest_start_tsc.as_ref(),
200+
self.guest_start_epoch.as_ref(),
201+
) {
202+
(Some(start), Some(start_time)) => (*start, *start_time),
203+
_ => {
204+
// If the guest start TSC and time are not set, we use the current time and TSC.
205+
// This is not ideal, but it allows us to calculate the TSC frequency without
206+
// failing.
207+
// This is a fallback mechanism to ensure that we can still calculate, however it
208+
// should be noted that this may lead to inaccuracies in the TSC frequency.
209+
// The start time should be already set before running the guest for each sandbox.
210+
log::error!(
211+
"Guest start TSC and time are not set. Calculating TSC frequency will use current time and TSC."
212+
);
213+
(
214+
hyperlight_guest_tracing::invariant_tsc::read_tsc(),
215+
std::time::Instant::now(),
216+
)
217+
}
218+
};
219+
188220
let end_time = std::time::Instant::now();
221+
let end = hyperlight_guest_tracing::invariant_tsc::read_tsc();
222+
189223
let elapsed = end_time.duration_since(start_time).as_secs_f64();
224+
let tsc_freq = ((end - start) as f64 / elapsed) as u64;
225+
226+
log::info!("Calculated TSC frequency: {} Hz", tsc_freq);
227+
self.tsc_freq = Some(tsc_freq);
190228

191-
Ok(((end - start) as f64 / elapsed) as u64)
229+
Ok(())
192230
}
193231
}
194232

src/hyperlight_host/src/sandbox/outb.rs

Lines changed: 24 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -232,8 +232,13 @@ pub(super) fn record_guest_trace_frame<F: FnOnce(&mut std::fs::File)>(
232232
.guest_start_tsc
233233
.as_ref()
234234
.map_or_else(|| 0, |c| *c);
235+
235236
// Convert cycles to microseconds based on the TSC frequency
236-
let micros = cycles_spent as f64 / trace_info.tsc_freq as f64 * 1_000_000f64;
237+
let tsc_freq = trace_info
238+
.tsc_freq
239+
.as_ref()
240+
.ok_or_else(|| new_error!("TSC frequency not set in TraceInfo"))?;
241+
let micros = cycles_spent as f64 / *tsc_freq as f64 * 1_000_000f64;
237242

238243
// Convert to a Duration
239244
let guest_duration = std::time::Duration::from_micros(micros as u64);
@@ -353,7 +358,6 @@ fn handle_outb_impl(
353358
.as_ref()
354359
.shared_mem
355360
.copy_to_slice(buffer, ptr as usize - SandboxMemoryLayout::BASE_ADDRESS)
356-
// .read::<u64>((addr - SandboxMemoryLayout::BASE_ADDRESS as u64) as usize)
357361
.map_err(|e| {
358362
new_error!(
359363
"Failed to copy trace records from guest memory to host: {:?}",
@@ -367,11 +371,24 @@ fn handle_outb_impl(
367371

368372
{
369373
let trace_info = _hv.trace_info_as_mut();
370-
// Store the start guest cycles if not already set
371-
// This is the `entrypoint` of the guest execution
372-
// This should be set only once, at the start of the guest execution
373-
if trace_info.guest_start_tsc.is_none() && !traces.is_empty() {
374-
trace_info.guest_start_tsc = Some(traces[0].cycles);
374+
375+
// Calculate the TSC frequency based on the current TSC reading
376+
// This is done only once, when the first trace record is received
377+
// Ideally, we should use a timer or a clock to measure the time elapsed,
378+
// but that adds delays.
379+
// To avoid that we store the TSC value and a timestamp right
380+
// before starting the guest execution and then calculate the TSC frequency when
381+
// the first trace record is received, based on the current TSC value and clock.
382+
if trace_info.tsc_freq.is_none() {
383+
trace_info.calculate_tsc_freq()?;
384+
385+
// After the TSC frequency is calculated, we no longer need the value of TSC
386+
// recorded on the host when the guest started, so we can set the guest_start_tsc field
387+
// to store the TSC value recorded on the guest when the guest started executing.
388+
// This is used to calculate the records timestamps relative to the first trace record.
389+
if !traces.is_empty() {
390+
trace_info.guest_start_tsc = Some(traces[0].cycles);
391+
}
375392
}
376393
}
377394

0 commit comments

Comments
 (0)