fix(shell): the lib tests' load-dependent failures, at their causes

crates/shell/src/dependencies.rs

@@ -75,8 +75,11 @@ impl GitDependencyStore {
         if !mirror.is_dir() {
             let temporary = temporary_path(&mirrors, &remote_key);
             let mut command = git_command();
+            // `--no-local`: a local path is cloned through Git's transport
+            // too, not by copying its object directory, which races any Git
+            // process working in it (a commit's background maintenance).
             command
-                .args(["clone", "--mirror", "--"])
+                .args(["clone", "--mirror", "--no-local", "--"])
                 .arg(dependency.git())
                 .arg(&temporary);
             if let Err(error) = run_command(name, "clone", command) {
@@ -475,6 +478,10 @@ const LOCK_TIMEOUT: Duration = Duration::from_secs(2 * 60);
 fn git_command() -> Command {
     let mut command = Command::new("git");
     command
+        // No maintenance in the background: a commit, clone or fetch would
+        // otherwise leave a detached `git maintenance` working in a mirror
+        // the cache then renames and clones from, racing both.
+        .args(["-c", "maintenance.auto=false", "-c", "gc.auto=0"])
         .env("GIT_TERMINAL_PROMPT", "0")
         .env("GCM_INTERACTIVE", "Never")
         .stdin(Stdio::null())
@@ -1003,6 +1010,31 @@ mod tests {
         );
     }
 
+    /// A local clone copies the source's object directory file by file, so a
+    /// file a Git process working in the source has there is copied into the
+    /// mirror, or vanishes mid-copy and fails the clone: the fixture's own
+    /// background maintenance did that to its `maintenance.lock` under load.
+    /// The mirror is cloned through Git's transport, which sends objects only,
+    /// and the cache's own Git commands start no maintenance of their own.
+    #[test]
+    fn a_mirror_of_a_local_repository_takes_none_of_its_object_files() {
+        let fixture = GitFixture::new();
+        fixture.commit("export const version = 1;", "first");
+        std::fs::write(fixture.remote.join(".git/objects/maintenance.lock"), "")
+            .expect("a maintenance lock in the source");
+        GitDependencyStore::new(fixture.cache.clone())
+            .materialize("omarchy-ui", &fixture.dependency(r#""branch": "main""#))
+            .expect("checkout");
+        let mirror = std::fs::read_dir(fixture.cache.join("mirrors"))
+            .expect("mirror directory")
+            .next()
+            .expect("one mirror")
+            .expect("mirror entry")
+            .path();
+        assert!(mirror.join("objects").is_dir());
+        assert!(!mirror.join("objects/maintenance.lock").exists());
+    }
+
     #[test]
     fn a_cached_mirror_with_the_wrong_origin_is_refused() {
         let fixture = GitFixture::new();
@@ -1044,6 +1076,7 @@ mod tests {
             &[
                 "clone",
                 "--mirror",
+                "--no-local",
                 "--",
                 fixture.remote.to_str().expect("UTF-8 fixture remote"),
                 mirror.to_str().expect("UTF-8 mirror path"),

crates/shell/src/engine/quickjs/sandbox.rs

@@ -55,7 +55,7 @@
 use std::{
     cell::Cell,
     sync::atomic::{AtomicBool, Ordering},
-    time::{Duration, Instant},
+    time::Duration,
 };
 
 use rquickjs::{
@@ -418,7 +418,8 @@ pub fn max_stack_size_bytes() -> usize {
     1024 * 1024
 }
 
-/// How long one host call may keep the interpreter before it is cut off.
+/// How much CPU time one host call may keep the interpreter for before it is
+/// cut off.
 ///
 /// Kept private: the numbers are policy, not API, and tests need a version with
 /// a millisecond deadline so they finish quickly.
@@ -492,7 +493,10 @@ enum ExecutionWindow {
 
 fn deadline(budgets: Budgets) -> impl FnMut() -> bool + 'static {
     let mut window = None;
-    let mut started = Instant::now();
+    // The interpreter's own time, not the wall clock's: a render the machine
+    // left waiting for the CPU has not kept the interpreter, and cutting it off
+    // would fail the view because the machine was busy.
+    let mut started = crate::metrics::thread_cpu_time();
 
     move || {
         let current = match scope::current_generation() {
@@ -501,7 +505,7 @@ fn deadline(budgets: Budgets) -> impl FnMut() -> bool + 'static {
         };
         if window != Some(current) {
             window = Some(current);
-            started = Instant::now();
+            started = crate::metrics::thread_cpu_time();
         }
 
         let budget = match scope::current_phase() {
@@ -510,13 +514,16 @@ fn deadline(budgets: Budgets) -> impl FnMut() -> bool + 'static {
             None => budgets.detached,
         };
 
-        started.elapsed() > budget
+        crate::metrics::thread_cpu_time().saturating_sub(started) > budget
     }
 }
 
 #[cfg(test)]
 mod tests {
-    use std::sync::{Mutex, MutexGuard};
+    use std::{
+        sync::{Mutex, MutexGuard},
+        time::Instant,
+    };
 
     use rquickjs::{Context as JsContext, Runtime as JsRuntime, Value};
 

crates/shell/src/metrics.rs

@@ -330,3 +330,39 @@ impl Metrics {
 fn elapsed_nanos(started: instant::Instant) -> u64 {
     u64::try_from(started.elapsed().as_nanos()).unwrap_or(u64::MAX)
 }
+
+/// The CPU time the calling thread has run.
+///
+/// What a budget on script work, or a test comparing the cost of two pieces of
+/// work, has to count: the wall clock also counts the time other threads and
+/// processes held the CPU, which on a loaded machine can be more than the work
+/// itself. Where no thread CPU clock is read, the wall clock stands in.
+#[cfg(unix)]
+pub(crate) fn thread_cpu_time() -> Duration {
+    let mut time = libc::timespec {
+        tv_sec: 0,
+        tv_nsec: 0,
+    };
+    // SAFETY: POSIX `clock_gettime` writes one `timespec` through the valid
+    // pointer it is given; `CLOCK_THREAD_CPUTIME_ID` is supported on Linux and
+    // macOS.
+    let result = unsafe { libc::clock_gettime(libc::CLOCK_THREAD_CPUTIME_ID, &mut time) };
+    if result != 0 {
+        return wall_clock();
+    }
+    Duration::new(time.tv_sec as u64, time.tv_nsec as u32)
+}
+
+/// The CPU time the calling thread has run; see the unix version.
+#[cfg(not(unix))]
+pub(crate) fn thread_cpu_time() -> Duration {
+    wall_clock()
+}
+
+/// The wall clock since the first time it was read in this process.
+fn wall_clock() -> Duration {
+    thread_local! {
+        static START: instant::Instant = instant::Instant::now();
+    }
+    START.with(instant::Instant::elapsed)
+}

crates/shell/src/process.rs

@@ -439,6 +439,19 @@ mod tests {
     use super::*;
     use std::time::Duration;
 
+    #[cfg(unix)]
+    /// The deadline of the tests that are not about the deadline: long past
+    /// anything they run, so the outcome they check never races how loaded
+    /// the machine is. A 2 s deadline here timed out a command that had not
+    /// yet written a byte while the suite ran beside parallel builds.
+    const NOT_THE_DEADLINE: Duration = Duration::from_secs(600);
+
+    #[cfg(unix)]
+    /// How long a command that should have been cut short may take, spawn
+    /// included, on a loaded machine: far less than the `sleep 600` it runs,
+    /// far more than spawning one.
+    const CUT_SHORT: Duration = Duration::from_secs(60);
+
     #[cfg(unix)]
     use std::ffi::OsStr;
 
@@ -470,7 +483,7 @@ mod tests {
         let result = run_bounded(
             "/bin/sh",
             &["-c".into(), "printf out; printf err >&2".into()],
-            Limits::for_test(Duration::from_secs(2), 1024),
+            Limits::for_test(NOT_THE_DEADLINE, 1024),
             Cancellation::new(),
         )
         .expect("command");
@@ -485,7 +498,7 @@ mod tests {
         let result = run_bounded(
             "/usr/bin/env",
             &[],
-            Limits::for_test(Duration::from_secs(2), 1024),
+            Limits::for_test(NOT_THE_DEADLINE, 1024),
             Cancellation::new(),
         )
         .expect("environment probe");
@@ -513,13 +526,13 @@ mod tests {
         let started = Instant::now();
         let error = run_bounded(
             "/bin/sh",
-            &["-c".into(), "(sleep 5) & exit 0".into()],
+            &["-c".into(), "(sleep 600) & exit 0".into()],
             Limits::for_test(Duration::from_millis(50), 1024),
             Cancellation::new(),
         )
         .expect_err("the inherited pipes must remain under the deadline");
         assert!(error.contains("timed out"), "{error}");
-        assert!(started.elapsed() < Duration::from_secs(1));
+        assert!(started.elapsed() < CUT_SHORT);
     }
 
     #[cfg(unix)]
@@ -528,7 +541,7 @@ mod tests {
         let error = run_bounded(
             "/bin/sh",
             &["-c".into(), "yes x | head -c 4096".into()],
-            Limits::for_test(Duration::from_secs(2), 128),
+            Limits::for_test(NOT_THE_DEADLINE, 128),
             Cancellation::new(),
         )
         .expect_err("limit");
@@ -541,7 +554,7 @@ mod tests {
         let error = run_bounded(
             "/bin/sh",
             &["-c".into(), "yes x | head -c 4096 >&2".into()],
-            Limits::for_test(Duration::from_secs(2), 128),
+            Limits::for_test(NOT_THE_DEADLINE, 128),
             Cancellation::new(),
         )
         .expect_err("limit");
@@ -556,13 +569,13 @@ mod tests {
         let started = std::time::Instant::now();
         let error = run_bounded(
             "/bin/sh",
-            &["-c".into(), "sleep 5".into()],
-            Limits::for_test(Duration::from_secs(2), 1024),
+            &["-c".into(), "sleep 600".into()],
+            Limits::for_test(NOT_THE_DEADLINE, 1024),
             cancellation,
         )
         .expect_err("cancelled");
         assert!(error.contains("cancelled"), "{error}");
-        assert!(started.elapsed() < Duration::from_secs(1));
+        assert!(started.elapsed() < CUT_SHORT);
     }
 
     #[cfg(windows)]

crates/shell/src/tests/benchmark.rs

@@ -932,25 +932,26 @@ fn one_recorded_call_is_priced_stage_by_stage(cx: &mut TestAppContext) {
         "stage", "ns per call", "added", "what the step adds"
     );
 
+    let stages = [
+        ("js", "QuickJS interpreting the builder"),
+        ("crossing", "the bare crossing into Rust"),
+        ("name", "the method name as a Rust String"),
+        (
+            "arguments",
+            "the argument list, in a JS array, as `Bridged`",
+        ),
+        ("recorded", "dispatch and the arena write"),
+        ("shipped", "— what the prelude binds instead"),
+    ];
     let mut shipped = Vec::new();
     for (family, argument, label) in [
         ("nullary", None, "items_center()"),
         ("parametric", Some("\"#f8f8f8\""), "bg(\"#f8f8f8\")"),
     ] {
         println!("{label}:");
-        let mut previous = floor;
-        for (stage, adds) in [
-            ("js", "QuickJS interpreting the builder"),
-            ("crossing", "the bare crossing into Rust"),
-            ("name", "the method name as a Rust String"),
-            (
-                "arguments",
-                "the argument list, in a JS array, as `Bridged`",
-            ),
-            ("recorded", "dispatch and the arena write"),
-            ("shipped", "— what the prelude binds instead"),
-        ] {
-            let call = match argument {
+        let calls: Vec<String> = stages
+            .iter()
+            .map(|(stage, _)| match argument {
                 None => format!(
                     "__bench.bare(__bench.stages.{family}.{stage}, {BENCH_ELEMENTS}, \
                      {BENCH_PER_ELEMENT})"
@@ -959,14 +960,16 @@ fn one_recorded_call_is_priced_stage_by_stage(cx: &mut TestAppContext) {
                     "__bench.valued(__bench.stages.{family}.{stage}, {BENCH_ELEMENTS}, \
                      {BENCH_PER_ELEMENT}, {value})"
                 ),
-            };
-            let elapsed = time_stage(&runtime, &call);
+            })
+            .collect();
+        let mut previous = floor;
+        for ((stage, adds), elapsed) in stages.iter().zip(time_stages(&runtime, &calls)) {
             println!(
                 "{stage:>11} | {:>9.0} ns | {:>9.0} ns | {adds}",
                 per_call(elapsed),
                 per_call(elapsed) - per_call(previous),
             );
-            if stage == "shipped" {
+            if *stage == "shipped" {
                 shipped.push((label, per_call(previous), per_call(elapsed)));
             }
             previous = elapsed;
@@ -988,6 +991,29 @@ fn one_recorded_call_is_priced_stage_by_stage(cx: &mut TestAppContext) {
     }
 }
 
+/// The best CPU time of each of `calls`, their rounds interleaved so load from
+/// elsewhere on the machine falls on every stage alike: timed one stage after
+/// another, a burst of load during one stage's rounds alone could reverse the
+/// comparison the test makes between two of them.
+fn time_stages(runtime: &std::rc::Rc<ShellRuntime>, calls: &[String]) -> Vec<std::time::Duration> {
+    // The first round pays for the arena's first growth and for QuickJS's
+    // inline caches, neither of which a steady-state description pays.
+    for call in calls {
+        runtime.eval_for_benchmark(call).expect("stage");
+        runtime.reset_arena_for_benchmark();
+    }
+    let mut best = vec![std::time::Duration::MAX; calls.len()];
+    for _ in 0..ROUNDS {
+        for (best, call) in best.iter_mut().zip(calls) {
+            let started = crate::metrics::thread_cpu_time();
+            runtime.eval_for_benchmark(call).expect("stage");
+            *best = (*best).min(crate::metrics::thread_cpu_time() - started);
+            runtime.reset_arena_for_benchmark();
+        }
+    }
+    best
+}
+
 fn time_stage(runtime: &std::rc::Rc<ShellRuntime>, call: &str) -> std::time::Duration {
     // The first round pays for the arena's first growth and for QuickJS's
     // inline caches, neither of which a steady-state description pays.
@@ -996,9 +1022,9 @@ fn time_stage(runtime: &std::rc::Rc<ShellRuntime>, call: &str) -> std::time::Dur
 
     let mut best = std::time::Duration::MAX;
     for _ in 0..ROUNDS {
-        let started = Instant::now();
+        let started = crate::metrics::thread_cpu_time();
         runtime.eval_for_benchmark(call).expect("stage");
-        best = best.min(started.elapsed());
+        best = best.min(crate::metrics::thread_cpu_time() - started);
         runtime.reset_arena_for_benchmark();
     }
     best