Add build timing capture from cargo's --timings JSON output

Introduces a timings module with a visitor pattern for optionally
intercepting cargo timing-info messages during builds. Timings are
captured only when capture_timings is enabled in config, the toolchain
is nightly/CI, and running in local/CLI mode (not agent mode).

Author: oriongonza

src/agent/mod.rs

@@ -177,6 +177,7 @@ fn run_experiment(
         threads_count,
         &agent.config,
         &|| agent.next_crate(&ex.name),
+        true,
     )
     .map_err(|err| (Some(Box::new(ex)), err))?;
     Ok(())

src/cli.rs

@@ -441,6 +441,7 @@ impl Crater {
                         threads,
                         &config,
                         &|| Ok(crates.lock().unwrap().pop()),
+                        false,
                     );
                     workspace.purge_all_build_dirs()?;
                     res?;

src/config.rs

@@ -86,6 +86,8 @@ pub struct Config {
     pub local_crates: HashMap<String, CrateConfig>,
     pub server: ServerConfig,
     pub sandbox: SandboxConfig,
+    #[serde(default = "default_false")]
+    pub capture_timings: bool,
 }
 
 impl Config {
@@ -253,6 +255,7 @@ impl Default for Config {
                     experiment_completed: "".into(),
                 },
             },
+            capture_timings: false,
         }
     }
 }

src/db/migrations.rs

@@ -363,6 +363,27 @@ fn migrations() -> Vec<(&'static str, MigrationKind)> {
         MigrationKind::SQL("alter table agents add column latest_work_for text;"),
     ));
 
+    migrations.push((
+        "create_build_timings_table",
+        MigrationKind::SQL(
+            "
+            CREATE TABLE build_timings (
+                experiment TEXT NOT NULL,
+                crate TEXT NOT NULL,
+                toolchain TEXT NOT NULL,
+                package_id TEXT NOT NULL,
+                target_name TEXT NOT NULL,
+                target_kind TEXT NOT NULL,
+                mode TEXT NOT NULL,
+                duration REAL NOT NULL,
+                rmeta_time REAL,
+                FOREIGN KEY (experiment) REFERENCES experiments(name) ON DELETE CASCADE
+            );
+            CREATE INDEX build_timings__experiment ON build_timings (experiment);
+            ",
+        ),
+    ));
+
     migrations
 }
 

src/lib.rs

@@ -27,6 +27,7 @@ pub mod report;
 pub mod results;
 pub mod runner;
 pub mod server;
+pub mod timings;
 pub mod toolchain;
 
 pub(crate) static GIT_REVISION: Option<&str> = include!(concat!(env!("OUT_DIR"), "/sha"));

src/results/db.rs

@@ -5,6 +5,7 @@ use crate::prelude::*;
 use crate::results::{
     DeleteResults, EncodedLog, EncodingType, ReadResults, TestResult, WriteResults,
 };
+use crate::timings::TimingInfo;
 use crate::toolchain::Toolchain;
 use base64::Engine;
 use rustwide::logging::{self, LogStorage};
@@ -143,6 +144,69 @@ impl<'a> DatabaseDB<'a> {
         Ok(())
     }
 
+    pub fn store_timings(
+        &self,
+        ex: &Experiment,
+        krate: &Crate,
+        toolchain: &Toolchain,
+        timings: &[TimingInfo],
+    ) -> Fallible<()> {
+        for timing in timings {
+            let target_kind = timing.target.kind.join(",");
+            self.db.execute_cached(
+                "INSERT INTO build_timings \
+                 (experiment, crate, toolchain, package_id, target_name, target_kind, mode, duration, rmeta_time) \
+                 VALUES (?1, ?2, ?3, ?4, ?5, ?6, ?7, ?8, ?9);",
+                &[
+                    &ex.name as &dyn rusqlite::types::ToSql,
+                    &krate.id(),
+                    &toolchain.to_string(),
+                    &timing.package_id,
+                    &timing.target.name,
+                    &target_kind,
+                    &timing.mode,
+                    &timing.duration,
+                    &timing.rmeta_time,
+                ],
+            )?;
+        }
+        Ok(())
+    }
+
+    pub fn load_timings(
+        &self,
+        ex: &Experiment,
+        krate: &Crate,
+        toolchain: &Toolchain,
+    ) -> Fallible<Vec<TimingInfo>> {
+        self.db.query(
+            "SELECT package_id, target_name, target_kind, mode, duration, rmeta_time \
+             FROM build_timings \
+             WHERE experiment = ?1 AND crate = ?2 AND toolchain = ?3;",
+            [&ex.name, &krate.id(), &toolchain.to_string()],
+            |row| {
+                let target_kind: String = row.get("target_kind")?;
+                let kinds: Vec<String> = target_kind.split(',').map(|s| s.to_string()).collect();
+                Ok(TimingInfo {
+                    package_id: row.get("package_id")?,
+                    target: crate::timings::TimingTarget {
+                        kind: kinds,
+                        crate_types: Vec::new(),
+                        name: row.get("target_name")?,
+                        src_path: String::new(),
+                        edition: String::new(),
+                        doc: false,
+                        doctest: false,
+                        test: false,
+                    },
+                    mode: row.get("mode")?,
+                    duration: row.get("duration")?,
+                    rmeta_time: row.get("rmeta_time")?,
+                })
+            },
+        )
+    }
+
     fn insert_into_results(
         &self,
         ex: &Experiment,
@@ -272,6 +336,16 @@ impl crate::runner::RecordProgress for DatabaseDB<'_> {
         }
         Ok(())
     }
