From aa9de38458017777fb186bf165a72750254185aa Mon Sep 17 00:00:00 2001 From: Chemaclass Date: Tue, 2 Jun 2026 17:23:01 +0200 Subject: [PATCH] feat(cli): add --profile flag to report slowest tests Records each test's wall-clock duration to a temp file when --profile (or BASHUNIT_PROFILE=true) is set, then prints the slowest tests sorted descending after the summary. Count is configurable via BASHUNIT_PROFILE_COUNT (default 10). Append-only temp file aggregates correctly across the subshells spawned by parallel runs. Closes #678 --- .env.example | 2 ++ CHANGELOG.md | 3 ++ docs/command-line.md | 33 ++++++++++++++++++++++ docs/configuration.md | 18 ++++++++++++ src/console_header.sh | 1 + src/console_results.sh | 27 ++++++++++++++++++ src/env.sh | 9 ++++++ src/main.sh | 10 +++++++ src/runner.sh | 17 ++++++++++++ tests/acceptance/bashunit_profile_test.sh | 34 +++++++++++++++++++++++ 10 files changed, 154 insertions(+) create mode 100644 tests/acceptance/bashunit_profile_test.sh diff --git a/.env.example b/.env.example index 12ff3d33..372606bc 100644 --- a/.env.example +++ b/.env.example @@ -24,6 +24,8 @@ BASHUNIT_SHOW_SKIPPED= # Default: false (show skipped test details) BASHUNIT_SHOW_INCOMPLETE= # Default: false (show incomplete test details) BASHUNIT_FAILURES_ONLY= # Default: false (only show failures) BASHUNIT_FAIL_ON_RISKY= # Default: false (treat no-assertion tests as failed) +BASHUNIT_PROFILE= # Default: false (report slowest tests after a run) +BASHUNIT_PROFILE_COUNT= # Default: 10 (how many slowest tests to report) BASHUNIT_NO_COLOR= # Default: false (disable colors) #─────────────────────────────────────────────────────────────────────────────── diff --git a/CHANGELOG.md b/CHANGELOG.md index b0151b2a..564249d9 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,6 +2,9 @@ ## Unreleased +### Added +- `--profile` reports the slowest tests after a run (count via `BASHUNIT_PROFILE_COUNT`, default 10); works in sequential and parallel mode (#678) + ### Fixed - `bashunit learn` and coverage now create temp directories via `mktemp -d` (no predictable PID-based paths under `/tmp`) - `bashunit::parallel::cleanup` refuses to `rm -rf` a `TEMP_DIR_PARALLEL_TEST_SUITE` whose path is not under `*/bashunit/parallel/*`, preventing accidental wipes from env overrides diff --git a/docs/command-line.md b/docs/command-line.md index 055a2338..8f3252aa 100644 --- a/docs/command-line.md +++ b/docs/command-line.md @@ -78,6 +78,7 @@ bashunit test tests/ --parallel --simple | `--no-output` | Suppress all output | | `--failures-only` | Only show failures | | `--fail-on-risky` | Treat risky tests (no assertions) as failures | +| `--profile` | Report the slowest tests after a run | | `--no-progress` | Suppress real-time progress, show only summary | | `--show-output` | Show test output on failure (default) | | `--no-output-on-failure` | Hide test output on failure | @@ -394,6 +395,38 @@ bashunit test tests/ --no-output-on-failure ``` ::: +### Profile + +> `bashunit test --profile` + +Report the slowest tests after a run. Each test's wall-clock duration is recorded +and, once the run finishes, the slowest ones are printed sorted from slowest to +fastest. Works in both sequential and parallel mode. + +The number of entries shown defaults to `10` and can be changed with the +`BASHUNIT_PROFILE_COUNT` environment variable. + +::: code-group +```bash [Example] +bashunit test tests/ --profile +``` +```[Output] +Tests: 10 passed, 10 total +Assertions: 25 passed, 25 total + + All tests passed + +Slowest tests: + 1.20s test_slow_database_query (tests/integration_test.sh) + 340ms test_http_client_timeout (tests/http_test.sh) + 12ms test_parse_config (tests/unit/config_test.sh) +Time taken: 1.60s +``` +```bash [Custom count] +BASHUNIT_PROFILE_COUNT=3 bashunit test tests/ --profile +``` +::: + ### No Progress > `bashunit test --no-progress` diff --git a/docs/configuration.md b/docs/configuration.md index fbed64ce..c3dd313b 100644 --- a/docs/configuration.md +++ b/docs/configuration.md @@ -386,6 +386,24 @@ BASHUNIT_FAIL_ON_RISKY=true ``` ::: +## Profile + +> `BASHUNIT_PROFILE=true|false` · `BASHUNIT_PROFILE_COUNT=` + +Report the slowest tests after a run. `false` by default; `BASHUNIT_PROFILE_COUNT` defaults to `10`. + +When enabled, each test's duration is recorded and the slowest ones are printed at the end, +sorted from slowest to fastest. `BASHUNIT_PROFILE_COUNT` limits how many are shown. + +Similar as using `--profile` option on the [command line](/command-line#profile). + +::: code-group +```bash [Example] +BASHUNIT_PROFILE=true +BASHUNIT_PROFILE_COUNT=5 +``` +::: + ## Failures only > `BASHUNIT_FAILURES_ONLY=true|false` diff --git a/src/console_header.sh b/src/console_header.sh index d7389c87..cb0272bb 100644 --- a/src/console_header.sh +++ b/src/console_header.sh @@ -123,6 +123,7 @@ Options: --no-output Suppress all output --failures-only Only show failures (suppress passed/skipped/incomplete) --fail-on-risky Treat risky tests (no assertions) as failures + --profile Report the slowest tests (count: BASHUNIT_PROFILE_COUNT, default 10) --no-progress Suppress real-time progress, show only final results --show-output Show test output on failure (default: enabled) --no-output-on-failure Hide test output on failure diff --git a/src/console_results.sh b/src/console_results.sh index 20d1291c..ddee8c53 100644 --- a/src/console_results.sh +++ b/src/console_results.sh @@ -432,6 +432,33 @@ function bashunit::console_results::print_failing_tests_and_reset() { fi } +## +# Prints the slowest tests recorded during the run, sorted by duration +# descending, limited to BASHUNIT_PROFILE_COUNT entries. Reads the +# tab-separated records appended to PROFILE_OUTPUT_PATH (duration, name, file). +## +function bashunit::console_results::print_profile_and_reset() { + if [ ! -s "$PROFILE_OUTPUT_PATH" ]; then + rm -f "$PROFILE_OUTPUT_PATH" + return + fi + + local count="${BASHUNIT_PROFILE_COUNT:-10}" + + echo -e "\n${_BASHUNIT_COLOR_BOLD}Slowest tests:${_BASHUNIT_COLOR_DEFAULT}" + + local duration name file formatted + # -rn on the first (numeric) field; head limits to the requested count. + while IFS=$'\t' read -r duration name file; do + formatted=$(bashunit::console_results::format_duration "$duration") + printf " %s\t%s (%s)\n" "$formatted" "$name" "$file" + done < <(sort -t"$(printf '\t')" -k1 -rn "$PROFILE_OUTPUT_PATH" | head -n "$count") + + echo "" + + rm -f "$PROFILE_OUTPUT_PATH" +} + function bashunit::console_results::print_skipped_tests_and_reset() { if [ -s "$SKIPPED_OUTPUT_PATH" ] && bashunit::env::is_show_skipped_enabled; then local total_skipped diff --git a/src/env.sh b/src/env.sh index 8a1ab14f..c762ff4d 100644 --- a/src/env.sh +++ b/src/env.sh @@ -68,6 +68,8 @@ _BASHUNIT_DEFAULT_SHOW_OUTPUT_ON_FAILURE="true" _BASHUNIT_DEFAULT_NO_PROGRESS="false" _BASHUNIT_DEFAULT_OUTPUT_FORMAT="" _BASHUNIT_DEFAULT_FAIL_ON_RISKY="false" +_BASHUNIT_DEFAULT_PROFILE="false" +_BASHUNIT_DEFAULT_PROFILE_COUNT="10" : "${BASHUNIT_PARALLEL_RUN:=${PARALLEL_RUN:=$_BASHUNIT_DEFAULT_PARALLEL_RUN}}" : "${BASHUNIT_PARALLEL_JOBS:=0}" @@ -91,6 +93,8 @@ _BASHUNIT_DEFAULT_FAIL_ON_RISKY="false" : "${BASHUNIT_NO_PROGRESS:=${NO_PROGRESS:=$_BASHUNIT_DEFAULT_NO_PROGRESS}}" : "${BASHUNIT_OUTPUT_FORMAT:=${OUTPUT_FORMAT:=$_BASHUNIT_DEFAULT_OUTPUT_FORMAT}}" : "${BASHUNIT_FAIL_ON_RISKY:=${FAIL_ON_RISKY:=$_BASHUNIT_DEFAULT_FAIL_ON_RISKY}}" +: "${BASHUNIT_PROFILE:=${PROFILE:=$_BASHUNIT_DEFAULT_PROFILE}}" +: "${BASHUNIT_PROFILE_COUNT:=${PROFILE_COUNT:=$_BASHUNIT_DEFAULT_PROFILE_COUNT}}" # Support NO_COLOR standard (https://no-color.org) if [ -n "${NO_COLOR:-}" ]; then BASHUNIT_NO_COLOR="true" @@ -220,6 +224,10 @@ function bashunit::env::is_fail_on_risky_enabled() { [ "$BASHUNIT_FAIL_ON_RISKY" = "true" ] } +function bashunit::env::is_profile_enabled() { + [ "$BASHUNIT_PROFILE" = "true" ] +} + function bashunit::env::active_internet_connection() { if [ "${BASHUNIT_NO_NETWORK:-}" = "true" ]; then return 1 @@ -313,6 +321,7 @@ FAILURES_OUTPUT_PATH=$("$MKTEMP") SKIPPED_OUTPUT_PATH=$("$MKTEMP") INCOMPLETE_OUTPUT_PATH=$("$MKTEMP") RISKY_OUTPUT_PATH=$("$MKTEMP") +PROFILE_OUTPUT_PATH=$("$MKTEMP") # Initialize temp directory once at startup for performance BASHUNIT_TEMP_DIR="${TMPDIR:-/tmp}/bashunit/tmp" diff --git a/src/main.sh b/src/main.sh index c55ad730..af148a10 100644 --- a/src/main.sh +++ b/src/main.sh @@ -126,6 +126,9 @@ function bashunit::main::cmd_test() { --fail-on-risky) export BASHUNIT_FAIL_ON_RISKY=true ;; + --profile) + export BASHUNIT_PROFILE=true + ;; --show-output) export BASHUNIT_SHOW_OUTPUT_ON_FAILURE=true ;; @@ -692,6 +695,10 @@ function bashunit::main::exec_tests() { bashunit::console_results::render_result exit_code=$? + if bashunit::env::is_profile_enabled; then + bashunit::console_results::print_profile_and_reset + fi + if [ -n "$BASHUNIT_LOG_JUNIT" ]; then bashunit::reports::generate_junit_xml "$BASHUNIT_LOG_JUNIT" fi @@ -789,6 +796,9 @@ function bashunit::main::handle_stop_on_failure_sync() { bashunit::console_results::print_incomplete_tests_and_reset bashunit::console_results::print_skipped_tests_and_reset bashunit::console_results::render_result + if bashunit::env::is_profile_enabled; then + bashunit::console_results::print_profile_and_reset + fi bashunit::cleanup_script_temp_files if bashunit::parallel::is_enabled; then bashunit::parallel::cleanup diff --git a/src/runner.sh b/src/runner.sh index b65eff41..11878877 100755 --- a/src/runner.sh +++ b/src/runner.sh @@ -129,6 +129,19 @@ function bashunit::runner::format_subshell_output() { _BASHUNIT_RUNNER_OUTPUT_OUT=$line } +## +# Appends a profiling record (duration, test name, file) to PROFILE_OUTPUT_PATH. +# Uses a tab-separated, append-only line so it aggregates correctly across the +# subshells spawned by parallel runs. +# Arguments: $1 duration (ms), $2 test name, $3 test file +## +function bashunit::runner::record_profile() { + local duration=$1 + local test_name=$2 + local test_file=$3 + printf '%s\t%s\t%s\n' "$duration" "$test_name" "$test_file" >>"$PROFILE_OUTPUT_PATH" +} + function bashunit::runner::detect_runtime_error() { local runtime_output=$1 case "$runtime_output" in @@ -834,6 +847,10 @@ function bashunit::runner::run_test() { local duration_ns=$((end_time - start_time)) local duration=$((duration_ns / 1000000)) + if bashunit::env::is_profile_enabled; then + bashunit::runner::record_profile "$duration" "$interpolated_fn_name" "$test_file" + fi + if bashunit::env::is_verbose_enabled; then bashunit::runner::print_verbose_test_summary \ "$test_file" "$fn_name" "$duration" "$test_execution_result" diff --git a/tests/acceptance/bashunit_profile_test.sh b/tests/acceptance/bashunit_profile_test.sh new file mode 100644 index 00000000..b0d68cc3 --- /dev/null +++ b/tests/acceptance/bashunit_profile_test.sh @@ -0,0 +1,34 @@ +#!/usr/bin/env bash +set -euo pipefail + +function set_up_before_script() { + TEST_ENV_FILE="tests/acceptance/fixtures/.env.default" +} + +function test_profile_flag_prints_slowest_tests_header() { + local test_file=./tests/acceptance/fixtures/test_bashunit_when_a_test_passes.sh + + local output + output="$(./bashunit --no-parallel --env "$TEST_ENV_FILE" --profile "$test_file")" + + assert_contains "Slowest tests" "$output" + assert_contains "test_assert_same" "$output" +} + +function test_profile_flag_is_off_by_default() { + local test_file=./tests/acceptance/fixtures/test_bashunit_when_a_test_passes.sh + + local output + output="$(./bashunit --no-parallel --env "$TEST_ENV_FILE" "$test_file")" + + assert_not_contains "Slowest tests" "$output" +} + +function test_profile_flag_works_in_parallel() { + local test_file=./tests/acceptance/fixtures/test_bashunit_when_a_test_passes.sh + + local output + output="$(./bashunit --parallel --env "$TEST_ENV_FILE" --profile "$test_file")" + + assert_contains "Slowest tests" "$output" +}