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 <robert.bradford@intel.com>

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",

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",

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 = []

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::*;

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<Mutex<HashMap<String, Vec<TraceEvent>>>>,
+    thread_depths: HashMap<String, Arc<AtomicU64>>,
+    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<Mutex<HashMap<String, Vec<TraceEvent>>>>,
+        }
+
+        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<Tracer> = OnceCell::new();
+
+#[derive(Clone, Debug, Serialize)]
+struct TraceEvent {
+    timestamp: Duration,
+    event: &'static str,
+    end_timestamp: Option<Duration>,
+    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() }
+}

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() {}

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"