diff --git a/CHANGELOG.md b/CHANGELOG.md index f71a4454..70728ba8 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -3,6 +3,7 @@ ## Unreleased ### Changed +- Performance: a file defining `set_up_before_script` or `tear_down_after_script` costs about 5.6ms less on Bash 3.2, and a test rendered with `--show-execution-time` about 0.74ms less. Four clock reads per file and the per-test padding still went through a capture subshell, next to return-slot variants that were already there (#1348) - Performance: startup is faster on suites of plain test files. Printing "Running N tests" sourced every file a second time and re-ran every data provider before the run began. A file whose functions the provider scan can already see is counted from that scan instead: over this repo's 241 files the counting pass went from 1.72s to 1.51s, and 124 of them no longer source or run a provider twice. Files with a data provider, a heredoc, a multi-line string, an `eval`, a nested `source` or a conditional definition keep the old path, so the count can never disagree with the run (#1347) - Performance: a sequential run is about 0.7ms faster per test — a 500-test file went from 2.75s to 2.40s on macOS arm64, bash 3.2. Every test forked a subshell to read its own definition line, for a `:` that only a failure message and a report row ever use. It is resolved on demand now (#1346) - A standalone `bashunit assert …` no longer reports a source location belonging to another process. Launched from inside a test, it inherited that test's exported location and printed it as its own (#1346) diff --git a/src/console/summary.sh b/src/console/summary.sh index e98f639e..213af0ac 100644 --- a/src/console/summary.sh +++ b/src/console/summary.sh @@ -321,9 +321,9 @@ function bashunit::console_results::print_hook_completed() { line=$(printf "%sā— %s%s" \ "$_BASHUNIT_COLOR_PASSED" "$hook_name" "$_BASHUNIT_COLOR_DEFAULT") - local time_display - time_display=$(bashunit::console_results::format_duration "$duration_ms") + bashunit::console_results::format_duration_to_slot "$duration_ms" + bashunit::str::rpad_to_slot "$line" "$_BASHUNIT_CONSOLE_DURATION_OUT" - printf "%s\n" "$(bashunit::str::rpad "$line" "$time_display")" + printf "%s\n" "$_BASHUNIT_STR_RPAD_OUT" } diff --git a/src/console/test_line.sh b/src/console/test_line.sh index 8a24afb5..d9fb1088 100644 --- a/src/console/test_line.sh +++ b/src/console/test_line.sh @@ -33,7 +33,8 @@ function bashunit::console_results::print_successful_test() { local full_line=$line if bashunit::env::is_show_execution_time_enabled; then bashunit::console_results::format_duration_to_slot "$duration" - full_line="$(bashunit::str::rpad "$line" "$_BASHUNIT_CONSOLE_DURATION_OUT")" + bashunit::str::rpad_to_slot "$line" "$_BASHUNIT_CONSOLE_DURATION_OUT" + full_line=$_BASHUNIT_STR_RPAD_OUT fi bashunit::console_results::print_line "successful" "$full_line" @@ -236,9 +237,9 @@ function bashunit::console_results::print_risky_test() { local full_line=$line if bashunit::env::is_show_execution_time_enabled; then - local time_display - time_display=$(bashunit::console_results::format_duration "$duration") - full_line="$(bashunit::str::rpad "$line" "$time_display")" + bashunit::console_results::format_duration_to_slot "$duration" + bashunit::str::rpad_to_slot "$line" "$_BASHUNIT_CONSOLE_DURATION_OUT" + full_line=$_BASHUNIT_STR_RPAD_OUT fi bashunit::console_results::print_line "risky" "$full_line" diff --git a/src/runner/hooks.sh b/src/runner/hooks.sh index 88ce1f34..ecad23df 100644 --- a/src/runner/hooks.sh +++ b/src/runner/hooks.sh @@ -203,7 +203,8 @@ function bashunit::runner::run_set_up_before_script() { fi local start_time - start_time=$(bashunit::clock::now) + bashunit::clock::now_to_slot + start_time=$_BASHUNIT_CLOCK_NOW_OUT # Enable coverage trap to attribute lines executed during set_up_before_script if [ "${_BASHUNIT_COVERAGE_ON:-0}" = 1 ]; then @@ -220,7 +221,8 @@ function bashunit::runner::run_set_up_before_script() { fi local end_time - end_time=$(bashunit::clock::now) + bashunit::clock::now_to_slot + end_time=$_BASHUNIT_CLOCK_NOW_OUT local duration_ns=$((end_time - start_time)) local duration_ms=$((duration_ns / 1000000)) @@ -454,7 +456,8 @@ function bashunit::runner::run_tear_down_after_script() { fi local start_time - start_time=$(bashunit::clock::now) + bashunit::clock::now_to_slot + start_time=$_BASHUNIT_CLOCK_NOW_OUT # Enable coverage trap to attribute lines executed during tear_down_after_script if [ "${_BASHUNIT_COVERAGE_ON:-0}" = 1 ]; then @@ -471,7 +474,8 @@ function bashunit::runner::run_tear_down_after_script() { fi local end_time - end_time=$(bashunit::clock::now) + bashunit::clock::now_to_slot + end_time=$_BASHUNIT_CLOCK_NOW_OUT local duration_ns=$((end_time - start_time)) local duration_ms=$((duration_ns / 1000000)) diff --git a/src/util/clock.sh b/src/util/clock.sh index b1e56c49..3ec3cca6 100644 --- a/src/util/clock.sh +++ b/src/util/clock.sh @@ -231,5 +231,6 @@ function bashunit::clock::total_runtime_in_milliseconds() { } function bashunit::clock::init() { - _BASHUNIT_START_TIME=$(bashunit::clock::now) + bashunit::clock::now_to_slot + _BASHUNIT_START_TIME=$_BASHUNIT_CLOCK_NOW_OUT } diff --git a/src/util/str.sh b/src/util/str.sh index f221bb17..9215f14c 100644 --- a/src/util/str.sh +++ b/src/util/str.sh @@ -89,7 +89,21 @@ function bashunit::str::strip_ansi() { echo "$_BASHUNIT_STR_STRIPPED_OUT" } -function bashunit::str::rpad() { +# A run of spaces, doubled on demand. Padding is a slice of it, because the +# only fork-free `printf` into a variable is `printf -v`, which is Bash 3.1 +# and this project floors at 3.0. +_BASHUNIT_STR_SPACES=" " +_BASHUNIT_STR_RPAD_OUT="" + +## +# Return-slot variant of rpad: writes the padded line into +# _BASHUNIT_STR_RPAD_OUT, without the trailing newline `$( )` used to strip. +# +# This runs once per passing test wherever per-test timing is on, and the +# function was already fork-free inside -- the capture subshell around it was +# the entire cost (#1348). +## +function bashunit::str::rpad_to_slot() { local left_text="$1" local right_word="$2" local width_padding="${3:-$TERMINAL_WIDTH}" @@ -156,7 +170,18 @@ function bashunit::str::rpad() { remaining_space=0 fi - printf "%s%${remaining_space}s %s\n" "$result_left_text" "" "$right_word" + while [ ${#_BASHUNIT_STR_SPACES} -lt "$remaining_space" ]; do + _BASHUNIT_STR_SPACES="$_BASHUNIT_STR_SPACES$_BASHUNIT_STR_SPACES" + done + + _BASHUNIT_STR_RPAD_OUT="${result_left_text}${_BASHUNIT_STR_SPACES:0:$remaining_space} $right_word" +} + +# Pads and echoes the result. Thin wrapper over the return-slot variant, the +# same shape strip_ansi has over strip_ansi_to_slot. +function bashunit::str::rpad() { + bashunit::str::rpad_to_slot "$@" + echo "$_BASHUNIT_STR_RPAD_OUT" } ## diff --git a/tests/unit/util/str_test.sh b/tests/unit/util/str_test.sh index 562c70d8..9d91038b 100644 --- a/tests/unit/util/str_test.sh +++ b/tests/unit/util/str_test.sh @@ -165,3 +165,47 @@ function test_strip_ansi_to_slot_long_input_matches_short_path() { assert_same "$short_expected" "$_BASHUNIT_STR_STRIPPED_OUT" } + +# rpad runs once per passing test on Bash 5, where per-test timing is on, and +# the `$( )` around it was the whole cost -- the function itself is already +# fork-free (#1348). The slot variant has to produce exactly what the capture +# produced, trailing newline stripped, on every shape rpad handles. +function _rpad_slot_matches_capture() { # $1..$3 = rpad arguments + local captured + captured="$(bashunit::str::rpad "$@")" + bashunit::str::rpad_to_slot "$@" + assert_same "$captured" "$_BASHUNIT_STR_RPAD_OUT" +} + +function test_rpad_to_slot_matches_rpad_for_plain_text() { + _rpad_slot_matches_capture "input" "right-text" 40 +} + +function test_rpad_to_slot_matches_rpad_for_empty_left_text() { + _rpad_slot_matches_capture "" "right-text" 40 +} + +function test_rpad_to_slot_matches_rpad_for_ansi_coloured_text() { + _rpad_slot_matches_capture "$(printf '\033[32mgreen\033[0m text')" "12ms" 40 +} + +# strip_ansi_to_slot changes strategy above 1024 characters, and rpad measures +# the visible width through it. +function test_rpad_to_slot_matches_rpad_for_a_long_string() { + local long="" + local i=0 + while [ $i -lt 130 ]; do + long="${long}0123456789" + i=$((i + 1)) + done + + _rpad_slot_matches_capture "$long" "12ms" 60 +} + +function test_rpad_to_slot_matches_rpad_when_truncating() { + _rpad_slot_matches_capture "a-fairly-long-test-name-that-will-not-fit" "12ms" 20 +} + +function test_rpad_to_slot_matches_rpad_when_width_is_smaller_than_right_word() { + _rpad_slot_matches_capture "input" "right-text" 3 +}