process startup time in CPU and wall clock micros

Signed-off-by: Alexandra Iordache <[email protected]>

Author: Alexandra Iordache

api_server/src/lib.rs

@@ -78,7 +78,8 @@ impl ApiServer {
     pub fn bind_and_run<P: AsRef<Path>>(
         &self,
         path_or_fd: UnixDomainSocket<P>,
-        jailer_start_time_ms: Option<u64>,
+        start_time_us: Option<u64>,
+        start_time_cpu_us: Option<u64>,
     ) -> Result<()> {
         let mut core = Core::new().map_err(Error::Io)?;
         let handle = Rc::new(core.handle());
@@ -95,12 +96,20 @@ impl ApiServer {
             }
         };
 
-        if let Some(start_time_ms) = jailer_start_time_ms {
-            let delta = (chrono::Utc::now().timestamp_millis() as u64) - start_time_ms;
+        if let Some(start_time) = start_time_us {
+            let delta_us = (chrono::Utc::now().timestamp_nanos() / 1000) as u64 - start_time;
             METRICS
                 .api_server
-                .process_startup_time_ms
-                .add(delta as usize);
+                .process_startup_time_us
+                .add(delta_us as usize);
+        }
+
+        if let Some(cpu_start_time) = start_time_cpu_us {
+            let delta_us = fc_util::now_cputime_us() - cpu_start_time;
+            METRICS
+                .api_server
+                .process_startup_time_cpu_us
+                .add(delta_us as usize);
         }
 
         let http: Http<hyper::Chunk> = Http::new();

data_model/src/lib.rs

@@ -17,5 +17,6 @@ pub struct FirecrackerContext {
     pub id: String,
     pub jailed: bool,
     pub seccomp_level: u32,
-    pub start_time_ms: u64,
+    pub start_time_us: u64,
+    pub start_time_cpu_us: u64,
 }

jailer/src/env.rs

@@ -43,11 +43,12 @@ pub struct Env {
     netns: Option<String>,
     daemonize: bool,
     seccomp_level: u32,
-    start_time_ms: u64,
+    start_time_us: u64,
+    start_time_cpu_us: u64,
 }
 
 impl Env {
-    pub fn new(args: ArgMatches, start_time_ms: u64) -> Result<Self> {
+    pub fn new(args: ArgMatches, start_time_us: u64, start_time_cpu_us: u64) -> Result<Self> {
         // All arguments are either mandatory, or have default values, so the unwraps
         // should not fail.
         let id = args.value_of("id").unwrap();
@@ -117,7 +118,8 @@ impl Env {
             netns,
             daemonize,
             seccomp_level,
-            start_time_ms,
+            start_time_us,
+            start_time_cpu_us,
         })
     }
 
@@ -271,7 +273,8 @@ impl Env {
             id: self.id.clone(),
             jailed: true,
             seccomp_level: self.seccomp_level,
-            start_time_ms: self.start_time_ms,
+            start_time_us: self.start_time_us,
+            start_time_cpu_us: self.start_time_cpu_us,
         };
 
         Err(Error::Exec(
@@ -358,6 +361,7 @@ mod tests {
                 true,
             ),
             0,
+            0,
         ).expect("This new environment should be created successfully.");
 
         let mut chroot_dir = PathBuf::from(chroot_base);
@@ -374,14 +378,16 @@ mod tests {
         let another_good_env = Env::new(
             make_args(node, id, exec_file, uid, gid, chroot_base, None, false),
             0,
+            0,
         ).expect("This another new environment should be created successfully.");
         assert!(!another_good_env.daemonize);
 
         // Not fine - invalid node.
         assert!(
             Env::new(
                 make_args("zzz", id, exec_file, uid, gid, chroot_base, None, true),
-                0
+                0,
+                0,
             ).is_err()
         );
 
@@ -398,6 +404,7 @@ mod tests {
                     None,
                     true
                 ),
+                0,
                 0
             ).is_err()
         );
@@ -415,6 +422,7 @@ mod tests {
                     None,
                     true
                 ),
+                0,
                 0
             ).is_err()
         );
@@ -423,6 +431,7 @@ mod tests {
         assert!(
             Env::new(
                 make_args(node, id, exec_file, "zzz", gid, chroot_base, None, true),
+                0,
                 0
             ).is_err()
         );
@@ -431,6 +440,7 @@ mod tests {
         assert!(
             Env::new(
                 make_args(node, id, exec_file, uid, "zzz", chroot_base, None, true),
+                0,
                 0
             ).is_err()
         );

jailer/src/lib.rs

@@ -190,7 +190,7 @@ fn open_dev_kvm() -> Result<i32> {
     Ok(ret)
 }
 
-pub fn run(args: ArgMatches, start_time_ms: u64) -> Result<()> {
+pub fn run(args: ArgMatches, start_time_us: u64, start_time_cpu_us: u64) -> Result<()> {
     // We open /dev/kvm and create the listening socket. These file descriptors will be
     // passed on to Firecracker post exec, and used via knowing their values in advance.
 
@@ -200,7 +200,7 @@ pub fn run(args: ArgMatches, start_time_ms: u64) -> Result<()> {
     sanitize_process();
     open_dev_kvm()?;
 
-    let env = Env::new(args, start_time_ms)?;
+    let env = Env::new(args, start_time_us, start_time_cpu_us)?;
 
     // Ensure the folder exists.
     fs::create_dir_all(env.chroot_dir())

logger/src/metrics.rs

@@ -117,7 +117,8 @@ impl Serialize for SharedMetric {
 #[derive(Default, Serialize)]
 pub struct ApiServerMetrics {
     pub instance_info_fails: SharedMetric,
-    pub process_startup_time_ms: SharedMetric,
+    pub process_startup_time_us: SharedMetric,
+    pub process_startup_time_cpu_us: SharedMetric,
     pub sync_outcome_fails: SharedMetric,
     pub sync_vmm_send_timeout_count: SharedMetric,
 }

src/bin/jailer.rs

@@ -1,11 +1,13 @@
 extern crate chrono;
 extern crate clap;
 
+extern crate fc_util;
 extern crate jailer;
 
 fn main() -> jailer::Result<()> {
     jailer::run(
         jailer::clap_app().get_matches(),
-        chrono::Utc::now().timestamp_millis() as u64,
+        (chrono::Utc::now().timestamp_nanos() / 1000) as u64,
+        fc_util::now_cputime_us(),
     )
 }

src/main.rs

@@ -74,16 +74,17 @@ fn main() {
 
     let mut instance_id = String::from(DEFAULT_INSTANCE_ID);
     let mut seccomp_level = 0;
-    let mut start_time_ms = None;
-
+    let mut start_time_us = None;
+    let mut start_time_cpu_us = None;
     let mut is_jailed = false;
 
     if let Some(s) = cmd_arguments.value_of("context") {
         let context = serde_json::from_str::<FirecrackerContext>(s).unwrap();
         is_jailed = context.jailed;
         instance_id = context.id;
         seccomp_level = context.seccomp_level;
-        start_time_ms = Some(context.start_time_ms);
+        start_time_us = Some(context.start_time_us);
+        start_time_cpu_us = Some(context.start_time_cpu_us);
     }
 
     let shared_info = Arc::new(RwLock::new(InstanceInfo {
@@ -113,7 +114,9 @@ fn main() {
         UnixDomainSocket::Path(bind_path)
     };
 
-    server.bind_and_run(uds_path_or_fd, start_time_ms).unwrap();
+    server
+        .bind_and_run(uds_path_or_fd, start_time_us, start_time_cpu_us)
+        .unwrap();
 }
 
 #[cfg(test)]

tests/integration_tests/performance/test_process_startup_time.py

@@ -8,8 +8,8 @@
 
 import host_tools.logging as log_tools
 
-MAX_STARTUP_TIME_US = 80
-""" The maximum acceptable startup time in ms. """
+MAX_STARTUP_TIME_CPU_US = 8000
+""" The maximum acceptable startup time in CPU us. """
 # TODO: Keep a `current` startup time in S3 and validate we don't regress
 
 
@@ -44,9 +44,11 @@ def test_startup_time(test_microvm_with_api):
     # Since metrics are flushed at InstanceStart, the first line will suffice.
     lines = log_tools.sequential_fifo_reader(metrics_fifo_path, 1)
     metrics = json.loads(lines[0])
-    startup_time = int(metrics['api_server']['process_startup_time_ms'])
+    startup_time_us = metrics['api_server']['process_startup_time_us']
+    cpu_startup_time_us = metrics['api_server']['process_startup_time_cpu_us']
 
-    print('Process startup time is: {} ms'.format(startup_time))
+    print('Process startup time is: {} us ({} CPU us)'
+          .format(startup_time_us, cpu_startup_time_us))
 
-    assert startup_time > 0
-    assert startup_time <= MAX_STARTUP_TIME_US
+    assert cpu_startup_time_us > 0
+    assert cpu_startup_time_us <= MAX_STARTUP_TIME_CPU_US