diff --git a/js/.changeset/issue-22-parallel-sleep-tests.md b/js/.changeset/issue-22-parallel-sleep-tests.md new file mode 100644 index 00000000..e111943f --- /dev/null +++ b/js/.changeset/issue-22-parallel-sleep-tests.md @@ -0,0 +1,9 @@ +--- +'command-stream': patch +--- + +Cover parallel execution of sleeping commands with tests (issue #22). Two and +three commands started together — through the built-in `sleep`, through real +`sleep` processes with virtual commands disabled, and through `sh -c` scripts +that sleep between writes — must all finish, keep their own output and +environment, and overlap in time instead of running one after another. diff --git a/js/tests/parallel-sleep.test.mjs b/js/tests/parallel-sleep.test.mjs new file mode 100644 index 00000000..a8f22731 --- /dev/null +++ b/js/tests/parallel-sleep.test.mjs @@ -0,0 +1,190 @@ +import { describe, expect, test } from 'bun:test'; +import { isWindows } from './test-helper.mjs'; // Installs per-test state cleanup +import { $, disableVirtualCommands } from '../src/$.mjs'; + +// Issue #22: starting 2-3 commands that sleep inside must run them at the same +// time and let every one of them finish. +// +// Timing alone is a weak signal on a loaded CI machine, so each test asserts +// three independent things: +// 1. every command completed successfully (and produced its output), +// 2. the execution windows of the commands overlap, which is what "parallel" +// actually means, +// 3. the wall clock stayed well below the sequential total. + +// A sleep long enough that process startup noise cannot hide it, short enough +// to keep the suite fast. +const SLEEP_SECONDS = 0.5; +const SLEEP_MS = SLEEP_SECONDS * 1000; + +// Timers are allowed to fire slightly early (timer resolution, rounding in the +// sleep implementation), so the per-command lower bound gets a small slack. +const TIMER_SLACK_MS = 50; + +// The wall clock of a parallel run is compared against the sequential total. +// 75% leaves room for startup overhead while still failing loudly if the +// commands were serialized. +const SEQUENTIAL_FRACTION = 0.75; + +/** + * Start a command and record when it started and finished. + * @param {object} command Thenable command returned by `$` + * @returns {Promise<{result: object, startedAt: number, finishedAt: number}>} + */ +function timed(command) { + const startedAt = Date.now(); + return Promise.resolve(command).then((result) => ({ + result, + startedAt, + finishedAt: Date.now(), + })); +} + +/** + * Assert that every pair of runs was in flight at the same moment. + * @param {Array<{startedAt: number, finishedAt: number}>} runs Completed runs + */ +function expectOverlappingExecution(runs) { + for (let i = 0; i < runs.length; i++) { + for (let j = i + 1; j < runs.length; j++) { + // Half-open windows overlap when each one starts before the other ends. + expect(runs[i].startedAt).toBeLessThan(runs[j].finishedAt); + expect(runs[j].startedAt).toBeLessThan(runs[i].finishedAt); + } + } +} + +/** + * Assert that a run slept at least as long as it was asked to. + * @param {{startedAt: number, finishedAt: number}} run Completed run + * @param {number} expectedMs Requested sleep in milliseconds + */ +function expectSlept(run, expectedMs) { + expect(run.finishedAt - run.startedAt).toBeGreaterThanOrEqual( + expectedMs - TIMER_SLACK_MS + ); +} + +describe('parallel sleep commands', () => { + test('runs 2 sleeping commands at the same time', async () => { + const startedAt = Date.now(); + const runs = await Promise.all([ + timed($`sleep ${SLEEP_SECONDS}`), + timed($`sleep ${SLEEP_SECONDS}`), + ]); + const elapsed = Date.now() - startedAt; + + for (const run of runs) { + expect(run.result.code).toBe(0); + expectSlept(run, SLEEP_MS); + } + expectOverlappingExecution(runs); + expect(elapsed).toBeLessThan(2 * SLEEP_MS * SEQUENTIAL_FRACTION); + }); + + test('runs 3 sleeping commands at the same time', async () => { + const startedAt = Date.now(); + const runs = await Promise.all([ + timed($`sleep ${SLEEP_SECONDS}`), + timed($`sleep ${SLEEP_SECONDS}`), + timed($`sleep ${SLEEP_SECONDS}`), + ]); + const elapsed = Date.now() - startedAt; + + for (const run of runs) { + expect(run.result.code).toBe(0); + expectSlept(run, SLEEP_MS); + } + expectOverlappingExecution(runs); + expect(elapsed).toBeLessThan(3 * SLEEP_MS * SEQUENTIAL_FRACTION); + }); + + test('finishes mixed durations in the time of the longest one', async () => { + const durations = [0.2, 0.5, 0.3]; + const startedAt = Date.now(); + const runs = await Promise.all( + durations.map((seconds) => timed($`sleep ${seconds}`)) + ); + const elapsed = Date.now() - startedAt; + + runs.forEach((run, index) => { + expect(run.result.code).toBe(0); + expectSlept(run, durations[index] * 1000); + }); + expectOverlappingExecution(runs); + + const sequentialMs = durations.reduce((total, s) => total + s, 0) * 1000; + expect(elapsed).toBeLessThan(sequentialMs * SEQUENTIAL_FRACTION); + }); + + test.skipIf(isWindows)( + 'runs real sleep processes in parallel when virtual commands are off', + async () => { + // Without the built-in sleep the commands become real child processes, + // so this covers process spawning rather than the virtual command path. + // test-helper.mjs re-enables virtual commands after the test. + disableVirtualCommands(); + + const startedAt = Date.now(); + const runs = await Promise.all([ + timed($`sleep ${SLEEP_SECONDS}`), + timed($`sleep ${SLEEP_SECONDS}`), + timed($`sleep ${SLEEP_SECONDS}`), + ]); + const elapsed = Date.now() - startedAt; + + for (const run of runs) { + expect(run.result.code).toBe(0); + expectSlept(run, SLEEP_MS); + } + expectOverlappingExecution(runs); + expect(elapsed).toBeLessThan(3 * SLEEP_MS * SEQUENTIAL_FRACTION); + } + ); + + test.skipIf(isWindows)( + 'keeps the output of commands that sleep between writes', + async () => { + const startedAt = Date.now(); + const runs = await Promise.all( + [1, 2, 3].map((id) => + timed( + $`sh -c ${`echo "start ${id}"; sleep ${SLEEP_SECONDS}; echo "end ${id}"`}` + ) + ) + ); + const elapsed = Date.now() - startedAt; + + runs.forEach((run, index) => { + const id = index + 1; + expect(run.result.code).toBe(0); + expect(run.result.stdout.trim().split('\n')).toEqual([ + `start ${id}`, + `end ${id}`, + ]); + expectSlept(run, SLEEP_MS); + }); + expectOverlappingExecution(runs); + expect(elapsed).toBeLessThan(3 * SLEEP_MS * SEQUENTIAL_FRACTION); + } + ); + + test.skipIf(isWindows)( + 'gives each parallel command its own environment', + async () => { + const runs = await Promise.all( + [1, 2, 3].map((id) => + timed( + $`sh -c ${`VALUE="value ${id}"; sleep ${SLEEP_SECONDS}; echo "$VALUE"`}` + ) + ) + ); + + runs.forEach((run, index) => { + expect(run.result.code).toBe(0); + expect(run.result.stdout.trim()).toBe(`value ${index + 1}`); + }); + expectOverlappingExecution(runs); + } + ); +}); diff --git a/rust/changelog.d/20260916_091500_parallel_sleep_tests.md b/rust/changelog.d/20260916_091500_parallel_sleep_tests.md new file mode 100644 index 00000000..877dd836 --- /dev/null +++ b/rust/changelog.d/20260916_091500_parallel_sleep_tests.md @@ -0,0 +1,11 @@ +--- +bump: patch +--- + +### Added + +- Tests covering parallel execution of sleeping commands (issue #22). Two and + three commands started together — through the built-in `sleep`, through real + `/bin/sleep` processes, and through `sh -c` scripts that sleep between writes + — must all finish, keep their own output and environment, and overlap in time + instead of running one after another. diff --git a/rust/tests/parallel_sleep.rs b/rust/tests/parallel_sleep.rs new file mode 100644 index 00000000..a37fd1bc --- /dev/null +++ b/rust/tests/parallel_sleep.rs @@ -0,0 +1,213 @@ +//! Parallel execution of commands that sleep (issue #22). +//! +//! Timing alone is a weak signal on a loaded CI machine, so each test asserts +//! three independent things: +//! 1. every command completed successfully (and produced its output), +//! 2. the execution windows of the commands overlap, which is what "parallel" +//! actually means, +//! 3. the wall clock stayed well below the sequential total. + +use command_stream::{run, CommandResult}; +use std::time::{Duration, Instant}; + +/// A sleep long enough that process startup noise cannot hide it, short enough +/// to keep the suite fast. +const SLEEP: Duration = Duration::from_millis(500); + +/// Timers are allowed to fire slightly early (timer resolution, rounding in the +/// sleep implementation), so the per-command lower bound gets a small slack. +const TIMER_SLACK: Duration = Duration::from_millis(50); + +/// The wall clock of a parallel run is compared against the sequential total. +/// 75% leaves room for startup overhead while still failing loudly if the +/// commands were serialized. +const SEQUENTIAL_FRACTION: f64 = 0.75; + +/// One completed command plus the window it occupied. +struct TimedRun { + result: CommandResult, + started: Instant, + finished: Instant, +} + +/// Run a command, recording when it started and when it finished. +async fn timed(command: String) -> TimedRun { + let started = Instant::now(); + let result = run(command).await.expect("command failed to run"); + + TimedRun { + result, + started, + finished: Instant::now(), + } +} + +/// Format a sleep duration the way `sleep(1)` expects it. +fn seconds(duration: Duration) -> String { + format!("{:.3}", duration.as_secs_f64()) +} + +/// Assert that every pair of runs was in flight at the same moment. +fn assert_overlapping(runs: &[&TimedRun]) { + for (first_index, first) in runs.iter().enumerate() { + for (offset, second) in runs[first_index + 1..].iter().enumerate() { + // Half-open windows overlap when each one starts before the other + // ends. + assert!( + first.started < second.finished && second.started < first.finished, + "commands {} and {} did not overlap", + first_index, + first_index + 1 + offset + ); + } + } +} + +/// Assert that a run slept at least as long as it was asked to. +fn assert_slept(run: &TimedRun, expected: Duration) { + let elapsed = run.finished - run.started; + assert!( + elapsed + TIMER_SLACK >= expected, + "command finished after {:?}, expected at least {:?}", + elapsed, + expected + ); +} + +/// Assert that the whole batch finished well below the sequential total. +fn assert_faster_than_sequential(elapsed: Duration, sequential: Duration) { + let budget = sequential.mul_f64(SEQUENTIAL_FRACTION); + assert!( + elapsed < budget, + "batch took {:?}, which is not below the {:?} parallel budget (sequential total {:?})", + elapsed, + budget, + sequential + ); +} + +#[tokio::test] +async fn two_sleeping_commands_run_at_the_same_time() { + let batch_started = Instant::now(); + let (first, second) = tokio::join!( + timed(format!("sleep {}", seconds(SLEEP))), + timed(format!("sleep {}", seconds(SLEEP))), + ); + let elapsed = batch_started.elapsed(); + + for run in [&first, &second] { + assert!(run.result.is_success()); + assert_slept(run, SLEEP); + } + assert_overlapping(&[&first, &second]); + assert_faster_than_sequential(elapsed, 2 * SLEEP); +} + +#[tokio::test] +async fn three_sleeping_commands_run_at_the_same_time() { + let batch_started = Instant::now(); + let (first, second, third) = tokio::join!( + timed(format!("sleep {}", seconds(SLEEP))), + timed(format!("sleep {}", seconds(SLEEP))), + timed(format!("sleep {}", seconds(SLEEP))), + ); + let elapsed = batch_started.elapsed(); + + for run in [&first, &second, &third] { + assert!(run.result.is_success()); + assert_slept(run, SLEEP); + } + assert_overlapping(&[&first, &second, &third]); + assert_faster_than_sequential(elapsed, 3 * SLEEP); +} + +#[tokio::test] +async fn mixed_durations_finish_in_the_time_of_the_longest_one() { + let durations = [ + Duration::from_millis(200), + Duration::from_millis(500), + Duration::from_millis(300), + ]; + + let batch_started = Instant::now(); + let (first, second, third) = tokio::join!( + timed(format!("sleep {}", seconds(durations[0]))), + timed(format!("sleep {}", seconds(durations[1]))), + timed(format!("sleep {}", seconds(durations[2]))), + ); + let elapsed = batch_started.elapsed(); + + for (run, duration) in [&first, &second, &third].iter().zip(durations) { + assert!(run.result.is_success()); + assert_slept(run, duration); + } + assert_overlapping(&[&first, &second, &third]); + assert_faster_than_sequential(elapsed, durations.iter().sum()); +} + +/// Absolute path so the built-in `sleep` is bypassed and real child processes +/// are spawned instead, covering the process path rather than the virtual one. +#[cfg(unix)] +#[tokio::test] +async fn real_sleep_processes_run_in_parallel() { + let batch_started = Instant::now(); + let (first, second, third) = tokio::join!( + timed(format!("/bin/sleep {}", seconds(SLEEP))), + timed(format!("/bin/sleep {}", seconds(SLEEP))), + timed(format!("/bin/sleep {}", seconds(SLEEP))), + ); + let elapsed = batch_started.elapsed(); + + for run in [&first, &second, &third] { + assert!(run.result.is_success()); + assert_slept(run, SLEEP); + } + assert_overlapping(&[&first, &second, &third]); + assert_faster_than_sequential(elapsed, 3 * SLEEP); +} + +#[cfg(unix)] +#[tokio::test] +async fn output_of_commands_that_sleep_between_writes_is_kept() { + let script = |id: u32| { + format!( + "sh -c 'echo \"start {id}\"; sleep {}; echo \"end {id}\"'", + seconds(SLEEP) + ) + }; + + let batch_started = Instant::now(); + let (first, second, third) = tokio::join!(timed(script(1)), timed(script(2)), timed(script(3))); + let elapsed = batch_started.elapsed(); + + for (index, run) in [&first, &second, &third].iter().enumerate() { + let id = index + 1; + assert!(run.result.is_success()); + assert_eq!( + run.result.stdout.trim().lines().collect::>(), + vec![format!("start {id}"), format!("end {id}")] + ); + assert_slept(run, SLEEP); + } + assert_overlapping(&[&first, &second, &third]); + assert_faster_than_sequential(elapsed, 3 * SLEEP); +} + +#[cfg(unix)] +#[tokio::test] +async fn each_parallel_command_keeps_its_own_environment() { + let script = |id: u32| { + format!( + "sh -c 'VALUE=\"value {id}\"; sleep {}; echo \"$VALUE\"'", + seconds(SLEEP) + ) + }; + + let (first, second, third) = tokio::join!(timed(script(1)), timed(script(2)), timed(script(3))); + + for (index, run) in [&first, &second, &third].iter().enumerate() { + assert!(run.result.is_success()); + assert_eq!(run.result.stdout.trim(), format!("value {}", index + 1)); + } + assert_overlapping(&[&first, &second, &third]); +}