diff --git a/CHANGELOG.md b/CHANGELOG.md index 859ff94e..c0d784d0 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -3,6 +3,7 @@ ## Unreleased ### Changed +- Per-test execution time now defaults to `auto` (`BASHUNIT_SHOW_EXECUTION_TIME=true|false|auto`): shown when the shell has a fork-free clock (Bash 5.0+, GNU `date`), hidden when measuring would fork an interpreter (e.g. Bash 3.2 on macOS, which falls back to `perl`). This removes ~2 `perl` forks per test on those shells. `--profile`, `--verbose`, reports, and `=true` still measure. See `adrs/adr-008-auto-skip-per-test-timing.md` (#765) - Faster test execution: each test file's data-provider annotations are scanned once and cached, replacing a per-test `grep`+`sed` probe with a pure-bash lookup (no behaviour change) (#763) ## [0.41.0](https://github.com/TypedDevs/bashunit/compare/0.40.0...0.41.0) - 2026-07-11 diff --git a/adrs/adr-008-auto-skip-per-test-timing.md b/adrs/adr-008-auto-skip-per-test-timing.md new file mode 100644 index 00000000..b39e641e --- /dev/null +++ b/adrs/adr-008-auto-skip-per-test-timing.md @@ -0,0 +1,74 @@ +# Auto-skip per-test timing when the clock forks an interpreter + +* Status: accepted +* Date: 2026-07-11 + +## Context and Problem Statement + +Every test measures its own wall-clock duration: `bashunit::runner::run_test` reads `bashunit::clock::now` once before and once after the test body. On a shell with a native high-resolution clock (`EPOCHREALTIME`, Bash 5.0+) these reads are fork-free. On the default macOS shell (Bash 3.2) there is no `EPOCHREALTIME`, and BSD `date` has no `%N`, so `bashunit::clock::now` falls through to forking a `perl` interpreter for every read. + +That is two `perl` process spawns per test. On a ~1200-test suite it is ~2400 `perl` forks and the single largest external cost measured in the runner (~40% of per-test framework overhead on a stock Mac), and it compounds inside every nested `./bashunit` invocation in the acceptance suite. + +The duration is only ever consumed by four things: the per-test execution-time column, `--profile`, `--verbose`, and the per-test `duration` recorded in report files (JUnit/JSON/HTML). When none of those is active, the suite pays the `perl` cost and then discards the result. + +## Decision Drivers + +* The largest available speedup on the framework's own reference platform (Bash 3.2 macOS). +* Bash 3.0+ compatibility: on Bash < 5 there is no way to read a sub-second clock without a subprocess, so the only way to remove the fork is to not measure. +* No behavior change on shells with a cheap clock (Bash 5, Linux CI): timing there is free, so nothing should change. +* Anything that genuinely needs the number (`--profile`, `--verbose`, a report, or an explicit opt-in) must still get an accurate measurement. +* Must be deterministic enough to pin in unit tests. + +## Considered Options + +1. **Auto-skip based on clock cost** — classify the resolved clock impl as expensive (forks an interpreter: perl/python/node/powershell) or cheap (shell/date). Default per-test timing to `auto`: measure only when a consumer needs it, and on an expensive clock treat display as off unless explicitly enabled. Skip both clock reads when nothing consumes the duration. +2. **Persistent timestamp co-process** — spawn one long-lived `perl` reading timestamps on demand over a FIFO, so the whole suite pays one fork instead of two per test. +3. **Do nothing** — keep measuring unconditionally; accept the `perl` cost. +4. **Always drop per-test timing** — remove per-test measurement on every platform for output consistency. + +## Decision Outcome + +Chosen option: **Option 1 (auto-skip based on clock cost)**. + +`bashunit::clock::is_expensive` reports whether the resolved impl forks an interpreter. `BASHUNIT_SHOW_EXECUTION_TIME` gains an `auto` value and becomes the default: `auto` shows per-test times when the clock is cheap and hides them when it is expensive. `bashunit::runner::needs_test_duration` is true when `--profile`, `--verbose`, any report, or a resolved-on execution-time display needs the number; `run_test` reads the clock only then. On Bash 5 / Linux the clock is cheap, `auto` resolves to shown, and behavior is identical to before. On Bash 3.2 a plain `./bashunit tests/` no longer forks `perl` per test. + +### Positive Consequences + +* Removes ~2400 `perl` forks from a default suite run on Bash 3.2; largest single speedup in the perf series. +* Zero behavior change on cheap-clock platforms (CI stays byte-identical). +* Opt-in path is intact: `--profile`, `--verbose`, `--report-*`/`--log-junit`, or `BASHUNIT_SHOW_EXECUTION_TIME=true` all force accurate timing back on. + +### Negative Consequences + +* On Bash 3.2 macOS, a default run no longer shows per-test milliseconds. Users who want them set `BASHUNIT_SHOW_EXECUTION_TIME=true` (and pay the `perl` cost). This is a visible default change, documented in the CHANGELOG and docs. +* `needs_test_duration` must enumerate every duration consumer; adding a new consumer without updating the predicate would make it read a zero duration. Mitigated by keeping all consumers behind the single predicate and testing it. + +## Pros and Cons of the Options + +### Option 1: Auto-skip based on clock cost (chosen) + +* Good, because it removes the fork entirely on the affected platform rather than reducing it. +* Good, because cheap-clock platforms are provably unaffected (the predicate resolves to "measure"). +* Good, because the classification is a `case` on a cached global — no per-test cost. +* Bad, because it changes default output on Bash 3.2. + +### Option 2: Persistent timestamp co-process over a FIFO + +* Good, because it preserves per-test timing everywhere at one fork per suite. +* Bad, because concurrent readers under `--parallel` race on the FIFO and stock macOS has no portable `flock` to serialize them. +* Bad, because co-process lifecycle and cleanup (crash, SIGINT, timeout kills) add real complexity to the hot path for a feature most default runs do not use. + +### Option 3: Do nothing + +* Good, because zero risk and per-test times always shown. +* Bad, because it forfeits the largest speedup on the reference platform. + +### Option 4: Always drop per-test timing + +* Good, because output is consistent across platforms. +* Bad, because it discards timing that is free on Bash 5 / Linux, a needless regression there. + +## Links + +* Issue #765 +* Related perf series: #762, #763, #764, #766 diff --git a/docs/configuration.md b/docs/configuration.md index c01ea42b..3e233f4b 100644 --- a/docs/configuration.md +++ b/docs/configuration.md @@ -264,9 +264,11 @@ BASHUNIT_HEADER_ASCII_ART=true ## Show execution time -> `BASHUNIT_SHOW_EXECUTION_TIME=true|false` +> `BASHUNIT_SHOW_EXECUTION_TIME=true|false|auto` -Specify if you want to display the execution time after running **bashunit**. `true` by default. +Specify if you want to display the per-test execution time after running **bashunit**. `auto` by default. + +`auto` shows per-test times when the shell has a fork-free high-resolution clock (Bash 5.0+ via `EPOCHREALTIME`, or GNU `date`), and hides them when measuring a test would require forking an interpreter (for example the default Bash 3.2 on macOS, which falls back to `perl`). This keeps a plain run fast on those shells. Set `true` to always measure and show per-test times (paying that cost), or `false` to always hide them. `--profile`, `--verbose`, and the `--report-*`/`--log-junit` reports always measure regardless of this setting. The time format adapts based on duration: - Under 1 second: displayed in milliseconds (e.g., `14 ms`) diff --git a/src/clock.sh b/src/clock.sh index f3e8cb8b..c516e3bd 100644 --- a/src/clock.sh +++ b/src/clock.sh @@ -79,6 +79,16 @@ function bashunit::clock::_choose_impl() { return 1 } +# Returns 0 when the chosen clock impl forks an interpreter (perl/python/node/ +# powershell), so callers can skip optional timing to avoid a per-read fork (#765). +function bashunit::clock::is_expensive() { + [ -n "$_BASHUNIT_CLOCK_NOW_IMPL" ] || bashunit::clock::_choose_impl >/dev/null 2>&1 || true + case "$_BASHUNIT_CLOCK_NOW_IMPL" in + perl | python | node | powershell) return 0 ;; + *) return 1 ;; + esac +} + function bashunit::clock::now() { if [ -z "$_BASHUNIT_CLOCK_NOW_IMPL" ]; then bashunit::clock::_choose_impl || return 1 diff --git a/src/console_results.sh b/src/console_results.sh index 1df9f03a..f4f99b36 100644 --- a/src/console_results.sh +++ b/src/console_results.sh @@ -133,7 +133,7 @@ function bashunit::console_results::render_result() { } function bashunit::console_results::print_execution_time() { - if ! bashunit::env::is_show_execution_time_enabled; then + if ! bashunit::env::is_total_execution_time_enabled; then return fi diff --git a/src/env.sh b/src/env.sh index 7e1c646e..37331925 100644 --- a/src/env.sh +++ b/src/env.sh @@ -100,7 +100,8 @@ _BASHUNIT_DEFAULT_SHOW_HEADER="true" _BASHUNIT_DEFAULT_HEADER_ASCII_ART="false" _BASHUNIT_DEFAULT_SIMPLE_OUTPUT="false" _BASHUNIT_DEFAULT_STOP_ON_FAILURE="false" -_BASHUNIT_DEFAULT_SHOW_EXECUTION_TIME="true" +# "auto" shows per-test times only when the clock is fork-free (#765). +_BASHUNIT_DEFAULT_SHOW_EXECUTION_TIME="auto" _BASHUNIT_DEFAULT_VERBOSE="false" _BASHUNIT_DEFAULT_BENCH_MODE="false" _BASHUNIT_DEFAULT_NO_OUTPUT="false" @@ -248,7 +249,18 @@ function bashunit::env::is_stop_on_failure_enabled() { } function bashunit::env::is_show_execution_time_enabled() { - [ "$BASHUNIT_SHOW_EXECUTION_TIME" = "true" ] + case "$BASHUNIT_SHOW_EXECUTION_TIME" in + true) return 0 ;; + auto) ! bashunit::clock::is_expensive ;; + *) return 1 ;; + esac +} + +# The total "Time taken" footer costs two clock reads per run (negligible), so it +# stays visible in "auto" mode even when per-test timing is skipped; only an +# explicit "false" hides it (#765). +function bashunit::env::is_total_execution_time_enabled() { + [ "$BASHUNIT_SHOW_EXECUTION_TIME" != "false" ] } function bashunit::env::is_dev_mode_enabled() { diff --git a/src/reports.sh b/src/reports.sh index 9a479a1d..dcbddc40 100755 --- a/src/reports.sh +++ b/src/reports.sh @@ -33,15 +33,18 @@ function bashunit::reports::add_test_failed() { bashunit::reports::add_test "$1" "$2" "$3" "$4" "failed" "$5" } +# Returns 0 when any report output is requested. +function bashunit::reports::is_enabled() { + [ -n "${BASHUNIT_LOG_JUNIT:-}" ] || + [ -n "${BASHUNIT_REPORT_HTML:-}" ] || + [ -n "${BASHUNIT_LOG_GHA:-}" ] || + [ -n "${BASHUNIT_REPORT_TAP:-}" ] || + [ -n "${BASHUNIT_REPORT_JSON:-}" ] +} + function bashunit::reports::add_test() { # Skip tracking when no report output is requested - { - [ -n "${BASHUNIT_LOG_JUNIT:-}" ] || - [ -n "${BASHUNIT_REPORT_HTML:-}" ] || - [ -n "${BASHUNIT_LOG_GHA:-}" ] || - [ -n "${BASHUNIT_REPORT_TAP:-}" ] || - [ -n "${BASHUNIT_REPORT_JSON:-}" ] - } || return 0 + bashunit::reports::is_enabled || return 0 local file="$1" local test_name="$2" diff --git a/src/runner.sh b/src/runner.sh index c26c26d1..1a86e34d 100755 --- a/src/runner.sh +++ b/src/runner.sh @@ -1037,8 +1037,19 @@ function bashunit::runner::run_with_timeout() { rm -f "$out_file" "$marker_file" } +# Per-test duration is consumed by --profile, --verbose, report files, and the +# execution-time display. When none are active we can skip the clock reads, +# which matters when the clock forks an interpreter (#765). +function bashunit::runner::needs_test_duration() { + bashunit::env::is_profile_enabled && return 0 + bashunit::env::is_verbose_enabled && return 0 + bashunit::reports::is_enabled && return 0 + bashunit::env::is_show_execution_time_enabled && return 0 + return 1 +} + function bashunit::runner::run_test() { - local start_time + local start_time=0 local test_file="$1" shift @@ -1066,12 +1077,14 @@ function bashunit::runner::run_test() { local retry_max retry_max=$(bashunit::env::retry_count) local retries_used=0 + local measure_duration=false + bashunit::runner::needs_test_duration && measure_duration=true # Retry wraps ONLY execution: a failed attempt is judged from its encoded # result without committing, so the parse/report/counter path below still runs # exactly once (on the final attempt) and nothing is double-counted. Each fork # in --parallel retries itself before writing its single .result file. while :; do - start_time=$(bashunit::clock::now) + [ "$measure_duration" = true ] && start_time=$(bashunit::clock::now) if bashunit::env::is_test_timeout_enabled; then bashunit::runner::run_with_timeout "$test_file" "$fn_name" "$@" test_execution_result="$_BASHUNIT_RUNNER_EXEC_OUT" @@ -1098,9 +1111,12 @@ function bashunit::runner::run_test() { # Closes FD 3, which was used temporarily to hold the original stdout. exec 3>&- - local end_time=$(bashunit::clock::now) - local duration_ns=$((end_time - start_time)) - local duration=$((duration_ns / 1000000)) + local duration=0 + if [ "$measure_duration" = true ]; then + local end_time + end_time=$(bashunit::clock::now) + duration=$(((end_time - start_time) / 1000000)) + fi if bashunit::env::is_profile_enabled; then bashunit::runner::record_profile "$duration" "$interpolated_fn_name" "$test_file" diff --git a/tests/unit/clock_test.sh b/tests/unit/clock_test.sh index 86f5befb..d72e2b9d 100644 --- a/tests/unit/clock_test.sh +++ b/tests/unit/clock_test.sh @@ -152,3 +152,29 @@ function test_runtime_in_milliseconds_when_empty_time() { assert_empty "$(bashunit::clock::total_runtime_in_milliseconds)" } + +function test_clock_is_expensive_true_for_interpreter_impls() { + local impl result="" + for impl in perl python node powershell; do + _BASHUNIT_CLOCK_NOW_IMPL="$impl" + if bashunit::clock::is_expensive; then + result="$result $impl:yes" + else + result="$result $impl:no" + fi + done + assert_same " perl:yes python:yes node:yes powershell:yes" "$result" +} + +function test_clock_is_expensive_false_for_native_impls() { + local impl result="" + for impl in shell date date-seconds; do + _BASHUNIT_CLOCK_NOW_IMPL="$impl" + if bashunit::clock::is_expensive; then + result="$result $impl:yes" + else + result="$result $impl:no" + fi + done + assert_same " shell:no date:no date-seconds:no" "$result" +} diff --git a/tests/unit/console_results_test.sh b/tests/unit/console_results_test.sh index 051a8ace..7e9cfed3 100644 --- a/tests/unit/console_results_test.sh +++ b/tests/unit/console_results_test.sh @@ -602,7 +602,7 @@ function test_print_successful_test_output_no_args() { assert_matches \ "✓ Passed.*$test_name.*12ms" \ - "$(bashunit::console_results::print_successful_test "$test_name" "12")" + "$(BASHUNIT_SHOW_EXECUTION_TIME=true bashunit::console_results::print_successful_test "$test_name" "12")" export BASHUNIT_SIMPLE_OUTPUT=$original_simple_output } @@ -617,7 +617,7 @@ function test_print_successful_test_output_with_args() { assert_matches \ "✓ Passed.*$test_name \('$data'\).*12ms" \ - "$(bashunit::console_results::print_successful_test "$test_name" "12" "$data")" + "$(BASHUNIT_SHOW_EXECUTION_TIME=true bashunit::console_results::print_successful_test "$test_name" "12" "$data")" export BASHUNIT_SIMPLE_OUTPUT=$original_simple_output } @@ -631,7 +631,7 @@ function test_print_successful_test_output_in_seconds() { assert_matches \ "✓ Passed.*$test_name.*5.12s" \ - "$(bashunit::console_results::print_successful_test "$test_name" "5123")" + "$(BASHUNIT_SHOW_EXECUTION_TIME=true bashunit::console_results::print_successful_test "$test_name" "5123")" export BASHUNIT_SIMPLE_OUTPUT=$original_simple_output } @@ -645,7 +645,7 @@ function test_print_successful_test_output_in_minutes() { assert_matches \ "✓ Passed.*$test_name.*1m 3s" \ - "$(bashunit::console_results::print_successful_test "$test_name" "63000")" + "$(BASHUNIT_SHOW_EXECUTION_TIME=true bashunit::console_results::print_successful_test "$test_name" "63000")" export BASHUNIT_SIMPLE_OUTPUT=$original_simple_output } @@ -659,7 +659,7 @@ function test_print_successful_test_output_in_minutes_exact() { assert_matches \ "✓ Passed.*$test_name.*2m 0s" \ - "$(bashunit::console_results::print_successful_test "$test_name" "120000")" + "$(BASHUNIT_SHOW_EXECUTION_TIME=true bashunit::console_results::print_successful_test "$test_name" "120000")" export BASHUNIT_SIMPLE_OUTPUT=$original_simple_output } diff --git a/tests/unit/env_test.sh b/tests/unit/env_test.sh index 64c773ae..43912040 100644 --- a/tests/unit/env_test.sh +++ b/tests/unit/env_test.sh @@ -71,6 +71,40 @@ function provide_boolean_flags_false() { bashunit::data_set "BASHUNIT_COVERAGE" "bashunit::env::is_coverage_enabled" } +function _show_execution_time_state() { + local value="$1" + local impl="$2" + local original="$BASHUNIT_SHOW_EXECUTION_TIME" + local original_impl="$_BASHUNIT_CLOCK_NOW_IMPL" + export BASHUNIT_SHOW_EXECUTION_TIME="$value" + _BASHUNIT_CLOCK_NOW_IMPL="$impl" + + local state="disabled" + if bashunit::env::is_show_execution_time_enabled; then + state="enabled" + fi + + export BASHUNIT_SHOW_EXECUTION_TIME="$original" + _BASHUNIT_CLOCK_NOW_IMPL="$original_impl" + echo "$state" +} + +function test_show_execution_time_auto_is_enabled_when_clock_is_cheap() { + assert_same "enabled" "$(_show_execution_time_state "auto" "shell")" +} + +function test_show_execution_time_auto_is_disabled_when_clock_is_expensive() { + assert_same "disabled" "$(_show_execution_time_state "auto" "perl")" +} + +function test_show_execution_time_true_is_enabled_even_when_clock_is_expensive() { + assert_same "enabled" "$(_show_execution_time_state "true" "perl")" +} + +function test_show_execution_time_false_is_disabled_even_when_clock_is_cheap() { + assert_same "disabled" "$(_show_execution_time_state "false" "shell")" +} + function test_is_dev_mode_enabled_when_dev_log_set() { local original="$BASHUNIT_DEV_LOG" export BASHUNIT_DEV_LOG="/tmp/dev.log" diff --git a/tests/unit/reports_test.sh b/tests/unit/reports_test.sh index 3b454640..2994f5cd 100644 --- a/tests/unit/reports_test.sh +++ b/tests/unit/reports_test.sh @@ -37,6 +37,28 @@ function tear_down() { unset BASHUNIT_LOG_GHA } +function _reports_is_enabled_state() { + local state="disabled" + if bashunit::reports::is_enabled; then + state="enabled" + fi + echo "$state" +} + +function test_reports_is_enabled_false_when_no_report_configured() { + unset BASHUNIT_LOG_JUNIT BASHUNIT_REPORT_HTML BASHUNIT_LOG_GHA BASHUNIT_REPORT_TAP BASHUNIT_REPORT_JSON + assert_same "disabled" "$(_reports_is_enabled_state)" +} + +function test_reports_is_enabled_true_when_a_report_is_configured() { + unset BASHUNIT_LOG_JUNIT BASHUNIT_REPORT_HTML BASHUNIT_LOG_GHA BASHUNIT_REPORT_TAP BASHUNIT_REPORT_JSON + export BASHUNIT_REPORT_JSON="$_TEMP_OUTPUT_FILE" + local state + state="$(_reports_is_enabled_state)" + unset BASHUNIT_REPORT_JSON + assert_same "enabled" "$state" +} + # Mock functions for report generation tests function _mock_state_functions() { function bashunit::state::get_tests_passed() { echo "5"; }