diff --git a/crates/shell/src/dependencies.rs b/crates/shell/src/dependencies.rs index 2b25066751..7fa49ffb92 100644 --- a/crates/shell/src/dependencies.rs +++ b/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"), diff --git a/crates/shell/src/engine/quickjs/sandbox.rs b/crates/shell/src/engine/quickjs/sandbox.rs index 50b0953656..95bd587642 100644 --- a/crates/shell/src/engine/quickjs/sandbox.rs +++ b/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}; diff --git a/crates/shell/src/metrics.rs b/crates/shell/src/metrics.rs index 9fe1bf95a1..767c817c72 100644 --- a/crates/shell/src/metrics.rs +++ b/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) +} diff --git a/crates/shell/src/process.rs b/crates/shell/src/process.rs index 49028b8fcc..b5fed6768b 100644 --- a/crates/shell/src/process.rs +++ b/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)] diff --git a/crates/shell/src/tests/benchmark.rs b/crates/shell/src/tests/benchmark.rs index 6c9e6b2450..62cb554433 100644 --- a/crates/shell/src/tests/benchmark.rs +++ b/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 = 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, calls: &[String]) -> Vec { + // 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, 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, 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 diff --git a/crates/shell/src/tests/network.rs b/crates/shell/src/tests/network.rs index eada1ea552..03eba9d021 100644 --- a/crates/shell/src/tests/network.rs +++ b/crates/shell/src/tests/network.rs @@ -1,6 +1,6 @@ use std::{ io::{Read as _, Write as _}, - net::TcpListener, + net::{TcpListener, TcpStream}, ops::Deref, sync::mpsc, thread, @@ -540,6 +540,88 @@ fn websocket_performs_a_real_handshake_off_thread(cx: &mut TestAppContext) { server.join().expect("WebSocket server"); } +/// The probe's render once `settled` holds for it, turning the test clock and +/// running what is ready while the client's I/O threads catch up, for at most +/// ten seconds. +fn render_until( + context: &mut VisualTestContext, + view: &Entity, + settled: impl Fn(&str) -> bool, +) -> String { + let deadline = std::time::Instant::now() + Duration::from_secs(10); + loop { + draw(context, view); + let rendered = snapshot(context, view); + if settled(&rendered) { + return rendered; + } + assert!( + std::time::Instant::now() < deadline, + "the probe never settled: {rendered}" + ); + thread::sleep(Duration::from_millis(5)); + context.executor().advance_clock(Duration::from_millis(10)); + context.run_until_parked(); + } +} + +/// Reads an HTTP request's head, up to the blank line that ends it, from a +/// stream accepted off a nonblocking listener. +/// +/// On macOS such a stream is nonblocking too, so a single read made before the +/// client's request arrives fails with `WouldBlock`, and one made while it is +/// arriving can return part of it. The stream is put back to blocking, with a +/// deadline, and read until the head is whole. +fn read_request_head(stream: &mut TcpStream) -> String { + stream.set_nonblocking(false).expect("blocking stream"); + stream + .set_read_timeout(Some(Duration::from_secs(10))) + .expect("read deadline"); + let mut head = Vec::new(); + let mut chunk = [0; 1024]; + while !head.windows(4).any(|window| window == b"\r\n\r\n") { + let count = stream.read(&mut chunk).expect("handshake request"); + assert!(count > 0, "the client closed before its request ended"); + head.extend_from_slice(&chunk[..count]); + } + String::from_utf8_lossy(&head).into_owned() +} + +/// Why [`read_request_head`] exists: on macOS a stream accepted off a +/// nonblocking listener inherits the mode, so reading it before the client +/// writes fails instead of waiting. The headers test read its request so, +/// and failed whenever a loaded machine let the server read first. +#[cfg(target_os = "macos")] +#[test] +fn a_stream_accepted_off_a_nonblocking_listener_does_not_wait_for_its_client() { + let listener = TcpListener::bind("127.0.0.1:0").expect("listener"); + listener + .set_nonblocking(true) + .expect("nonblocking listener"); + let client = TcpStream::connect(listener.local_addr().expect("address")).expect("connect"); + let mut stream = loop { + match listener.accept() { + Ok((stream, _)) => break stream, + Err(error) if error.kind() == std::io::ErrorKind::WouldBlock => thread::yield_now(), + Err(error) => panic!("accept failed: {error}"), + } + }; + let error = stream + .read(&mut [0; 16]) + .expect_err("nothing was written yet"); + assert_eq!(error.kind(), std::io::ErrorKind::WouldBlock); + + // Written only once the server is reading, the request is still read whole. + let reader = thread::spawn(move || read_request_head(&mut stream)); + let mut client = client; + client.write_all(b"GET / HTTP/1.1\r\n").expect("first part"); + client + .write_all(b"Host: example\r\n\r\n") + .expect("second part"); + let head = reader.join().expect("reader"); + assert_eq!(head, "GET / HTTP/1.1\r\nHost: example\r\n\r\n"); +} + #[gpui::test] fn websocket_sends_ordinary_and_custom_protocol_headers(cx: &mut TestAppContext) { let listener = TcpListener::bind("127.0.0.1:0").expect("WebSocket listener"); @@ -561,9 +643,7 @@ fn websocket_sends_ordinary_and_custom_protocol_headers(cx: &mut TestAppContext) Err(error) => panic!("WebSocket accept failed: {error}"), } }; - let mut request = [0; 4096]; - let count = stream.read(&mut request).expect("handshake request"); - let request = String::from_utf8_lossy(&request[..count]).to_ascii_lowercase(); + let request = read_request_head(&mut stream).to_ascii_lowercase(); assert!(request.contains("accept-language: zh-cn\r\n"), "{request}"); assert!( request.contains("user-agent: protocol-client/1\r\n"), @@ -994,11 +1074,12 @@ fn websocket_write_rejects_after_the_server_closes(cx: &mut TestAppContext) { let (_runtime, view, mut context) = probe(cx, &source); context.run_until_parked(); server.join().expect("WebSocket server"); - thread::sleep(Duration::from_millis(10)); - context.executor().advance_clock(Duration::from_millis(10)); - context.run_until_parked(); - draw(&mut context, &view); - let rendered = snapshot(&mut context, &view); + // The client's socket is read and written on threads of its own: wait for + // the probe to settle rather than for a fixed time, which a loaded machine + // outlasted with the probe still pending. + let rendered = render_until(&mut context, &view, |rendered| { + !rendered.contains("pending") + }); assert!( rendered.contains("rejected:WebSocket connection is closed"), "{rendered}" diff --git a/crates/shell/src/tests/template.rs b/crates/shell/src/tests/template.rs index 5d5e7385e4..221e267260 100644 --- a/crates/shell/src/tests/template.rs +++ b/crates/shell/src/tests/template.rs @@ -309,8 +309,12 @@ fn a_templated_panel_against_the_chain_it_replaces(cx: &mut TestAppContext) { const ITERATIONS: usize = 50; const ROUNDS: usize = 7; - let inline = time_board(cx, INLINE_WATCHLIST, ITERATIONS, ROUNDS); - let templated = time_board(cx, TEMPLATED_WATCHLIST, ITERATIONS, ROUNDS); + let [inline, templated] = time_boards( + cx, + [INLINE_WATCHLIST, TEMPLATED_WATCHLIST], + ITERATIONS, + ROUNDS, + ); println!( "\n[H] template against builder chain — 40-row watchlist\ @@ -331,30 +335,56 @@ fn a_templated_panel_against_the_chain_it_replaces(cx: &mut TestAppContext) { ); } -fn time_board( +/// The best CPU time per build of each of two boards, over `rounds` rounds +/// of `iterations` builds. +/// +/// The rounds alternate between the boards, so load from elsewhere on the +/// machine falls on both alike: timed one after the other, a burst of load +/// during either board's rounds alone decides the comparison. +fn time_boards( cx: &mut TestAppContext, - source: &str, + sources: [&str; 2], iterations: usize, rounds: usize, -) -> std::time::Duration { - let (runtime, mut context, object) = script_object(cx, source); +) -> [std::time::Duration; 2] { + let mut boards = sources.map(|source| script_object(cx, source)); + for board in &mut boards { + time_builds(board, 1); + } + let mut best = [std::time::Duration::MAX; 2]; + for _ in 0..rounds { + for (best, board) in best.iter_mut().zip(&mut boards) { + *best = (*best).min(time_builds(board, iterations)); + } + } + // A view's script object goes before the runtime it lives in, as locals + // dropped in reverse would; a tuple drops the runtime first. + for (runtime, context, object) in boards { + drop(object); + drop(context); + drop(runtime); + } + best +} + +type Board = ( + std::rc::Rc, + gpui::VisualTestContext, + crate::engine::ViewObject, +); + +/// The CPU time per build of `iterations` builds of `board`. +fn time_builds((runtime, context, object): &mut Board, iterations: usize) -> std::time::Duration { context.update(|window, cx| { - let mut build = || { + // Each board's runtime is the app's while it builds. + runtime.set_global(cx); + let started = crate::metrics::thread_cpu_time(); + for _ in 0..iterations { runtime - .build_snapshot(&object, None, crate::policy::default(), window, cx) - .expect("render") - }; - build(); - - let mut best = std::time::Duration::MAX; - for _ in 0..rounds { - let started = std::time::Instant::now(); - for _ in 0..iterations { - build(); - } - best = best.min(started.elapsed() / iterations as u32); + .build_snapshot(object, None, crate::policy::default(), window, cx) + .expect("render"); } - best + (crate::metrics::thread_cpu_time() - started) / iterations as u32 }) } @@ -474,8 +504,12 @@ fn what_automatic_templating_of_the_safe_helpers_would_buy(cx: &mut TestAppConte const ITERATIONS: usize = 50; const ROUNDS: usize = 7; - let plain = time_board(cx, BOARD_PLAIN, ITERATIONS, ROUNDS); - let templated = time_board(cx, BOARD_TEMPLATED_HELPERS, ITERATIONS, ROUNDS); + let [plain, templated] = time_boards( + cx, + [BOARD_PLAIN, BOARD_TEMPLATED_HELPERS], + ITERATIONS, + ROUNDS, + ); println!( "\n[I] automatic templating of leaf helpers — 20-row board, 6 cells\