diff --git a/.github/workflows/fspy-benchmark.yml b/.github/workflows/fspy-benchmark.yml new file mode 100644 index 00000000..a0761fb1 --- /dev/null +++ b/.github/workflows/fspy-benchmark.yml @@ -0,0 +1,162 @@ +name: fspy benchmark + +permissions: {} + +on: + workflow_dispatch: + pull_request: + types: [opened, reopened, synchronize] + push: + branches: + - main + +concurrency: + group: ${{ github.workflow }}-${{ github.event.pull_request.number || github.ref }} + cancel-in-progress: ${{ github.ref_name != 'main' }} + +defaults: + run: + shell: bash + +jobs: + benchmark: + name: Benchmark (${{ matrix.platform }}) + permissions: + actions: read + contents: read + strategy: + fail-fast: false + matrix: + include: + - platform: linux + os: namespace-profile-linux-x64-default + static: true + - platform: macos + os: namespace-profile-mac-default + static: false + - platform: windows + os: namespace-profile-windows-4c-8g + static: false + runs-on: ${{ matrix.os }} + env: + CARGO_TARGET_DIR: ${{ github.workspace }}/target + CRITERION_HOME: ${{ github.workspace }}/target/criterion + steps: + - uses: taiki-e/checkout-action@7d1e50e93dc4fb3bba58f85018fadf77898aee8b # v1.4.2 + + - name: Update Detours submodule + if: matrix.platform == 'windows' + run: git submodule update --init --recursive + + - uses: oxc-project/setup-rust@3d6fb132fbe7cdcb66bf8ec193911c2945369d12 # v1.0.17 + with: + save-cache: ${{ github.ref_name == 'main' }} + cache-key: fspy-benchmark-${{ matrix.platform }} + + - name: Install static target + if: matrix.static + run: rustup target add x86_64-unknown-linux-musl + + - name: Download main baseline + id: main-baseline + if: github.event_name != 'push' + uses: dawidd6/action-download-artifact@b6e2e70617bc3265edd6dab6c906732b2f1ae151 # v21 + with: + github_token: ${{ github.token }} + workflow: fspy-benchmark.yml + workflow_conclusion: success + branch: main + event: push + name: fspy-benchmark-baseline-v1-${{ matrix.platform }} + path: ${{ env.CRITERION_HOME }}/fspy + search_artifacts: true + if_no_artifact_found: warn + + - name: Run benchmark + env: + MAIN_BASELINE_FOUND: ${{ steps.main-baseline.outputs.found_artifact }} + run: | + mkdir -p .benchmark-results + if [[ "$GITHUB_EVENT_NAME" != "push" && "$MAIN_BASELINE_FOUND" == "true" ]]; then + baseline=(--baseline main) + else + baseline=(--save-baseline main) + fi + set -o pipefail + result_file=".benchmark-results/${{ matrix.platform }}.txt" + cargo bench --locked -p fspy_benchmark --bench fspy -- \ + --color never --verbose -n "${baseline[@]}" | + tee "$result_file" + result="$(<"$result_file")" + printf '%s' "$result" > "$result_file" + + - name: Add job summary + run: | + { + echo '```text' + cat ".benchmark-results/${{ matrix.platform }}.txt" + echo + echo '```' + } >> "$GITHUB_STEP_SUMMARY" + + - name: Upload main baseline + if: github.event_name == 'push' && github.ref_name == 'main' + uses: actions/upload-artifact@043fb46d1a93c77aae656e7c1c64a875d1fc6a0a # v7.0.1 + with: + name: fspy-benchmark-baseline-v1-${{ matrix.platform }} + path: ${{ env.CRITERION_HOME }}/fspy + if-no-files-found: error + overwrite: true + retention-days: 90 + + - name: Upload benchmark report + if: github.event_name == 'pull_request' + # Matrix jobs have isolated filesystems, so persist each report for the + # comment job to combine into one sticky comment after all platforms finish. + uses: actions/upload-artifact@043fb46d1a93c77aae656e7c1c64a875d1fc6a0a # v7.0.1 + with: + name: fspy-benchmark-report-${{ matrix.platform }} + path: .benchmark-results/${{ matrix.platform }}.txt + if-no-files-found: error + overwrite: true + retention-days: 90 + + comment: + name: Report benchmark + if: >- + github.event_name == 'pull_request' && + github.event.pull_request.head.repo.full_name == github.repository + needs: benchmark + runs-on: namespace-profile-linux-x64-default + permissions: + actions: read + pull-requests: write + steps: + - name: Download benchmark reports + uses: actions/download-artifact@3e5f45b2cfb9172054b4087a40e8e0b5a5461e7c # v8.0.1 + with: + pattern: fspy-benchmark-report-* + path: .benchmark-results + merge-multiple: true + + - name: Assemble comment + run: | + { + echo '## fspy benchmark' + echo + for platform in linux macos windows; do + echo "### $platform" + echo + echo '```text' + cat ".benchmark-results/$platform.txt" + echo + echo '```' + echo + done + } > .benchmark-results/comment.md + + - name: Update PR comment + uses: marocchino/sticky-pull-request-comment@0ea0beb66eb9baf113663a64ec522f60e49231c0 # v3.0.4 + with: + header: fspy-benchmark + path: .benchmark-results/comment.md diff --git a/Cargo.lock b/Cargo.lock index fd72b2ce..1a71e151 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -317,6 +317,12 @@ dependencies = [ "syn 2.0.117", ] +[[package]] +name = "bpaf" +version = "0.9.26" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "0b86829876e7e200161a5aa6ea688d46c32d64d70ee3100127790dde84688d6e" + [[package]] name = "brush-parser" version = "0.4.0" @@ -411,6 +417,12 @@ version = "0.1.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ade8366b8bd5ba243f0a58f036cc0ca8a2f069cff1a2351ef1cac6b083e16fc0" +[[package]] +name = "cast" +version = "0.3.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "37b2a672a2cb129a2e41c10b1224bb368f9f37a2b16b612598138befd7b37eb5" + [[package]] name = "castaway" version = "0.2.4" @@ -459,6 +471,33 @@ version = "0.2.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "613afe47fcd5fac7ccf1db93babcb082c5994d996f20b8b159f2ad1658eb5724" +[[package]] +name = "ciborium" +version = "0.2.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "42e69ffd6f0917f5c029256a24d0161db17cea3997d185db0d35926308770f0e" +dependencies = [ + "ciborium-io", + "ciborium-ll", + "serde", +] + +[[package]] +name = "ciborium-io" +version = "0.2.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "05afea1e0a06c9be33d539b876f1ce3692f4afea2cb41f740e7743225ed1c757" + +[[package]] +name = "ciborium-ll" +version = "0.2.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "57663b653d948a338bfb3eeba9bb2fd5fcfaecb9e199e87e1eda4d9e8b240fd9" +dependencies = [ + "ciborium-io", + "half", +] + [[package]] name = "clang-sys" version = "1.8.1" @@ -670,6 +709,21 @@ dependencies = [ "cfg-if", ] +[[package]] +name = "criterion2" +version = "3.0.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b961b72d7eaf7444d1eb98d353d5c2aa08e2443d77fef6bff0e6e97064162482" +dependencies = [ + "bpaf", + "cast", + "ciborium", + "num-traits", + "oorandom", + "serde", + "serde_json", +] + [[package]] name = "crossbeam-deque" version = "0.8.6" @@ -723,6 +777,12 @@ dependencies = [ "winapi", ] +[[package]] +name = "crunchy" +version = "0.2.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "460fbee9c2c2f33933d720630a6a0bac33ba7053db5344fac858d4b8952d77d5" + [[package]] name = "crypto-common" version = "0.1.7" @@ -1239,6 +1299,26 @@ dependencies = [ "winsafe 0.0.27", ] +[[package]] +name = "fspy_benchmark" +version = "0.0.0" +dependencies = [ + "criterion2", + "fspy", + "fspy_benchmark_static_target", + "fspy_benchmark_target", + "tokio", + "tokio-util", +] + +[[package]] +name = "fspy_benchmark_static_target" +version = "0.0.0" + +[[package]] +name = "fspy_benchmark_target" +version = "0.0.0" + [[package]] name = "fspy_detours_sys" version = "0.0.0" @@ -1537,6 +1617,17 @@ dependencies = [ "regex-syntax", ] +[[package]] +name = "half" +version = "2.7.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6ea2d84b969582b4b1864a92dc5d27cd2b77b622a8d79306834f1be5ba20d84b" +dependencies = [ + "cfg-if", + "crunchy", + "zerocopy", +] + [[package]] name = "hashbrown" version = "0.15.5" @@ -2394,6 +2485,12 @@ version = "1.70.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "384b8ab6d37215f3c5301a95a4accb5d64aa607f1fcb26a11b5303878451b4fe" +[[package]] +name = "oorandom" +version = "11.1.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d6790f58c7ff633d8771f42965289203411a5e5c68388703c06e14f24770b41e" + [[package]] name = "option-ext" version = "0.2.0" @@ -3251,9 +3348,9 @@ dependencies = [ [[package]] name = "serde_json" -version = "1.0.149" +version = "1.0.151" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "83fc039473c5595ace860d8c4fafa220ff474b3fc6bfdb4293327f1a37e94d86" +checksum = "c841b55ecdae098c80dcae9cf767f6f8a0c2cdb3416bbef72181df4d0fe73f14" dependencies = [ "indexmap", "itoa", diff --git a/Cargo.toml b/Cargo.toml index 80454123..818b4545 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -64,6 +64,7 @@ crossterm = { version = "0.29.0", features = ["event-stream"] } csv-async = { version = "1.3.1", features = ["tokio"] } ctor = "1.0" ctrlc = "3.5.2" +criterion2 = { version = "3.0.4", default-features = false } derive_more = "2.0.1" diff-struct = "0.5.3" directories = "6.0.0" @@ -72,6 +73,7 @@ materialized_artifact = { path = "crates/materialized_artifact" } materialized_artifact_build = { path = "crates/materialized_artifact_build" } flate2 = "1.0.35" fspy = { path = "crates/fspy" } +fspy_benchmark_target = { path = "crates/fspy_benchmark_target", artifact = "bin" } fspy_detours_sys = { path = "crates/fspy_detours_sys" } fspy_preload_unix = { path = "crates/fspy_preload_unix", artifact = "cdylib", target = "target" } fspy_preload_windows = { path = "crates/fspy_preload_windows", artifact = "cdylib", target = "target" } @@ -177,6 +179,7 @@ zstd = "0.13" [workspace.metadata.cargo-shear] ignored = [ # These are artifact dependencies. They are not directly `use`d in Rust code. + "fspy_benchmark_target", "fspy_preload_unix", "fspy_preload_windows", "vite_task_client_napi", diff --git a/crates/fspy_benchmark/Cargo.toml b/crates/fspy_benchmark/Cargo.toml new file mode 100644 index 00000000..c6fbe7b6 --- /dev/null +++ b/crates/fspy_benchmark/Cargo.toml @@ -0,0 +1,33 @@ +[package] +name = "fspy_benchmark" +version = "0.0.0" +authors.workspace = true +edition.workspace = true +license.workspace = true +publish = false +rust-version.workspace = true + +[lints] +workspace = true + +[lib] +test = false +bench = false +doctest = false + +[[bench]] +name = "fspy" +harness = false + +[dev-dependencies] +criterion2 = { workspace = true } +fspy = { workspace = true } +fspy_benchmark_target = { workspace = true } +tokio = { workspace = true, features = ["macros", "process", "rt-multi-thread"] } +tokio-util = { workspace = true } + +[target.'cfg(all(target_os = "linux", target_arch = "x86_64"))'.dev-dependencies] +fspy_benchmark_static_target = { path = "../fspy_benchmark_static_target", artifact = "bin", target = "x86_64-unknown-linux-musl" } + +[package.metadata.cargo-shear] +ignored = ["fspy_benchmark_target", "fspy_benchmark_static_target"] diff --git a/crates/fspy_benchmark/README.md b/crates/fspy_benchmark/README.md new file mode 100644 index 00000000..1d869c9b --- /dev/null +++ b/crates/fspy_benchmark/README.md @@ -0,0 +1,60 @@ +# fspy benchmark + +Measures what fspy costs a process it tracks. That cost is two separable things, and each is +measured apart from the other so that neither dilutes it: + +- `launch` is the wall clock of a launch that opens nothing, so it prices starting a process under + tracking: injection, session setup, and teardown. +- `access` is how long a batch of opens takes, timed by the thread that runs them, so it prices + interception itself rather than the launch around it. +- `access-tail` is the slow end of the same samples, which moves when accesses start to scatter + rather than to cost more. +- `access-concurrent` is `access` with a second thread intercepting at the same time, each thread + opening a path of its own. + +Every sample runs tracked and untracked launches as interleaved pairs, alternating which one goes +first, and reports the median per-pair overhead: `tracked / untracked - 1`. + +Linux measures a dynamically linked target that exercises `LD_PRELOAD` plus a +`x86_64-unknown-linux-musl` target that exercises seccomp user notification. macOS measures +`DYLD_INSERT_LIBRARIES` and Windows measures Detours injection. + +Run the benchmark with: + +```sh +just benchmark-fspy +``` + +## Comparing runs + +CI stores the results of the latest `main` run and compares pull request runs against them, so the +numbers have to be reproducible on whichever runner instance a pull request happens to get. + +Absolute times are not reproducible: identically configured runners disagree by tens of percent, +which is far more than the overhead being measured. Two things bring that back under control. + +Overhead is measured against an untracked launch that ran back to back, and reported as a share of +it rather than as a difference, so that a given slowdown in fspy moves the number by the same amount +everywhere, however cheap tracking is compared with the work the target does. + +Accesses are timed from inside the target rather than around the launch. A wall-clock launch is one +number covering milliseconds, so anything the runner does during it lands in the result; timing each +batch of eight opens instead produces hundreds of samples per launch, each a few microseconds long, +and the median discards the ones the scheduler spoiled. That took the spread from 4% to 0.7% on +macOS, and it made the benchmark faster, because a handful of launches now carries more information +than hundreds did. + +What remains is a spread of about 1% to 4%, measured by benchmarking the same commit on six runner +instances per platform. The noise threshold is set above it, and Criterion still prints the change it +measured when it stays below the threshold. `launch` is the widest of them, at times 7% on Linux: it +is the one row that has to be a whole-process wall-clock measurement, so it is also the one most +exposed to the runner. + +Two rows are left out where they do not reproduce: + +- `access-concurrent` on macOS. A second busy thread there makes every open cost about three times + as much, by an amount that changes from launch to launch, which moves the result by 25% between + runner instances against 3% for one thread. The same measurement reproduces within 4% on Linux and + Windows. +- `access-tail` on the seccomp target, whose slow samples are dominated by how quickly the runner + wakes the supervisor and move by 10% between instances. diff --git a/crates/fspy_benchmark/benches/fspy.rs b/crates/fspy_benchmark/benches/fspy.rs new file mode 100644 index 00000000..4f415f0e --- /dev/null +++ b/crates/fspy_benchmark/benches/fspy.rs @@ -0,0 +1,437 @@ +use std::{ + cell::RefCell, + collections::VecDeque, + process::Stdio, + time::{Duration, Instant}, +}; + +use criterion::{ + BenchmarkGroup, BenchmarkId, Criterion, SamplingMode, Throughput, criterion_group, + criterion_main, + measurement::{Measurement, ValueFormatter}, +}; +use fspy::{ChildTermination, Command}; +use tokio::{ + io::AsyncReadExt as _, + process::ChildStdout, + runtime::{Builder, Runtime}, +}; +use tokio_util::sync::CancellationToken; + +const DYNAMIC_TARGET: &str = env!("CARGO_BIN_FILE_FSPY_BENCHMARK_TARGET"); + +#[cfg(all(target_os = "linux", target_arch = "x86_64"))] +const STATIC_TARGET: &str = env!("CARGO_BIN_FILE_FSPY_BENCHMARK_STATIC_TARGET"); + +#[cfg(unix)] +const MISSING_PATH: &str = "/.fspy-benchmark-missing"; +#[cfg(windows)] +const MISSING_PATH: &str = r"C:\.fspy-benchmark-missing"; + +struct Workload { + threads: &'static str, + opens: &'static str, + /// Launch pairs behind every Criterion sample. Fixed so that a sample always + /// averages the same amount of work, whatever the runner speed is. + pairs_per_sample: u32, +} + +/// Concurrent launches scatter far more than single threaded ones, and by how +/// much depends on how many cores the runner has to spare, so samples have to +/// average enough pairs for the median to settle. Unix launches are cheap +/// enough to afford four times the base count; Windows launches cost several +/// times more wall clock and reproduce just as well without it. +#[cfg(windows)] +const PAIR_MULTIPLIER: u32 = 1; +#[cfg(not(windows))] +const PAIR_MULTIPLIER: u32 = 4; + +/// Opens one batch, so that capturing can be validated before measuring. Never +/// sampled, so its pair count does not matter. +const VALIDATION_WORKLOAD: Workload = Workload { threads: "1", opens: "8", pairs_per_sample: 0 }; + +/// Opens nothing, so the whole launch is the cost of starting a tracked +/// process. Two threads, because a process that fspy tracks rarely has one. +const LAUNCH_WORKLOAD: Workload = Workload { threads: "2", opens: "0", pairs_per_sample: 200 }; + +/// Accesses timed one thread at a time. Its samples come from inside the +/// target, so a handful of launches already carries hundreds of them. +const ACCESS_WORKLOAD: Workload = Workload { threads: "1", opens: "4096", pairs_per_sample: 25 }; + +/// The same access count spread over two threads, each opening a path of its +/// own so that they exercise interception rather than one shared lookup. +#[cfg(not(target_os = "macos"))] +const CONCURRENT_ACCESS_WORKLOAD: Workload = + Workload { threads: "2", opens: "2048", pairs_per_sample: 25 }; + +/// fspy costs a process two separable things: a one-off cost to start it under +/// tracking, and a cost on every access it makes. They are measured apart so +/// that neither dilutes the other, and each in the way that reproduces best. +#[derive(Clone, Copy)] +enum Metric { + /// Wall clock of a launch that opens nothing. + Launch = 0, + /// The typical time a batch of opens took, timed by the thread running it. + Access = 1, + /// The slow end of the same samples, which moves when accesses start to + /// scatter rather than to cost more. + AccessTail = 2, + /// The typical sample once a second thread is intercepting as well. + ConcurrentAccess = 3, +} + +impl Metric { + const fn name(self) -> &'static str { + match self { + Self::Launch => "launch", + Self::Access => "access", + Self::AccessTail => "access-tail", + Self::ConcurrentAccess => "access-concurrent", + } + } + + const fn of(self, launch: &Launch) -> Duration { + match self { + Self::Launch => launch.wall, + Self::Access | Self::ConcurrentAccess => launch.access, + Self::AccessTail => launch.access_tail, + } + } +} + +/// A workload and the metrics read out of its launches. +struct Case { + workload: &'static Workload, + metrics: &'static [Metric], +} + +/// Two threads racing to be intercepted only reproduce where the runner can be +/// counted on to run them at once. On macOS the same measurement moves by 25% +/// between runner instances, against 3% for one thread, because a second busy +/// thread there makes every open cost about three times as much by an amount +/// that changes from launch to launch. +#[cfg(target_os = "macos")] +const CONCURRENT_ACCESS_CASES: &[Case] = &[]; +#[cfg(not(target_os = "macos"))] +const CONCURRENT_ACCESS_CASES: &[Case] = + &[Case { workload: &CONCURRENT_ACCESS_WORKLOAD, metrics: &[Metric::ConcurrentAccess] }]; + +const ACCESS_CASES: &[Case] = + &[Case { workload: &ACCESS_WORKLOAD, metrics: &[Metric::Access, Metric::AccessTail] }]; + +const LAUNCH_CASES: &[Case] = &[Case { workload: &LAUNCH_WORKLOAD, metrics: &[Metric::Launch] }]; + +#[cfg(all(target_os = "linux", target_arch = "x86_64"))] +const STATIC_ACCESS_CASES: &[Case] = + &[Case { workload: &ACCESS_WORKLOAD, metrics: &[Metric::Access] }]; + +fn benchmark(criterion: &mut Criterion) { + let runtime = Builder::new_multi_thread().worker_threads(2).enable_all().build().unwrap(); + + let mut group = criterion.benchmark_group("fspy"); + group.sampling_mode(SamplingMode::Flat); + + for cases in [LAUNCH_CASES, ACCESS_CASES, CONCURRENT_ACCESS_CASES] { + benchmark_target(&mut group, &runtime, "dynamic", DYNAMIC_TARGET, cases); + } + + // Setting up seccomp user notification costs too differently between runner + // instances to compare, so the static target only measures accesses. Its + // tail is left out too: waiting for the supervisor to wake up scatters + // enough that the slow end moves by 10% between runner instances. + #[cfg(all(target_os = "linux", target_arch = "x86_64"))] + for cases in [STATIC_ACCESS_CASES, CONCURRENT_ACCESS_CASES] { + benchmark_target(&mut group, &runtime, "static", STATIC_TARGET, cases); + } + + group.finish(); +} + +fn benchmark_target( + group: &mut BenchmarkGroup<'_, Overhead>, + runtime: &Runtime, + target_name: &str, + target: &str, + cases: &[Case], +) { + validate_tracked_run(runtime, target); + + for case in cases { + benchmark_case(group, runtime, target_name, target, case); + } +} + +fn benchmark_case( + group: &mut BenchmarkGroup<'_, Overhead>, + runtime: &Runtime, + target_name: &str, + target: &str, + case: &Case, +) { + let workload = case.workload; + let metrics = case.metrics; + + // Criterion reports one number per benchmark and runs benchmarks one after + // another, so the first one measures every metric of the case and leaves + // the samples of the metrics after it here. + let handed_over: RefCell> = RefCell::new(VecDeque::new()); + + for (position, &metric) in metrics.iter().enumerate() { + group.bench_function(BenchmarkId::new(target_name, metric.name()), |bencher| { + bencher.iter_custom(|iterations| { + let overhead = if position == 0 { + let overheads = measure_overheads(runtime, target, workload); + let mut handed_over = handed_over.borrow_mut(); + for later in &metrics[1..] { + handed_over.push_back(overheads[*later as usize]); + } + overheads[metric as usize] + } else { + let sample = handed_over.borrow_mut().pop_front(); + sample.unwrap_or_else(|| { + measure_overheads(runtime, target, workload)[metric as usize] + }) + }; + // The sample always covers `pairs_per_sample` launch pairs, so + // report the per-pair overhead scaled to whatever iteration + // count Criterion asked for. + #[expect(clippy::cast_precision_loss, reason = "iteration counts stay small")] + let iterations = iterations as f64; + overhead * iterations + }); + }); + } +} + +/// Interleaves tracked and untracked launches, alternating which one goes first +/// so that ordering cannot bias a pair, and reports the median per-pair +/// overhead of every metric. +/// +/// Absolute launch times differ by tens of percent between runner instances, +/// while the overhead of a tracked launch relative to an untracked launch +/// measured back to back stays comparable, which is what makes results from +/// different runs comparable. Overhead is reported relative to the untracked +/// launch instead of as a tracked/untracked ratio so that a given slowdown in +/// fspy moves the number by the same amount on every platform, however cheap +/// tracking is compared with the work the target does. +fn measure_overheads(runtime: &Runtime, target: &str, workload: &Workload) -> [f64; 4] { + let pairs = workload.pairs_per_sample * PAIR_MULTIPLIER; + let mut overheads = [ + Vec::with_capacity(pairs as usize), + Vec::with_capacity(pairs as usize), + Vec::with_capacity(pairs as usize), + Vec::with_capacity(pairs as usize), + ]; + for index in 0..pairs { + let (tracked, untracked) = if index % 2 == 0 { + let untracked = measure(runtime, target, workload, Tracking::Off); + (measure(runtime, target, workload, Tracking::On), untracked) + } else { + let tracked = measure(runtime, target, workload, Tracking::On); + (tracked, measure(runtime, target, workload, Tracking::Off)) + }; + for (metric, samples) in + [Metric::Launch, Metric::Access, Metric::AccessTail, Metric::ConcurrentAccess] + .into_iter() + .zip(&mut overheads) + { + samples.push(overhead(metric, &tracked, &untracked)); + } + } + overheads.map(|mut samples| median(&mut samples)) +} + +fn overhead(metric: Metric, tracked: &Launch, untracked: &Launch) -> f64 { + metric.of(tracked).as_secs_f64() / metric.of(untracked).as_secs_f64() - 1.0 +} + +fn median(overheads: &mut [f64]) -> f64 { + overheads.sort_unstable_by(f64::total_cmp); + overheads[overheads.len() / 2] +} + +#[derive(Clone, Copy)] +enum Tracking { + On, + Off, +} + +/// What one launch measured. +struct Launch { + /// Wall clock of the launch, from spawning it to reaping it. + wall: Duration, + /// The typical batch of opens, as timed inside the target. + access: Duration, + /// The slow end of those batches. + access_tail: Duration, +} + +fn validate_tracked_run(runtime: &Runtime, target: &str) { + let termination = runtime.block_on(run_tracked(target, &VALIDATION_WORKLOAD)); + assert!(termination.status.success(), "benchmark target failed: {}", termination.status); + let captured_missing_access = termination.path_accesses.iter().any(|access| { + access.path.strip_path_prefix(MISSING_PATH, |result| { + result.is_ok_and(|path| path.as_os_str().is_empty()) + }) + }); + assert!(captured_missing_access, "failed to capture access to {MISSING_PATH}"); +} + +fn measure(runtime: &Runtime, target: &str, workload: &Workload, tracking: Tracking) -> Launch { + runtime.block_on(async { + let start = Instant::now(); + let mut reported = match tracking { + Tracking::Off => run_untracked(target, workload).await, + Tracking::On => run_tracked_reporting(target, workload).await, + }; + let wall = start.elapsed(); + let [access, access_tail] = read_reported_samples(&mut reported).await; + Launch { wall, access, access_tail } + }) +} + +/// Reads the samples the target timed for itself, which it writes to its +/// standard output once it is done. +async fn read_reported_samples(reported: &mut ChildStdout) -> [Duration; 2] { + let mut output = Vec::new(); + reported.read_to_end(&mut output).await.expect("failed to read the reported samples"); + let output = str::from_utf8(&output).expect("the reported samples are not utf-8"); + let mut samples = output + .split_whitespace() + .map(|sample| Duration::from_nanos(sample.parse().expect("unreadable reported sample"))); + let typical = samples.next().expect("the target reported no samples"); + let tail = samples.next().expect("the target reported no tail sample"); + [typical, tail] +} + +async fn run_untracked(target: &str, workload: &Workload) -> ChildStdout { + let mut child = tokio::process::Command::new(target) + .args([workload.threads, workload.opens]) + .stdin(Stdio::null()) + .stdout(Stdio::piped()) + .stderr(Stdio::inherit()) + .spawn() + .expect("failed to run untracked benchmark target"); + let stdout = child.stdout.take().expect("untracked benchmark target has no stdout"); + let status = child.wait().await.expect("failed to wait for untracked benchmark target"); + assert!(status.success(), "untracked benchmark target failed: {status}"); + stdout +} + +async fn run_tracked_reporting(target: &str, workload: &Workload) -> ChildStdout { + let mut child = tracked_command(target, workload, Stdio::piped()) + .spawn(CancellationToken::new()) + .await + .expect("failed to spawn tracked benchmark target"); + let stdout = child.stdout.take().expect("tracked benchmark target has no stdout"); + let termination = child.wait_handle.await.expect("failed to wait for tracked target"); + assert!( + termination.status.success(), + "tracked benchmark target failed: {}", + termination.status + ); + stdout +} + +async fn run_tracked(target: &str, workload: &Workload) -> ChildTermination { + tracked_command(target, workload, Stdio::null()) + .spawn(CancellationToken::new()) + .await + .expect("failed to spawn tracked benchmark target") + .wait_handle + .await + .expect("failed to wait for tracked benchmark target") +} + +fn tracked_command(target: &str, workload: &Workload, stdout: Stdio) -> Command { + let mut command = Command::new(target); + command + .args([workload.threads, workload.opens]) + .stdin(Stdio::null()) + .stdout(stdout) + .stderr(Stdio::inherit()); + command +} + +/// Measures the share of extra wall-clock time a tracked launch takes over an +/// untracked one. +struct Overhead; + +impl Measurement for Overhead { + type Intermediate = (); + type Value = f64; + + fn start(&self) -> Self::Intermediate {} + + fn end(&self, _intermediate: Self::Intermediate) -> Self::Value { + // Samples come from `iter_custom`, which reports shares directly. + 0.0 + } + + fn add(&self, v1: &Self::Value, v2: &Self::Value) -> Self::Value { + v1 + v2 + } + + fn zero(&self) -> Self::Value { + 0.0 + } + + fn to_f64(&self, value: &Self::Value) -> f64 { + *value + } + + fn formatter(&self) -> &dyn ValueFormatter { + &PercentFormatter + } +} + +struct PercentFormatter; + +impl PercentFormatter { + fn to_percent(values: &mut [f64]) -> &'static str { + for value in values { + *value *= 100.0; + } + "%" + } +} + +impl ValueFormatter for PercentFormatter { + fn scale_values(&self, _typical_value: f64, values: &mut [f64]) -> &'static str { + Self::to_percent(values) + } + + fn scale_throughputs( + &self, + _typical_value: f64, + _throughput: &Throughput, + values: &mut [f64], + ) -> &'static str { + Self::to_percent(values) + } + + fn scale_for_machines(&self, values: &mut [f64]) -> &'static str { + Self::to_percent(values) + } +} + +fn criterion_config() -> Criterion { + Criterion::default() + .with_measurement(Overhead) + .sample_size(10) + // A single call already covers a full sample of launch pairs, and the + // benchmark that reads handed over samples must not spend its warmup + // draining them. + .warm_up_time(Duration::from_nanos(1)) + .measurement_time(Duration::from_secs(5)) + // Runner instances still disagree by a few percent, so only report + // larger moves as changes. + .noise_threshold(0.1) +} + +criterion_group! { + name = benches; + config = criterion_config(); + targets = benchmark +} +criterion_main!(benches); diff --git a/crates/fspy_benchmark/src/lib.rs b/crates/fspy_benchmark/src/lib.rs new file mode 100644 index 00000000..6d118a16 --- /dev/null +++ b/crates/fspy_benchmark/src/lib.rs @@ -0,0 +1 @@ +//! Benchmarks for the overhead fspy adds to tracked processes. diff --git a/crates/fspy_benchmark_static_target/Cargo.toml b/crates/fspy_benchmark_static_target/Cargo.toml new file mode 100644 index 00000000..d8daccfe --- /dev/null +++ b/crates/fspy_benchmark_static_target/Cargo.toml @@ -0,0 +1,16 @@ +[package] +name = "fspy_benchmark_static_target" +version = "0.0.0" +authors.workspace = true +edition.workspace = true +license.workspace = true +publish = false +rust-version.workspace = true + +[lints] +workspace = true + +[[bin]] +name = "fspy_benchmark_static_target" +test = false +doctest = false diff --git a/crates/fspy_benchmark_static_target/src/main.rs b/crates/fspy_benchmark_static_target/src/main.rs new file mode 100644 index 00000000..6e96ceda --- /dev/null +++ b/crates/fspy_benchmark_static_target/src/main.rs @@ -0,0 +1 @@ +include!("../../fspy_benchmark_target/src/main.rs"); diff --git a/crates/fspy_benchmark_target/Cargo.toml b/crates/fspy_benchmark_target/Cargo.toml new file mode 100644 index 00000000..ea5536db --- /dev/null +++ b/crates/fspy_benchmark_target/Cargo.toml @@ -0,0 +1,16 @@ +[package] +name = "fspy_benchmark_target" +version = "0.0.0" +authors.workspace = true +edition.workspace = true +license.workspace = true +publish = false +rust-version.workspace = true + +[lints] +workspace = true + +[[bin]] +name = "fspy_benchmark_target" +test = false +doctest = false diff --git a/crates/fspy_benchmark_target/src/main.rs b/crates/fspy_benchmark_target/src/main.rs new file mode 100644 index 00000000..da3b63e2 --- /dev/null +++ b/crates/fspy_benchmark_target/src/main.rs @@ -0,0 +1,79 @@ +use std::{ + env, + fs::File, + sync::{Arc, Barrier}, + thread, + time::{Duration, Instant}, +}; + +const DEFAULT_THREAD_COUNT: usize = 4; +const DEFAULT_OPEN_COUNT_PER_THREAD: usize = 512; + +/// Opens behind one timing sample. Timing every open on its own would leave the +/// sample close to the clock's granularity, which is 42 ns on Apple silicon and +/// 100 ns on Windows, while a batch this small still keeps a sample short +/// enough that the scheduler only ever spoils a few of them. +const OPENS_PER_SAMPLE: usize = 8; + +#[cfg(unix)] +const MISSING_PATH: &str = "/.fspy-benchmark-missing"; +#[cfg(windows)] +const MISSING_PATH: &str = r"C:\.fspy-benchmark-missing"; + +/// Threads open distinct paths so that they do not contend for the same lookup. +const THREAD_SUFFIXES: [&str; 8] = ["", "1", "2", "3", "4", "5", "6", "7"]; + +fn main() { + let mut args = env::args().skip(1); + let thread_count = + args.next().and_then(|arg| arg.parse().ok()).unwrap_or(DEFAULT_THREAD_COUNT).max(1); + let open_count_per_thread = + args.next().and_then(|arg| arg.parse().ok()).unwrap_or(DEFAULT_OPEN_COUNT_PER_THREAD); + let barrier = Arc::new(Barrier::new(thread_count)); + + let mut samples = Vec::new(); + thread::scope(|scope| { + let workers: Vec<_> = (0..thread_count) + .map(|index| { + let barrier = Arc::clone(&barrier); + let mut path = MISSING_PATH.to_owned(); + path.push_str(THREAD_SUFFIXES[index % THREAD_SUFFIXES.len()]); + scope.spawn(move || time_opens(&barrier, &path, open_count_per_thread)) + }) + .collect(); + for worker in workers { + samples.extend(worker.join().expect("benchmark thread panicked")); + } + }); + + report(&mut samples); +} + +/// Times how long batches of opens take, from the thread that runs them, so +/// that the measurement covers the opens themselves rather than the launch +/// around them. +fn time_opens(barrier: &Barrier, path: &str, open_count: usize) -> Vec { + let sample_count = open_count / OPENS_PER_SAMPLE; + let mut samples = Vec::with_capacity(sample_count); + barrier.wait(); + for _ in 0..sample_count { + let started = Instant::now(); + for _ in 0..OPENS_PER_SAMPLE { + drop(File::open(path)); + } + samples.push(started.elapsed()); + } + samples +} + +/// Reports the typical and the slow sample, so that a change in how long opens +/// take can be told apart from a change in how much they scatter. +fn report(samples: &mut [Duration]) { + samples.sort_unstable(); + let percentile = + |percent: usize| samples.get(samples.len() * percent / 100).map_or(0, Duration::as_nanos); + #[expect(clippy::print_stdout, reason = "the benchmark reads the samples from stdout")] + { + println!("{} {}", percentile(50), percentile(90)); + } +} diff --git a/justfile b/justfile index f4b8b865..bd2d114f 100644 --- a/justfile +++ b/justfile @@ -47,6 +47,9 @@ lint-linux: lint-windows: cargo-xwin clippy --workspace --all-targets --all-features --target x86_64-pc-windows-msvc -- --deny warnings +benchmark-fspy: + cargo bench -p fspy_benchmark --bench fspy + [unix] doc: RUSTDOCFLAGS='-D warnings' cargo doc --no-deps --document-private-items