+
+    fn record_timings(
+        &self,
+        ex: &Experiment,
+        krate: &Crate,
+        toolchain: &Toolchain,
+        timings: &[TimingInfo],
+    ) -> Fallible<()> {
+        self.store_timings(ex, krate, toolchain, timings)
+    }
 }
 
 impl DeleteResults for DatabaseDB<'_> {
@@ -468,6 +542,85 @@ mod tests {
             .is_none());
     }
 
+    #[test]
+    fn test_store_and_load_timings() {
+        let db = Database::temp().unwrap();
+        let results = DatabaseDB::new(&db);
+        let config = Config::default();
+        let ctx = ActionsCtx::new(&db, &config);
+
+        crate::crates::lists::setup_test_lists(&db, &config).unwrap();
+
+        CreateExperiment::dummy("dummy").apply(&ctx).unwrap();
+        let ex = Experiment::get(&db, "dummy").unwrap().unwrap();
+
+        let krate = Crate::Registry(RegistryCrate {
+            name: "lazy_static".into(),
+            version: "1".into(),
+        });
+
+        let timings = vec![
+            crate::timings::TimingInfo {
+                package_id: "serde 1.0.0 (registry+https://github.com/rust-lang/crates.io-index)"
+                    .to_string(),
+                target: crate::timings::TimingTarget {
+                    kind: vec!["lib".to_string()],
+                    crate_types: vec!["lib".to_string()],
+                    name: "serde".to_string(),
+                    src_path: "/path/to/src/lib.rs".to_string(),
+                    edition: "2021".to_string(),
+                    doc: true,
+                    doctest: true,
+                    test: true,
+                },
+                mode: "build".to_string(),
+                duration: 12.5,
+                rmeta_time: Some(8.3),
+            },
+            crate::timings::TimingInfo {
+                package_id: "foo 0.1.0".to_string(),
+                target: crate::timings::TimingTarget {
+                    kind: vec!["bin".to_string()],
+                    crate_types: vec!["bin".to_string()],
+                    name: "foo".to_string(),
+                    src_path: "/path/to/main.rs".to_string(),
+                    edition: "2021".to_string(),
+                    doc: false,
+                    doctest: false,
+                    test: false,
+                },
+                mode: "build".to_string(),
+                duration: 1.0,
+                rmeta_time: None,
+            },
+        ];
+
+        results
+            .store_timings(&ex, &krate, &MAIN_TOOLCHAIN, &timings)
+            .unwrap();
+
+        let loaded = results.load_timings(&ex, &krate, &MAIN_TOOLCHAIN).unwrap();
+
+        assert_eq!(loaded.len(), 2);
+
+        assert_eq!(loaded[0].package_id, timings[0].package_id);
+        assert_eq!(loaded[0].target.name, "serde");
+        assert_eq!(loaded[0].target.kind, vec!["lib"]);
+        assert_eq!(loaded[0].mode, "build");
+        assert!((loaded[0].duration - 12.5).abs() < f64::EPSILON);
+        assert!((loaded[0].rmeta_time.unwrap() - 8.3).abs() < f64::EPSILON);
+
+        assert_eq!(loaded[1].package_id, "foo 0.1.0");
+        assert_eq!(loaded[1].target.name, "foo");
+        assert_eq!(loaded[1].target.kind, vec!["bin"]);
+        assert!((loaded[1].duration - 1.0).abs() < f64::EPSILON);
+        assert!(loaded[1].rmeta_time.is_none());
+
+        // Different toolchain should return empty
+        let empty = results.load_timings(&ex, &krate, &TEST_TOOLCHAIN).unwrap();
+        assert!(empty.is_empty());
+    }
+
     #[test]
     fn test_store() {
         let db = Database::temp().unwrap();

src/runner/mod.rs

@@ -29,6 +29,7 @@ pub fn run_ex(
     threads_count: usize,
     config: &Config,
     next_crate: &(dyn Fn() -> Fallible<Option<Crate>> + Send + Sync),
+    is_agent_mode: bool,
 ) -> Fallible<()> {
     // Attempt to spin indefinitely until docker is up. Ideally, we would
     // decomission this agent until docker is up, instead of leaving the
@@ -89,6 +90,7 @@ pub fn run_ex(
                 config,
                 api,
                 next_crate,
+                is_agent_mode,
             )
         })
         .collect::<Vec<_>>();

src/runner/tasks.rs

@@ -4,6 +4,7 @@ use crate::experiments::Experiment;
 use crate::prelude::*;
 use crate::results::TestResult;
 use crate::runner::test;
+use crate::timings::TimingVisitor;
 use crate::toolchain::Toolchain;
 use rustwide::{Build, BuildDirectory};
 use std::collections::HashMap;
@@ -91,12 +92,13 @@ impl Task {
         config: &'ctx Config,
         build_dir: &'ctx HashMap<&'ctx crate::toolchain::Toolchain, Mutex<BuildDirectory>>,
         ex: &'ctx Experiment,
+        timing_visitor: &'ctx mut dyn TimingVisitor,
         logs: &LogStorage,
     ) -> Fallible<TestResult> {
         let (build_dir, action, test, toolchain, quiet): (
             _,
             _,
-            fn(&TaskCtx, &Build, &_) -> _,
+            fn(&TaskCtx, &Build, &_, &mut dyn TimingVisitor) -> _,
             _,
             _,
         ) = match self.step {
@@ -130,6 +132,6 @@ impl Task {
         };
 
         let ctx = TaskCtx::new(build_dir, config, ex, toolchain, &self.krate, quiet);
-        test::run_test(action, &ctx, test, logs)
+        test::run_test(action, &ctx, test, timing_visitor, logs)
     }
 }