From b35e6f3018024c476f66e527ccfbdc4800ba59e2 Mon Sep 17 00:00:00 2001 From: Rob Bradford Date: Tue, 21 Jun 2022 15:01:26 +0100 Subject: [PATCH] tracing: Tracing infrastructure Add a new feature "tracing" that enables tracing functionality via the "tracer" crate (sadly features and crates cannot share the same name.) Setup: tracer::start() The main functionality is a tracer::trace_scope()! macro that will add trace points for the duration of the scope. Tracing events are per thread. Finish: tracer::end() this will write the trace file (pretty printed JSON) to a file in the current directory. Signed-off-by: Rob Bradford --- Cargo.lock | 13 +++ Cargo.toml | 3 + tracer/Cargo.toml | 15 ++++ tracer/src/lib.rs | 18 ++++ tracer/src/tracer.rs | 170 ++++++++++++++++++++++++++++++++++++++ tracer/src/tracer_noop.rs | 17 ++++ vmm/Cargo.toml | 2 + 7 files changed, 238 insertions(+) create mode 100644 tracer/Cargo.toml create mode 100644 tracer/src/lib.rs create mode 100644 tracer/src/tracer.rs create mode 100644 tracer/src/tracer_noop.rs diff --git a/Cargo.lock b/Cargo.lock index 63da12bed..c1fdabe70 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -175,6 +175,7 @@ dependencies = [ "signal-hook", "test_infra", "thiserror", + "tracer", "vm-memory", "vmm", "vmm-sys-util", @@ -1197,6 +1198,17 @@ dependencies = [ "syn", ] +[[package]] +name = "tracer" +version = "0.1.0" +dependencies = [ + "libc", + "log", + "once_cell", + "serde", + "serde_json", +] + [[package]] name = "unicode-ident" version = "1.0.4" @@ -1516,6 +1528,7 @@ dependencies = [ "serial_buffer", "signal-hook", "thiserror", + "tracer", "uuid", "versionize", "versionize_derive", diff --git a/Cargo.toml b/Cargo.toml index 3d7a582e8..e8c6b9b10 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -31,6 +31,7 @@ seccompiler = "0.3.0" serde_json = "1.0.85" signal-hook = "0.3.14" thiserror = "1.0.35" +tracer = { path = "tracer" } vmm = { path = "vmm" } vmm-sys-util = "0.10.0" vm-memory = "0.9.0" @@ -62,6 +63,7 @@ guest_debug = ["vmm/guest_debug"] kvm = ["vmm/kvm"] mshv = ["vmm/mshv"] tdx = ["vmm/tdx"] +tracing = ["vmm/tracing", "tracer/tracing"] [workspace] members = [ @@ -81,6 +83,7 @@ members = [ "rate_limiter", "serial_buffer", "test_infra", + "tracer", "vfio_user", "vhdx", "vhost_user_block", diff --git a/tracer/Cargo.toml b/tracer/Cargo.toml new file mode 100644 index 000000000..08986e6be --- /dev/null +++ b/tracer/Cargo.toml @@ -0,0 +1,15 @@ +[package] +name = "tracer" +version = "0.1.0" +authors = ["The Cloud Hypervisor Authors"] +edition = "2021" + +[dependencies] +libc = "0.2.126" +log = "0.4.17" +once_cell = "1.12.0" +serde = { version = "1.0.137", features = ["rc", "derive"] } +serde_json = "1.0.81" + +[features] +tracing = [] diff --git a/tracer/src/lib.rs b/tracer/src/lib.rs new file mode 100644 index 000000000..40677cf8b --- /dev/null +++ b/tracer/src/lib.rs @@ -0,0 +1,18 @@ +// Copyright © 2022 Intel Corporation +// +// SPDX-License-Identifier: Apache-2.0 +// + +#[cfg(feature = "tracing")] +#[macro_use] +extern crate log; + +#[cfg(not(feature = "tracing"))] +mod tracer_noop; +#[cfg(not(feature = "tracing"))] +pub use tracer_noop::*; + +#[cfg(feature = "tracing")] +mod tracer; +#[cfg(feature = "tracing")] +pub use tracer::*; diff --git a/tracer/src/tracer.rs b/tracer/src/tracer.rs new file mode 100644 index 000000000..807a51d76 --- /dev/null +++ b/tracer/src/tracer.rs @@ -0,0 +1,170 @@ +// Copyright © 2022 Intel Corporation +// +// SPDX-License-Identifier: Apache-2.0 +// + +use once_cell::unsync::OnceCell; +use serde::Serialize; +use std::collections::HashMap; +use std::fs::File; +use std::io::Write; +use std::sync::atomic::{AtomicU64, Ordering}; +use std::sync::{Arc, Mutex}; +use std::time::{Duration, Instant}; + +#[derive(Debug)] +struct Tracer { + events: Arc>>>, + thread_depths: HashMap>, + start: Instant, +} + +impl Tracer { + fn new() -> Self { + Self { + events: Arc::new(Mutex::new(HashMap::default())), + start: Instant::now(), + thread_depths: HashMap::default(), + } + } + + fn end(&self) { + let end = Instant::now(); + let path = format!("cloud-hypervisor-{}.trace", unsafe { libc::getpid() }); + let mut file = File::create(&path).unwrap(); + + #[derive(Serialize)] + struct TraceReport { + duration: Duration, + events: Arc>>>, + } + + let trace_report = TraceReport { + duration: end.duration_since(self.start), + events: self.events.clone(), + }; + + serde_json::to_writer_pretty(&file, &trace_report).unwrap(); + + file.flush().unwrap(); + + warn!("Trace output: {}", path); + } + + fn add_event(&mut self, event: TraceEvent) { + let thread_name = std::thread::current().name().unwrap_or("").to_string(); + let mut events = self.events.lock().unwrap(); + if let Some(thread_events) = events.get_mut(&thread_name) { + thread_events.push(event); + } else { + events.insert(thread_name.to_string(), vec![event]); + } + } + + fn increase_thread_depth(&mut self) { + let thread_name = std::thread::current().name().unwrap_or("").to_string(); + if let Some(depth) = self.thread_depths.get_mut(&thread_name) { + depth.fetch_add(1, Ordering::SeqCst); + } else { + self.thread_depths + .insert(thread_name, Arc::new(AtomicU64::new(0))); + } + } + + fn decrease_thread_depth(&mut self) { + let thread_name = std::thread::current().name().unwrap_or("").to_string(); + if let Some(depth) = self.thread_depths.get_mut(&thread_name) { + depth.fetch_sub(1, Ordering::SeqCst); + } else { + panic!("Unmatched decreas for thread: {}", thread_name); + } + } + + fn thread_depth(&self) -> u64 { + let thread_name = std::thread::current().name().unwrap_or("").to_string(); + self.thread_depths + .get(&thread_name) + .map(|v| v.load(Ordering::SeqCst)) + .unwrap_or_default() + } +} + +static mut TRACER: OnceCell = OnceCell::new(); + +#[derive(Clone, Debug, Serialize)] +struct TraceEvent { + timestamp: Duration, + event: &'static str, + end_timestamp: Option, + depth: u64, +} + +pub fn trace_point_log(event: &'static str) { + let trace_event = TraceEvent { + timestamp: Instant::now().duration_since(unsafe { TRACER.get().unwrap().start }), + event, + end_timestamp: None, + depth: unsafe { TRACER.get().unwrap().thread_depth() }, + }; + unsafe { + TRACER.get_mut().unwrap().add_event(trace_event); + } +} + +pub struct TraceBlock { + start: Instant, + event: &'static str, +} + +impl TraceBlock { + pub fn new(event: &'static str) -> Self { + unsafe { + TRACER.get_mut().unwrap().increase_thread_depth(); + } + Self { + start: Instant::now(), + event, + } + } +} + +impl Drop for TraceBlock { + fn drop(&mut self) { + let trace_event = TraceEvent { + timestamp: self + .start + .duration_since(unsafe { TRACER.get().unwrap().start }), + event: self.event, + end_timestamp: Some( + Instant::now().duration_since(unsafe { TRACER.get().unwrap().start }), + ), + depth: unsafe { TRACER.get().unwrap().thread_depth() }, + }; + unsafe { + TRACER.get_mut().unwrap().add_event(trace_event); + TRACER.get_mut().unwrap().decrease_thread_depth(); + } + } +} + +#[macro_export] +macro_rules! trace_point { + ($event:expr) => { + $crate::trace_point_log($event) + }; +} + +#[macro_export] +macro_rules! trace_scoped { + ($event:expr) => { + let _trace_scoped = $crate::TraceBlock::new($event); + }; +} + +pub fn end() { + unsafe { TRACER.get().unwrap().end() } +} + +pub fn start() { + unsafe { TRACER.set(Tracer::new()).unwrap() } +} diff --git a/tracer/src/tracer_noop.rs b/tracer/src/tracer_noop.rs new file mode 100644 index 000000000..8cffbcb92 --- /dev/null +++ b/tracer/src/tracer_noop.rs @@ -0,0 +1,17 @@ +// Copyright © 2022 Intel Corporation +// +// SPDX-License-Identifier: Apache-2.0 +// + +#[macro_export] +macro_rules! trace_scoped { + ($event:expr) => {}; +} + +#[macro_export] +macro_rules! trace_point { + ($event:expr) => {}; +} + +pub fn end() {} +pub fn start() {} diff --git a/vmm/Cargo.toml b/vmm/Cargo.toml index 4741194c5..225a416bd 100644 --- a/vmm/Cargo.toml +++ b/vmm/Cargo.toml @@ -12,6 +12,7 @@ guest_debug = ["kvm"] kvm = ["hypervisor/kvm", "vfio-ioctls/kvm", "vm-device/kvm", "pci/kvm"] mshv = ["hypervisor/mshv", "vfio-ioctls/mshv", "vm-device/mshv", "pci/mshv"] tdx = ["arch/tdx", "hypervisor/tdx"] +tracing = ["tracer/tracing"] [dependencies] acpi_tables = { path = "../acpi_tables" } @@ -42,6 +43,7 @@ serde_json = "1.0.85" serial_buffer = { path = "../serial_buffer" } signal-hook = "0.3.14" thiserror = "1.0.35" +tracer = { path = "../tracer" } uuid = "1.1.2" versionize = "0.1.6" versionize_derive = "0.1.4"