perf(runner): auto-skip per-test timing when the clock forks an interpreter

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

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

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`)

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

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
 

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() {

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"

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"

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"
+}

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
 }

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"

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"; }