diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 880f465..342eb34 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -72,6 +72,28 @@ jobs: - run: make install-dev - run: make test SHELLSPEC_FLAGS="--shell ${{ matrix.shell }}" + # The benchmarks are a report, and a hosted runner is a noisy place to + # take timings on, so the job only fails when a scenario was not faster in + # chains than in order at all. That is a claim no amount of a busy runner + # should be able to break, and the table lands in the run summary either + # way. + bench: + runs-on: ubuntu-latest + timeout-minutes: 15 + steps: + - uses: actions/checkout@v7 + - name: Benchmark + run: make bench 2>&1 | tee bench.txt + - name: Publish the table + if: always() + run: | + [ -f bench.txt ] || exit 0 + { + echo '```' + cat bench.txt + echo '```' + } >>"$GITHUB_STEP_SUMMARY" + freebsd: runs-on: ubuntu-latest timeout-minutes: 30 diff --git a/Makefile b/Makefile index dd03f56..7b48b7b 100644 --- a/Makefile +++ b/Makefile @@ -7,15 +7,16 @@ SHELLSPEC = .tools/bin/shellspec # Extra flags for the suite, e.g. `make test SHELLSPEC_FLAGS="--shell dash"`. SHELLSPEC_FLAGS = -# The library and the example: POSIX sh, formatted, no bashisms. -SCRIPTS = parallel.sh examples/build.sh +# The library, the example and the benchmarks: POSIX sh, formatted, no +# bashisms. +SCRIPTS = parallel.sh examples/build.sh bench/bench.sh # The spec files are POSIX sh as well and get checked, but not formatted: # shellspec's Describe, It and End are ordinary commands, so shfmt sees no # nesting to keep and flattens the whole file to one column. SPECS = spec/parallel_spec.sh spec/spec_helper.sh -.PHONY: check lint test install-dev +.PHONY: check lint test bench install-dev check: lint test @@ -28,6 +29,11 @@ test: @[ -x $(SHELLSPEC) ] || { echo "$(SHELLSPEC) is missing: make install-dev" >&2; exit 1; } $(SHELLSPEC) $(SHELLSPEC_FLAGS) +# Not part of `check`: it is minutes of sleeping, and it reports rather than +# asserts. Takes REPS, SCALE and SHELL_UNDER_TEST from the environment. +bench: + ./bench/bench.sh + # Into .tools, which is gitignored. install-dev: curl -fsSL https://raw.githubusercontent.com/shellspec/shellspec/$(SHELLSPEC_VERSION)/install.sh \ diff --git a/README.md b/README.md index ab4f7a8..068317a 100644 --- a/README.md +++ b/README.md @@ -30,6 +30,45 @@ chain "npm ci --audit false" "npm run build" run ``` +Drawn out, with the times off a middling Laravel app. The second one +finishes when its longest chain does rather than when its last command +does: + +```mermaid +gantt + title The build above, in order and in chains + dateFormat HH:mm:ss + axisFormat %M:%S + todayMarker off + section In order + composer install :done, 00:00:00, 00:00:40 + npm ci :done, 00:00:40, 00:01:30 + npm run build :done, 00:01:30, 00:01:50 + section In chains + composer install :active, 00:00:00, 00:00:40 + npm ci :active, 00:00:00, 00:00:50 + npm run build :active, 00:00:50, 00:01:10 +``` + +A failure arrives sooner for the same reason. The step that fails is not +waiting on the steps that would have run before it, so the build stops +about when the failure happens instead of once everything ahead of it is +done: + +```mermaid +gantt + title A lint that fails, at the end of a script and in a chain + dateFormat HH:mm:ss + axisFormat %M:%S + todayMarker off + section In order + phpunit :done, 00:00:00, 00:00:50 + lint, exits 1 :crit, 00:00:50, 00:01:00 + section In chains + phpunit, cancelled :active, 00:00:00, 00:00:10 + lint, exits 1 :crit, 00:00:00, 00:00:10 +``` + When something fails, the failure is at the bottom and the rest is grouped above it: @@ -92,6 +131,58 @@ a different interval and `POLL_WHOLE` for a different fallback: POLL=0.5 . ./parallel.sh ``` +## Benchmarks + +`bench/bench.sh` runs four builds twice each, once in declaration order the +way a `set -e` script runs them and once as chains. Every step in them is a +`sleep`, at a tenth of the length the step it stands for would take, so the +suite is minutes rather than hours. On a four-core Linux box, under dash, +best of three runs: + +| Scenario | In order | In chains | Speedup | +| --- | ---: | ---: | ---: | +| PHP app with a front end | 11.01s | 7.09s | 1.6x | +| CI checks, four of them | 12.01s | 5.03s | 2.4x | +| A failing lint | 6.01s | 1.03s | 5.8x | +| One dominant step | 10.01s | 6.04s | 1.7x | + +- **PHP app with a front end** — `composer install` (4s) in one chain, + `npm ci` (5s) then `npm run build` (2s) in the other. The build at the top + of this file. +- **CI checks, four of them** — lint (1s), typecheck (3s), unit tests (5s) + and a build (3s), none of them waiting on any other. The shape chains are + best at: the job takes as long as its slowest check instead of as long as + all of them. +- **A failing lint** — unit tests (5s) alongside a lint that exits 1 after + 1s. In order the failure turns up last because that is where the step is, + and a lint at the top of the script would be found just as early. That is + the point: in chains it does not matter where it is. +- **One dominant step** — `npm run build` (6s) alongside `composer install` + (3s) and `php artisan migrate` (1s). The ceiling on all of this: a build + cannot finish before its longest chain does, so the most chains can do is + hide the rest behind it. + +Eight chains that do nothing at all finish in 0.15s: one `mktemp`, eight +forks, and a poll or two. That is about what the library costs a build with +nothing to gain. + +The table is a report on shapes, not a measurement of any real build. A +`sleep` waits without competing for a core, a disk or a link, so these are +the times a build gets when its steps are mostly waiting on something other +than each other. Steps that each saturate the machine will not see them. + +`make bench` runs it. `REPS` is how many runs each scenario gets, `SCALE` +multiplies every duration, and `SHELL_UNDER_TEST` picks the shell: + +```sh +REPS=1 SCALE=0.25 SHELL_UNDER_TEST=/bin/bash make bench +``` + +CI runs it on every push and puts the table in the run summary. It fails the +job only when a scenario was not faster in chains than in order at all: +anything tighter is a number to hold against a hosted runner, and they are +too noisy to be held to one. + ## Caveats `kill` stops a cancelled chain's shell, not its grandchildren. A command diff --git a/bench/bench.sh b/bench/bench.sh new file mode 100755 index 0000000..53fae29 --- /dev/null +++ b/bench/bench.sh @@ -0,0 +1,246 @@ +#!/bin/sh +# shellcheck shell=sh +# Benchmarks for parallel.sh. POSIX sh, like the library it measures. +# +# A scenario is a build, described as the chains it is made of, and every +# step in it is a `sleep` as long as that step usually takes. The same steps +# then run twice: once in declaration order, the way a `set -e` script runs +# them, and once as chains. The difference between the two is the whole of +# what this measures. +# +# Sleeps stand in for the work because the shape of a build is what changes +# here, not the work in it: `sleep` waits without competing for a core, a +# disk or a network link, so these numbers are the ones a build gets when +# its steps are mostly waiting on something other than each other. Steps +# that each saturate the machine will not see them. +# +# ./bench/bench.sh every scenario, three runs each +# REPS=1 ./bench/bench.sh one run each +# SCALE=0.25 ./bench/bench.sh a quarter of every duration +# SHELL_UNDER_TEST=/bin/bash ./bench/bench.sh +# +# It exits non-zero if a scenario was not faster in chains than in order, +# which is the only assertion here: the times themselves are a report, and +# a machine slow enough to change them by a few percent should not fail a +# build over it. + +set -u + +REPS=${REPS:-3} +SCALE=${SCALE:-1} +SHELL_UNDER_TEST=${SHELL_UNDER_TEST:-/bin/sh} + +_here=$(dirname "$0") +LIB=${LIB:-$_here/../parallel.sh} +if [ ! -f "$LIB" ]; then + printf 'no parallel.sh at %s\n' "$LIB" >&2 + exit 1 +fi +# The generated scripts are run from elsewhere, so the library needs a path +# that does not depend on where they run from. +LIB=$(cd "$(dirname "$LIB")" && pwd)/$(basename "$LIB") + +_work=$(mktemp -d "${TMPDIR:-/tmp}/parallel-bench.XXXXXX") +trap 'rm -rf "$_work"' EXIT +trap 'rm -rf "$_work"; exit 130' INT +trap 'rm -rf "$_work"; exit 143' TERM + +_slower='' # scenarios that chains did not help, filled in as they run + +# Milliseconds since the epoch, from whatever this machine happens to have. +# GNU date takes %3N and BSD date does not, so the clock is chosen once, by +# trying each candidate and keeping the first that answers with a plausible +# number of digits. Whole seconds are the last resort: the report says which +# clock it used, because a scenario timed to the second is worth less than +# one timed to the millisecond. +_clock=seconds +_now() { + case $_clock in + date) date +%s%3N ;; + perl) perl -MTime::HiRes -e 'printf "%.0f", Time::HiRes::time() * 1000' ;; + python) python3 -c 'import time; print(int(time.time() * 1000))' ;; + *) printf '%s000' "$(date +%s)" ;; + esac +} + +_pick_clock() { + for _c in date perl python; do + _clock=$_c + _t=$(_now 2>/dev/null) || _t='' + case $_t in + '' | *[!0-9]*) continue ;; + esac + [ "${#_t}" -ge 13 ] && return 0 + done + _clock=seconds +} + +# A chain is written "label:seconds|label:seconds": steps in order, each one +# the length it takes. A duration ending in ! is a step that fails when it +# is done, which is how a scenario says where the failure is. +_steps() { printf '%s\n' "$1" | tr '|' '\n'; } + +_label() { + _first=${1%%|*} + printf '%s' "${_first%:*}" +} + +_seconds() { + _d=${1##*:} + _d=${_d%!} + awk -v d="$_d" -v s="$SCALE" 'BEGIN { printf "%g", d * s }' +} + +_command() { + case ${1##*:} in + *!) printf 'sleep %s; exit 1' "$(_seconds "$1")" ;; + *) printf 'sleep %s' "$(_seconds "$1")" ;; + esac +} + +# The build as a script that runs its steps in order and stops at the first +# failure, which is what it looked like before. +_write_ordered() { + { + printf '#!/bin/sh\nset -e\n' + for _chain in "$@"; do + _steps "$_chain" | while IFS= read -r _step; do + printf '%s\n' "$(_command "$_step")" + done + done + } >"$_work/ordered.sh" +} + +# The same build as chains. +_write_chained() { + { + printf '#!/bin/sh\n. "%s"\n' "$LIB" + for _chain in "$@"; do + printf 'chain "%s"' "$(_label "$_chain")" + _steps "$_chain" | while IFS= read -r _step; do + printf ' "%s"' "$(_command "$_step")" + done + printf '\n' + done + printf 'run\n' + } >"$_work/chained.sh" +} + +# One run, in milliseconds. A scenario that ends in a failure exits +# non-zero by design, so the status is not the point and is thrown away. +_time() { + _start=$(_now) + "$SHELL_UNDER_TEST" "$1" >/dev/null 2>&1 || : + _end=$(_now) + printf '%s' "$((_end - _start))" +} + +# The best of REPS runs, not the mean: a run can only be made slower by +# whatever else the machine was doing, so the fastest one is the closest to +# what was actually being measured. +_best() { + _min='' + _i=1 + while [ "$_i" -le "$REPS" ]; do + _ms=$(_time "$1") + if [ -z "$_min" ] || [ "$_ms" -lt "$_min" ]; then + _min=$_ms + fi + _i=$((_i + 1)) + done + printf '%s' "$_min" +} + +_secs() { awk -v ms="$1" 'BEGIN { printf "%.2fs", ms / 1000 }'; } + +_ratio() { + if [ "$2" -le 0 ]; then + printf '-' + return 0 + fi + awk -v a="$1" -v b="$2" 'BEGIN { printf "%.1fx", a / b }' +} + +_row() { printf '%-32s %11s %11s %9s\n' "$1" "$2" "$3" "$4"; } + +scenario() { + _name=$1 + shift + _write_ordered "$@" + _write_chained "$@" + _ordered=$(_best "$_work/ordered.sh") + _chained=$(_best "$_work/chained.sh") + _row "$_name" "$(_secs "$_ordered")" "$(_secs "$_chained")" \ + "$(_ratio "$_ordered" "$_chained")" + [ "$_chained" -lt "$_ordered" ] || _slower="$_slower + $_name" +} + +# What the library costs when there is nothing to gain: eight chains that do +# nothing at all, so the time is one mktemp, eight forks and a poll or two. +# Any scenario above is that much slower than the build it describes. +_overhead() { + { + printf '#!/bin/sh\n. "%s"\n' "$LIB" + _i=1 + while [ "$_i" -le 8 ]; do + printf 'chain "chain %s" ":"\n' "$_i" + _i=$((_i + 1)) + done + printf 'run\n' + } >"$_work/overhead.sh" + _best "$_work/overhead.sh" +} + +_pick_clock + +printf 'parallel.sh benchmarks\n' +printf 'shell %s, clock %s, poll %s, best of %s, scale %s\n\n' \ + "$SHELL_UNDER_TEST" "$_clock" "${POLL:-0.1}" "$REPS" "$SCALE" + +_row 'scenario' 'in order' 'in chains' 'speedup' +_row '--------' '--------' '---------' '-------' + +# A PHP app with a front end: composer waits on nothing npm does, and npm +# waits on nothing composer does, but a script runs them one after the other +# anyway. The npm steps are a chain because the build needs its own +# dependencies first. +scenario 'PHP app with a front end' \ + 'composer install:4' \ + 'npm ci:5|npm run build:2' + +# The checks a CI job runs over a monorepo, all four independent of each +# other. This is the shape chains are best at: the build takes as long as +# its longest check instead of as long as all of them. +scenario 'CI checks, four of them' \ + 'lint:1' \ + 'typecheck:3' \ + 'unit tests:5' \ + 'build:3' + +# The same checks, with the lint failing. In order, the failure is found +# only once everything ahead of it has run, and where that is depends on +# where the failing step sits in the script; in chains it is found as soon +# as it happens, whatever else is still going. +scenario 'A failing lint' \ + 'unit tests:5' \ + 'lint:1!' + +# One step much longer than the rest, which is where the gain runs out: the +# build can never finish before its longest chain does, so the most chains +# can do is hide everything else behind it. +scenario 'One dominant step' \ + 'npm run build:6' \ + 'composer install:3' \ + 'php artisan migrate:1' + +_row '--------' '--------' '---------' '-------' +printf '\neight empty chains: %s\n' "$(_secs "$(_overhead)")" + +case $_slower in +'') ;; +*) + printf '\nnot faster in chains than in order:%s\n' "$_slower" >&2 + exit 1 + ;; +esac