perf(console): read the clock and pad a line through return slots

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 `<file>:<line>` that only a failure message and a report row ever use. It is resolved on demand now (#1346)
 - A standalone `bashunit assert <fn> …` 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)

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

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"

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

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
 }

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

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