[PATCH] Add support for running test scripts in parallel

[Philippe Altherr <philippe.altherr@xxxxxxxxx>]

This patch implements support for running test scripts in parallel. It also cleans up, enhances, and/or documents a few other test features, like colorization.

Test scripts are run in parallel by setting ZTST_jobs to the desired number of jobs. Each job runs a single test script, records the output to a dedicated file, and writes the run result to a result FIFO. The test runner waits for results in the result FIFO. For each one, it prints the recorded output, records the run result, and restarts a new job if there are still test scripts to run.

Test scripts are run from slowest to fastest based on run times recorded in previous runs. Run times and other temporary files are stored in Test/rundata.tmp, which survives "make check"  but gets deleted by "make clean".

If ZTST_jobs is unset or zero, test scripts are run sequentially.

Here are some run times from my machine, which has 8 CPU threads. All parallel runs could benefit from run times recorded in a previous run.

- ZTST_jobs=00 make check  38.89s user 48.87s system  50% cpu 2:52.89  total
- ZTST_jobs=01 make check  39.81s user 51.08s system  52% cpu 2:53.11  total
- ZTST_jobs=02 make check  39.32s user 50.94s system 102% cpu 1:28.49  total
- ZTST_jobs=03 make check  39.88s user 52.26s system 157% cpu   58.682 total
- ZTST_jobs=04 make check  41.32s user 54.74s system 207% cpu   46.393 total
- ZTST_jobs=05 make check  44.19s user 58.61s system 250% cpu   41.093 total
- ZTST_jobs=06 make check  48.29s user 65.03s system 306% cpu   37.000 total
- ZTST_jobs=07 make check  49.57s user 65.18s system 354% cpu   32.342 total
- ZTST_jobs=08 make check  52.49s user 69.83s system 374% cpu   32.689 total
- ZTST_jobs=09 make check  53.90s user 72.17s system 405% cpu   31.083 total
- ZTST_jobs=10 make check  53.99s user 71.06s system 411% cpu   30.364 total
- ZTST_jobs=11 make check  53.79s user 70.65s system 437% cpu   28.470 total
- ZTST_jobs=12 make check  53.91s user 71.36s system 418% cpu   29.967 total
- ZTST_jobs=13 make check  54.62s user 72.42s system 410% cpu   30.964 total
- ZTST_jobs=14 make check  53.45s user 70.79s system 383% cpu   32.356 total
- ZTST_jobs=16 make check  53.96s user 72.08s system 384% cpu   32.779 total
- ZTST_jobs=20 make check  53.95s user 72.32s system 351% cpu   35.938 total

I get the best results with 9 to 11 jobs, so slightly more jobs than there are CPU threads. One reason for this might be that some of the slowest test scripts spend a lot of time "sleep"ing. Although, the slowest of all scripts, V01zmodload.ztst, doesn't contain any explicit "sleep" but it's definitely idling a lot; its CPU time is less than 10% of the real time. It's not clear to me why that test is so slow and so idle.

There is some garbled output because W01history.ztst writes directly to /dev/tty, which can't be intercepted. I wonder whether that script could be rewritten to use comptest, which iiuc offers a mechanism to test interactive zsh sessions. It's used by the X* zle tests and the Y* completion tests.

- Add support for running test scripts in parallel

  (depends on workers/55185 - Use test script specific run directories)

Philippe

