feat: Add instrumentation profiler

Adds `tracing_flame` as code instrumentation based profiler that can
be used to profile Firecracker.

Signed-off-by: Jonathan Woollett-Light <[email protected]>

Author: Jonathan Woollett-Light

Cargo.lock

@@ -43,6 +43,7 @@ mod tests {
             show_level: Some(false),
             show_log_origin: Some(false),
             filter: None,
+            profile_path: None,
         };
         match vmm_action_from_request(parse_put_logger(&Body::new(body)).unwrap()) {
             VmmAction::ConfigureLogger(cfg) => assert_eq!(cfg, expected_cfg),
@@ -62,6 +63,7 @@ mod tests {
             show_level: Some(false),
             show_log_origin: Some(false),
             filter: None,
+            profile_path: None,
         };
         match vmm_action_from_request(parse_put_logger(&Body::new(body)).unwrap()) {
             VmmAction::ConfigureLogger(cfg) => assert_eq!(cfg, expected_cfg),

src/api_server/src/request/logger.rs

@@ -117,7 +117,7 @@ fn run(cli: Cli) -> Result<(), HelperError> {
         Command::Template(op) => match op {
             TemplateOperation::Dump { config, output } => {
                 let config = read_to_string(config)?;
-                let (vmm, _) = utils::build_microvm_from_config(&config)?;
+                let ((vmm, _), _flame_guard) = utils::build_microvm_from_config(&config)?;
 
                 let cpu_config = template::dump::dump(vmm)?;
 
@@ -142,7 +142,8 @@ fn run(cli: Cli) -> Result<(), HelperError> {
             }
             TemplateOperation::Verify { config } => {
                 let config = read_to_string(config)?;
-                let (vmm, vm_resources) = utils::build_microvm_from_config(&config)?;
+                let ((vmm, vm_resources), _flame_guard) =
+                    utils::build_microvm_from_config(&config)?;
 
                 let cpu_template = vm_resources
                     .vm_config
@@ -157,7 +158,7 @@ fn run(cli: Cli) -> Result<(), HelperError> {
         Command::Fingerprint(op) => match op {
             FingerprintOperation::Dump { config, output } => {
                 let config = read_to_string(config)?;
-                let (vmm, _) = utils::build_microvm_from_config(&config)?;
+                let ((vmm, _), _flame_guard) = utils::build_microvm_from_config(&config)?;
 
                 let fingerprint = fingerprint::dump::dump(vmm)?;
 

src/cpu-template-helper/src/main.rs

@@ -47,7 +47,7 @@ mod tests {
         let tmp_file = TempFile::new().unwrap();
         let valid_config =
             generate_config(&kernel_image_path, tmp_file.as_path().to_str().unwrap());
-        let (vmm, _) = build_microvm_from_config(&valid_config).unwrap();
+        let ((vmm, _), _flame_guard) = build_microvm_from_config(&valid_config).unwrap();
 
         assert!(dump(vmm).is_ok());
     }

src/cpu-template-helper/src/template/dump/mod.rs

@@ -69,19 +69,27 @@ pub enum UtilsError {
     BuildMicroVm(#[from] StartMicrovmError),
 }
 
+#[allow(clippy::type_complexity)]
 #[tracing::instrument(level = "trace", skip(config))]
 pub fn build_microvm_from_config(
     config: &str,
-) -> Result<(Arc<Mutex<Vmm>>, VmResources), UtilsError> {
+) -> Result<
+    (
+        (Arc<Mutex<Vmm>>, VmResources),
+        Option<vmm::vmm_config::logger::FlameGuard>,
+    ),
+    UtilsError,
+> {
     // Prepare resources from the given config file.
     let instance_info = InstanceInfo {
         id: "anonymous-instance".to_string(),
         state: VmState::NotStarted,
         vmm_version: CPU_TEMPLATE_HELPER_VERSION.to_string(),
         app_name: "cpu-template-helper".to_string(),
     };
-    let vm_resources = VmResources::from_json(config, &instance_info, HTTP_MAX_PAYLOAD_SIZE, None)
-        .map_err(UtilsError::CreateVmResources)?;
+    let (vm_resources, flame_guard) =
+        VmResources::from_json(config, &instance_info, HTTP_MAX_PAYLOAD_SIZE, None)
+            .map_err(UtilsError::CreateVmResources)?;
     let mut event_manager = EventManager::new().unwrap();
     let seccomp_filters = get_empty_filters();
 
@@ -93,7 +101,7 @@ pub fn build_microvm_from_config(
         &seccomp_filters,
     )?;
 
-    Ok((vmm, vm_resources))
+    Ok(((vmm, vm_resources), flame_guard))
 }
 
 #[tracing::instrument(level = "trace", skip(path, suffix))]

src/cpu-template-helper/src/utils/mod.rs

@@ -301,7 +301,7 @@ fn main_exec() -> Result<(), MainError> {
     };
 
     // Configure logger, the logger handles can be used to re-configure the logger with the API.
-    let logger_handles = {
+    let (logger_handles, _flame_guard) = {
         let level_res = arguments
             .single_value("level")
             .map(|s| LevelFilter::from_str(s))
@@ -319,6 +319,7 @@ fn main_exec() -> Result<(), MainError> {
             show_level: Some(arguments.flag_present("show-level")),
             show_log_origin: Some(arguments.flag_present("show-log-origin")),
             filter,
+            profile_path: None,
         };
         logger_config
             .init()
@@ -541,7 +542,7 @@ fn build_microvm_from_json(
     mmds_size_limit: usize,
     metadata_json: Option<&str>,
 ) -> Result<(VmResources, Arc<Mutex<vmm::Vmm>>), BuildFromJsonError> {
-    let mut vm_resources =
+    let (mut vm_resources, _flame_guard) =
         VmResources::from_json(&config_json, &instance_info, mmds_size_limit, metadata_json)
             .map_err(BuildFromJsonError::ParseFromJson)?;
     vm_resources.boot_timer = boot_timer_enabled;
@@ -617,7 +618,7 @@ fn run_without_api(
             .expect("Failed to start the event manager");
 
         if let Some(exit_code) = vmm.lock().unwrap().shutdown_exit_code() {
-            return Err(RunWithoutApiError::Shutdown(exit_code));
+            break Err(RunWithoutApiError::Shutdown(exit_code));
         }
     }
 }

src/firecracker/src/main.rs

@@ -31,6 +31,7 @@ vm-fdt = "0.2.0"
 vm-superio = "0.7.0"
 tracing = { version = "0.1.37", features = ["max_level_debug"] }
 tracing-subscriber = "0.3.17"
+tracing-flame = "0.2.0"
 log = { version = "0.4.17", features = ["serde"] }
 
 dumbo = { path = "../dumbo" }

src/vmm/Cargo.toml

@@ -138,12 +138,15 @@ impl VmResources {
         instance_info: &InstanceInfo,
         mmds_size_limit: usize,
         metadata_json: Option<&str>,
-    ) -> Result<Self, ResourcesError> {
+    ) -> Result<(Self, Option<crate::vmm_config::logger::FlameGuard>), ResourcesError> {
         let vmm_config = serde_json::from_str::<VmmConfig>(config_json)?;
 
-        if let Some(logger) = vmm_config.logger {
-            logger.init()?;
-        }
+        let flame_guard = if let Some(logger) = vmm_config.logger {
+            let (_logger_handles, flame_guard) = logger.init()?;
+            flame_guard
+        } else {
+            None
+        };
 
         if let Some(metrics) = vmm_config.metrics {
             init_metrics(metrics)?;
@@ -199,7 +202,7 @@ impl VmResources {
             resources.build_entropy_device(entropy_device_config)?;
         }
 
-        Ok(resources)
+        Ok((resources, flame_guard))
     }
 
     #[tracing::instrument(level = "trace", skip(self))]
@@ -1058,7 +1061,7 @@ mod tests {
             kernel_file.as_path().to_str().unwrap(),
             rootfs_file.as_path().to_str().unwrap(),
         );
-        let resources = VmResources::from_json(
+        let (resources, _flame_guard) = VmResources::from_json(
             json.as_str(),
             &default_instance_info,
             1200,
@@ -1146,7 +1149,7 @@ mod tests {
             rootfs_file.as_path().to_str().unwrap(),
         );
 
-        let vm_resources = VmResources::from_json(
+        let (vm_resources, _flame_guard) = VmResources::from_json(
             json.as_str(),
             &default_instance_info,
             HTTP_MAX_PAYLOAD_SIZE,
@@ -1206,7 +1209,7 @@ mod tests {
             );
 
             {
-                let resources = VmResources::from_json(
+                let (resources, _flame_guard) = VmResources::from_json(
                     json.as_str(),
                     &InstanceInfo::default(),
                     HTTP_MAX_PAYLOAD_SIZE,
@@ -1221,7 +1224,7 @@ mod tests {
 
             {
                 // In this case the mmds data store will be initialised but the config still None.
-                let resources = VmResources::from_json(
+                let (resources, _flame_guard) = VmResources::from_json(
                     json.as_str(),
                     &InstanceInfo::default(),
                     HTTP_MAX_PAYLOAD_SIZE,
@@ -1281,7 +1284,7 @@ mod tests {
                 kernel_file.as_path().to_str().unwrap(),
                 rootfs_file.as_path().to_str().unwrap(),
             );
-            let resources = VmResources::from_json(
+            let (resources, _flame_guard) = VmResources::from_json(
                 json.as_str(),
                 &InstanceInfo::default(),
                 HTTP_MAX_PAYLOAD_SIZE,
@@ -1340,7 +1343,7 @@ mod tests {
                 kernel_file.as_path().to_str().unwrap(),
                 rootfs_file.as_path().to_str().unwrap(),
             );
-            let resources = VmResources::from_json(
+            let (resources, _flame_guard) = VmResources::from_json(
                 json.as_str(),
                 &InstanceInfo::default(),
                 HTTP_MAX_PAYLOAD_SIZE,

src/vmm/src/resources.rs

@@ -3,8 +3,10 @@
 
 use std::convert::From;
 use std::fmt;
-use std::io::LineWriter;
+use std::fs::OpenOptions;
+use std::io::{BufWriter, LineWriter};
 use std::os::unix::fs::OpenOptionsExt;
+use std::path::PathBuf;
 use std::str::FromStr;
 use std::sync::atomic::AtomicBool;
 use std::sync::atomic::Ordering::SeqCst;
@@ -107,7 +109,7 @@ impl FromStr for LevelFilter {
 #[serde(deny_unknown_fields)]
 pub struct LoggerConfig {
     /// Named pipe or file used as output for logs.
-    pub log_path: Option<std::path::PathBuf>,
+    pub log_path: Option<PathBuf>,
     // TODO Deprecate this API argument.
     /// The level of the Logger.
     pub level: Option<LevelFilter>,
@@ -117,6 +119,8 @@ pub struct LoggerConfig {
     pub show_log_origin: Option<bool>,
     /// Filter components. If this is `Some` it overrides `self.level`.
     pub filter: Option<FilterArgs>,
+    /// Named pipe or file used as output for profile.
+    pub profile_path: Option<PathBuf>,
 }
 
 /// Error type for [`LoggerConfig::init`].
@@ -186,17 +190,24 @@ type FmtHandle<F, G> = tracing_subscriber::reload::Handle<
     >,
 >;
 
+/// An alias for the specific [`tracing_flame::FlushGuard`] used to flush the
+/// [`tracing_flame::FlameLayer`].
+pub type FlameGuard = tracing_flame::FlushGuard<BufWriter<std::fs::File>>;
+
 impl LoggerConfig {
     /// Initializes the logger.
     ///
     /// Returns handles that can be used to dynamically re-configure the logger.
     pub fn init(
         self,
     ) -> Result<
-        LoggerHandles<
-            impl Fn(&tracing::Metadata<'_>) -> bool,
-            impl Fn(&tracing::Metadata<'_>) -> bool,
-        >,
+        (
+            LoggerHandles<
+                impl Fn(&tracing::Metadata<'_>) -> bool,
+                impl Fn(&tracing::Metadata<'_>) -> bool,
+            >,
+            Option<FlameGuard>,
+        ),
         InitLoggerError,
     > {
         // Update default filter to match passed arguments.
@@ -243,7 +254,7 @@ impl LoggerConfig {
                     // consuming the message that is flushed to the two pipes, we are opening it
                     // with `O_NONBLOCK` flag. In this case, writing to a pipe will start failing
                     // when reaching 64K of unconsumed content.
-                    let file = std::fs::OpenOptions::new()
+                    let file = OpenOptions::new()
                         .custom_flags(libc::O_NONBLOCK)
                         .read(true)
                         .write(true)
@@ -264,19 +275,37 @@ impl LoggerConfig {
             ReloadLayer::new(fmt_subscriber)
         };
 
-        Registry::default()
-            .with(filter)
-            .with(fmt)
-            .try_init()
-            .map_err(InitLoggerError::Init)?;
+        // Setup flame layer
+        let flame_guard = if let Some(profile_path) = self.profile_path {
+            let writer = OpenOptions::new().write(true).open(profile_path).unwrap();
+            let buffer = BufWriter::new(writer);
+            let flame_layer = tracing_flame::FlameLayer::new(buffer);
+            let guard = flame_layer.flush_on_drop();
+
+            Registry::default()
+                .with(filter)
+                .with(fmt)
+                .with(flame_layer)
+                .try_init()
+                .map_err(InitLoggerError::Init)?;
+
+            Some(guard)
+        } else {
+            Registry::default()
+                .with(filter)
+                .with(fmt)
+                .try_init()
+                .map_err(InitLoggerError::Init)?;
+            None
+        };
 
         tracing::error!("Error level logs enabled.");
         tracing::warn!("Warn level logs enabled.");
         tracing::info!("Info level logs enabled.");
         tracing::debug!("Debug level logs enabled.");
         tracing::trace!("Trace level logs enabled.");
 
-        Ok(LoggerHandles { fmt: fmt_handle })
+        Ok((LoggerHandles { fmt: fmt_handle }, flame_guard))
     }
     /// Updates the logger using the given handles.
     pub fn update(
@@ -292,7 +321,7 @@ impl LoggerConfig {
             // message that is flushed to the two pipes, we are opening it with `O_NONBLOCK` flag.
             // In this case, writing to a pipe will start failing when reaching 64K of unconsumed
             // content.
-            let file = std::fs::OpenOptions::new()
+            let file = OpenOptions::new()
                 .custom_flags(libc::O_NONBLOCK)
                 .read(true)
                 .write(true)