diff --git a/Test/README b/Test/README
index b9d393d7c..bb3d88130 100644
--- a/Test/README
+++ b/Test/README
@@ -21,19 +21,39 @@ more information about the tests being performed with
   ZTST_verbose=1 make check
 (`test' is equivalent to `check') or change 1 to 2 for even more detail.
 
-A test file is usually aborted on the first error.  To continue to the
+A test scripts is usually aborted on the first error.  To continue to the
 end, run with
   ZTST_continue=1 make check
-This can usefully be combined with ZTST_verbose.  The test is always
+This can usefully be combined with ZTST_verbose.  The script is always
 aborted on a syntax error as in that case it is not obvoius how to
 continue.
 
-Individual or groups of tests can be performed with
+Individual or groups of scripts can be run with
   make TESTNUM=C02 check
 or
-  make TESTNUM=C check
-to perform just the test beginning C02, or all tests beginning C,
-respectively.
+  make TESTNUM=A check
+to run just the script beginning with C02, or all scripts beginning with A,
+respectively. Multiple sets of scripts can be run with
+  make TESTNUM="{A,C02,E}" check
+to run all scripts beginning with A, C02, and E.
 
-Instructions on how to write tests are given in B01cd.ztst, which acts as a
-model.
+If ZTST_jobs is non-zero, scripts are run in parallel with up to the
+specified number of parallel jobs. Otherwise, scripts are run sequentially
+in the order specified by TESTNUM. When run in parallel, the slowest
+scripts, based on run time from previous runs, are scheduled first. Run
+times are saved in Test/rundata.tmp/runtimes.zsh. If ZTST_log is non-zero,
+additional run time data is saved in the same directory in runtimes.txt and
+runtests.log.
+
+Unless NO_COLOR is non-empty and `make check' runs in a terminal supporting
+colors, the output is colorized. The use of colors can be forced by setting
+ZTST_failcolor to the color for failure messages. Colors for warning and
+success messages can be specified with ZTST_warncolor and ZTST_passcolor.
+
+Unless ZTST_hide_failing is non-zero, failing scripts are listed in the
+summary. If ZTST_show_skipped or ZTST_show_passing are non-zero, skipped or
+passing scripts are listed, too. Scripts are listed in run order when run
+sequentially and in alphabetical order when run in parallel.
+
+Instructions on how to write scripts are given in B01cd.ztst, which acts as
+a model.
diff --git a/Test/runtests.zsh b/Test/runtests.zsh
index ea862d2b3..7dbe89214 100644
--- a/Test/runtests.zsh
+++ b/Test/runtests.zsh
@@ -7,60 +7,186 @@ emulate zsh
 # protect from catastrophic failure of an individual test.
 # We could probably do that with subshells instead.
 
-integer success=0 failure=0 skipped=0 retval
-typeset resln rule col
-typeset -a ffiles res
-
-# colour to use for ztst failure messages. also used as a signal that colours
-# are available generally
-[[ -t 1 ]] &&
-(( ! $+ZTST_failcolour )) &&
-[[ -z $NO_COLOR ]] &&
-[[ $TERM == *color* || "$( tput colors 2> /dev/null )" == <8-> ]] &&
-typeset -x ZTST_failcolour=red
-
-for file in "${(f)ZTST_testlist}"; do
-  file=${file#./}
-  $ZTST_exe +Z -f $ZTST_srcdir/ztst.zsh $file
-  retval=$?
-  if (( $retval == 2 )); then
-    (( skipped++ ))
-  elif (( $retval )); then
-    (( failure++ ))
-    (( $retval > 128 )) && {
-      [[ -n $ZTST_failcolour ]] && print -rnP "%F{$ZTST_failcolour}"
-      print -r - "$file: test failed: SIG$signals[$retval - 127]."
-      [[ -n $ZTST_failcolour ]] && print -rnP %f
-    }
-    ffiles+=( $file )
-  else
-    (( success++ ))
-  fi
+# Colors to use for ztst messages. ZTST_failcolor is also used as a
+# signal that colors are available generally.
+if [[ -z $NO_COLOR && \
+    ( -n $ZTST_failcolor || \
+    ( -t 1 && \
+    ( $TERM == *color* || "$( tput colors 2> /dev/null )" == <8-> ))) ]]; then
+  : ${ZTST_failcolor:=red}
+  : ${ZTST_warncolor:=yellow}
+  : ${ZTST_passcolor:=green}
+  typeset -x -m "ZTST_*color"
+else
+  unset -m "ZTST_*color"
+fi
+
+run-test() {
+  $ZTST_exe +Z -f $ZTST_srcdir/ztst.zsh $test
+  local -i result=$?
+  (( result > 128 )) && {
+    [[ -n $ZTST_failcolor ]] && print -rnP "%F{$ZTST_failcolor}"
+    print -r - "$test: test failed: SIG$signals[result - 127]."
+    [[ -n $ZTST_failcolor ]] && print -rnP %f
+  }
   print
-done
+  return result
+}
+
+typeset -a passing=() skipped=() failing=()
+
+add-test-result() {
+  case $1 in
+    0) passing+=$test;;
+    2) skipped+=$test;;
+    *) failing+=$test;;
+  esac
+}
+
+run-tests-sequentially() {
+  local test
+  for test in $tests; do
+    run-test
+    add-test-result $?
+  done
+}
+
+run-tests-in-parallel() {
+  # Setup data directory.
+  local datadir=$0:h/rundata.tmp
+  [[ -d $datadir ]] || mkdir $datadir
+
+  # Setup logging, if requested.
+  if (( ZTST_log )); then
+    typeset -F SECONDS
+    rm -f $datadir/runtests.log
+    local -i log_fd && exec {log_fd}>$datadir/runtests.log
+    local -a log=(print -u$log_fd -f "%8.3f %s\n" SECONDS)
+  fi
+  ((log_fd)) && $log "--- <<<"
+
+  # Read run times from previous runs, if any.
+  local -A test2real=() test2cpu=()
+  [[ -r $datadir/runtimes.zsh ]] && . $datadir/runtimes.zsh
+
+  # Sort tests by increasing real run time and then in reverse listing
+  # order. Note that tests are run starting from the end of the array,
+  # so slowest first and in listing order if no run time is available.
+  local -i ntests=$#tests i
+  for ((i=ntests; i; i--)); do
+    tests[i]=$(( 1000 * test2real[$tests[i]] + ntests - i))-$tests[i]
+  done
+  tests=(${${(on)tests}#*-})
+
+  # Setup FIFO for run results.
+  rm -f $datadir/runresults.fifo
+  mkfifo $datadir/runresults.fifo
+  typeset -i fifo_fd && exec {fifo_fd}<>$datadir/runresults.fifo
+
+  # Start up to ZTST_jobs jobs. Each job runs a single test, records
+  # the output to a dedicated file, and writes the run result to the
+  # result FIFO. Once jobs are started, wait for results in the result
+  # FIFO, print the output and record the result, and restart new jobs
+  # until there are no more tests left to run.
+  local job test match mbegin mend
+  local -i jobs=0 next=$#tests result real
+  local -a output
+  while (( jobs || next )); do
+    if (( jobs < ZTST_jobs && next )); then
+      # Start a new job
+      printf -v job "%03d" $(( ++jobs ))
+    else
+      # Read one test result
+      read -u$fifo_fd job test result
+      ((log_fd)) && $log "$job >>> $test"
+      output=( "${(@f)$(<$datadir/output-$job.log)}" )
+      print -rl "${(@)output[1,-3]}"
+      add-test-result $result
+      if [[ $output[-1] =~ "children  ([0-9.]+)s user ([0-9.]+)s sys.* ([0-9.]+) tot" ]]; then
+        real=$(( 1000 * match[3] ))
+        # Save run times only if the test was successful or slower than previously
+        if (( !result || real > test2real[$test] )); then
+          test2real[$test]=$real
+          test2cpu[$test]=$(( 1000 * (match[1] + match[2]) ))
+        fi
+      fi
+      # End job and revive it if a next test is still there
+      (( jobs-- && next && ++jobs )) || continue
+    fi
+    # Start next test
+    test=$tests[next--]
+    ((log_fd)) && $log "$job <<< $test"
+    { &>$datadir/output-$job.log time run-test; print -u$fifo_fd $job $test $? } &
+  done
+
+  # Wait for all jobs to finish and close the run result FIFO.
+  wait
+  exec {fifo_fd}>&-
+  rm -f $datadir/runresults.fifo
+
+  # Save run times.
+  typeset -p 1 test2cpu test2real >$datadir/runtimes.zsh
+
+  # End logging.
+  ((log_fd)) && $log "--- >>>"
+  ((log_fd)) && exec {log_fd}>&-
+
+  # Order test scripts alphabetically.
+  passing=(${(o)passing})
+  skipped=(${(o)skipped})
+  failing=(${(o)failing})
+
+  # Write run time data, if requested.
+  if (( ZTST_log )); then
+    local -i ntests=$#tests i
+    for ((i=ntests; i; i--)); do
+      tests[i]=$(( 1000 * 1000 * test2real[$tests[i]] + test2cpu[$tests[i]] ))-$tests[i]
+    done
+    tests=(${${(on)tests}#*-})
+    printf "%9s %9s %9s   %s\n" \
+        "Real time" "CPU time" "Idle part" "Test script" >$datadir/runtimes.txt
+    for ((i=ntests; i; i--)); do
+      local test=$tests[i]
+      local -F real=$test2real[$test] cpu=$test2cpu[$test]
+      printf "%9.3f %9.3f %8.2f%%   %s\n" \
+          "real/1000" "cpu/1000" "100*(1-cpu/real)" "$test"
+    done >>$datadir/runtimes.txt
+  fi
+}
+
+typeset -a tests=(${${(f)ZTST_testlist}#./})
+if (( ZTST_jobs )); then
+  run-tests-in-parallel
+else
+  run-tests-sequentially
+fi
 
-res=(
-  "$success successful test script${${success:#1}:+s}"
-  "$failure failure${${failure:#1}:+s}"
-  "$skipped skipped"
+typeset -a res=(
+  "$#passing successful test script${${${#passing}:#1}:+s}"
+  "$#failing failure${${${#failing}:#1}:+s}"
+  "$#skipped skipped"
 )
-resln=${(j<, >)res}
-rule=${resln//?/\*}
-
-[[ -n $ZTST_failcolour ]] &&
-if (( failure )); then
-  col=red
-elif (( success )); then
-  col=green
+typeset resln=${(j<, >)res}
+typeset rule=${resln//?/\*}
+typeset col
+[[ -n $ZTST_failcolor ]] &&
+if (( $#failing )); then
+  col=$ZTST_failcolor
+elif (( $#passing )); then
+  col=$ZTST_passcolor
 else
-  col=yellow
+  col=$ZTST_warncolor
 fi
 
 (( $#col )) && print -rnP - "%F{$col}"
 print -rl - $rule $resln
-(( $#ffiles )) &&
-print -rl - '' "failing test script${${#ffiles:#1}:+s}:" ${(@)ffiles/#/  }
+(( !ZTST_hide_failing && $#failing )) &&
+print -rl - '' "failing test script${${${#failing}:#1}:+s}:" ${(@)failing/#/  }
+(( ZTST_show_skipped && $#skipped )) &&
+print -rl - '' "skipped test script${${${#skipped}:#1}:+s}:" ${(@)skipped/#/  }
+(( ZTST_show_passing && $#passing )) &&
+print -rl - '' "passing test script${${${#passing}:#1}:+s}:" ${(@)passing/#/  }
 print -rl - $rule
 (( $#col )) && print -rnP - %f
 
-return $(( failure ? 1 : 0 ))
+return $(( $#failing ? 1 : 0 ))
diff --git a/Test/ztst.zsh b/Test/ztst.zsh
index df0a09b61..89d5c5917 100755
--- a/Test/ztst.zsh
+++ b/Test/ztst.zsh
@@ -93,9 +93,9 @@ ZTST_testfailed() {
   if [[ -n $ZTST_message ]]; then
     print -r "Was testing: $ZTST_message"
   fi
-  [[ -n $ZTST_failcolour ]] && print -rnP "%F{$ZTST_failcolour}"
+  [[ -n $ZTST_failcolor ]] && print -rnP "%F{$ZTST_failcolor}"
   print -r "$ZTST_testname: test failed."
-  [[ -n $ZTST_failcolour ]] && print -rnP %f
+  [[ -n $ZTST_failcolor ]] && print -rnP %f
   if [[ -n $ZTST_failmsg ]]; then
     print -r "The following may (or may not) help identifying the cause:
 $ZTST_failmsg"
@@ -112,9 +112,9 @@ ZTST_testxpassed() {
   if [[ -n $ZTST_message ]]; then
     print -r "Was testing: $ZTST_message"
   fi
-  [[ -n $ZTST_failcolour ]] && print -rnP "%F{$ZTST_failcolour}"
+  [[ -n $ZTST_failcolor ]] && print -rnP "%F{$ZTST_failcolor}"
   print -r "$ZTST_testname: test XPassed."
-  [[ -n $ZTST_failcolour ]] && print -rnP %f
+  [[ -n $ZTST_failcolor ]] && print -rnP %f
   if [[ -n $ZTST_failmsg ]]; then
     print -r "The following may (or may not) help identifying the cause:
 $ZTST_failmsg"
@@ -337,12 +337,12 @@ ZTST_diff() {
 
     out=( ${(f)"$( $cmd "$@" )"} ) || ret=$?
 
-    # massage + colourise diff
+    # massage + colorize diff
     (( ret )) && {
       local B=${(%):-%B} b=${(%):-%b} f=${(%):-%f}
       local Fr=${(%):-'%F{red}'} Fg=${(%):-'%F{green}'} Fc=${(%):-'%F{cyan}'}
 
-      [[ -n $ZTST_failcolour ]] || B= b= Fr= Fg= Fc= f=
+      [[ -n $ZTST_failcolor ]] || B= b= Fr= Fg= Fc= f=
 
       out[1]=${out[1]/#---*/$B--- expected$b}
       out[2]=${out[2]/#+++*/$B+++ actual$b}