Clean test_{runner,scalafmt_helper}, add diagnostic env vars, and improve test_cross_build performance (#1646)

mbland · web-flow · commit d43ae0dab832 · 2024-11-12T22:09:48.000+02:00
* Clean test_{runner,scalafmt_helper}, add env vars

Did a little cleaning up while trying to get protobuf to stop
recompiling so often. Didn't impact that problem, but good cleanups
regardless.

Also added two environment variables to make diagnosing test failures
(or slowdowns) easier:

- Defining `RULES_SCALA_TEST_ONLY`will cause only one specific test case
  to run, with full Bazel output. This is helpful for pinpointing and
  working on a specific test without hunting for it or recreating its
  commands.

- Defining `RULES_SCALA_TEST_VERBOSE` will cause all tests to emit full
  Bazel output. This is more useful when running all the tests from a
  specific script from `test/shell/test_*.sh`.

Also, today I learned that `SECONDS` is a special Bash variable. Making
it `local` screwed it up and showed all tests as taking zero seconds.

* Don't clean test_cross_build, shutdown at end

This speeds up the `test_cross_build.sh` tests substantially,
particularly between runs. Here are the times for two runs before this
change; the first is after running `bazel clean` and `bazel shutdown` in
the `test_cross_build` directory:

```txt
$ /usr/bin/time ./test_cross_build.sh

running test test_cross_build
 Test "test_cross_build" successful (73 sec)
running test test_scalafmt
 Test "test_scalafmt" successful (94 sec)
      167.01 real         0.37 user         0.50 sys

$ /usr/bin/time ./test_cross_build.sh

running test test_cross_build
 Test "test_cross_build" successful (8 sec)
running test test_scalafmt
 Test "test_scalafmt" successful (92 sec)
       99.96 real         0.35 user         0.48 sys
```

Here are the times for two equivalent runs after this change:

```txt
$ /usr/bin/time ./test_cross_build.sh

running test test_cross_build
 Test "test_cross_build" successful (71 sec)
running test test_scalafmt
 Test "test_scalafmt" successful (6 sec)
       77.50 real         0.33 user         0.44 sys

$ /usr/bin/time ./test_cross_build.sh

running test test_cross_build
 Test "test_cross_build" successful (5 sec)
running test test_scalafmt
 Test "test_scalafmt" successful (2 sec)
        7.21 real         0.26 user         0.38 sys
```

The effect is even more dramatic when setting compiler flags in
`.bazelrc`, as I've tried while building protobuf-v28.3 under Bazel
6.5.0.
diff --git a/test/shell/test_cross_build.sh b/test/shell/test_cross_build.sh
@@ -9,11 +9,11 @@ cd test_cross_build
 
 function test_cross_build() {
   bazel test //...
-  bazel clean
-  bazel shutdown;
 }
 
 function test_scalafmt() {
+  bazel build //scalafmt/...
+
   run_formatting scalafmt binary2 binary2
   run_formatting scalafmt binary3 binary3
   run_formatting scalafmt library2 library2
@@ -24,3 +24,10 @@ function test_scalafmt() {
 
 $runner test_cross_build
 $runner test_scalafmt
+
+# `bazel shutdown` used to be in `test_cross_build`, after a `bazel clean`.
+# However, the protobuf library tends to rebuild frequently. Not cleaning and
+# postponing the shutdown to the end of the script helps avoid rebuilding as
+# often, speeding up the tests. It also potentially speeds up debugging by
+# preserving the workspace state when a test fails.
+bazel shutdown
diff --git a/test/shell/test_runner.sh b/test/shell/test_runner.sh
@@ -13,9 +13,10 @@ run_test_ci() {
   echo "running test $TEST_ARG"
   eval $TEST_ARG &>$log_file &
   local test_pid=$!
+
   SECONDS=0
-  TIMOUT=${TEST_TIMEOUT-60}
-  test_pulse_printer $! $TIMOUT $TEST_ARG &
+  test_pulse_printer "$test_pid" "${TEST_TIMEOUT:-60}" $TEST_ARG &
+
   local pulse_printer_pid=$!
   local result
 
@@ -25,7 +26,7 @@ run_test_ci() {
     kill $pulse_printer_pid && wait $pulse_printer_pid 2>/dev/null || true
   } || return 1
 
-  DURATION=$SECONDS
+  local DURATION=$SECONDS
   if [ $result -eq 0 ]; then
     echo -e "\n${GREEN}Test \"$TEST_ARG\" successful ($DURATION sec) $NC"
   else
@@ -38,9 +39,9 @@ run_test_ci() {
 
 test_pulse_printer() {
   # makes sure something is printed to stdout while test is running
-  local test_pid=$1
+  local test_pid="$1"
   shift
-  local timeout=$1 # in minutes
+  local timeout="$1" # in minutes
   shift
   local count=0
 
@@ -60,24 +61,42 @@ test_pulse_printer() {
 run_test_local() {
   # runs the tests locally
   set +e
-  SECONDS=0
-  TEST_ARG=$@
+  local TEST_ARG=$@
+  local RES=''
+
+  # This allows us to run a single test case with full Bazel output without
+  # having to search for it and recreate its command line.
+  if [[ -n "$RULES_SCALA_TEST_ONLY" &&
+        "$TEST_ARG" != "$RULES_SCALA_TEST_ONLY" ]]; then
+    return
+  fi
+
   echo "running test $TEST_ARG"
-  RES=$($TEST_ARG 2>&1)
-  RESPONSE_CODE=$?
-  DURATION=$SECONDS
+  SECONDS=0
+
+  if [[ -n "$RULES_SCALA_TEST_VERBOSE" || -n "$RULES_SCALA_TEST_ONLY" ]]; then
+    $TEST_ARG
+  else
+    RES="$($TEST_ARG 2>&1)"
+  fi
+
+  local RESPONSE_CODE="$?"
+  local DURATION="$SECONDS"
+
   if [ $RESPONSE_CODE -eq 0 ]; then
     echo -e "${GREEN} Test \"$TEST_ARG\" successful ($DURATION sec) $NC"
   else
-    echo -e "\nLog:\n"
-    echo "$RES"
+    if [[ -n "$RES" ]]; then
+      echo -e "\nLog:\n"
+      echo "$RES"
+    fi
     echo -e "${RED} Test \"$TEST_ARG\" failed $NC ($DURATION sec) $NC"
     exit $RESPONSE_CODE
   fi
 }
 
 get_test_runner() {
-  test_env=$1
+  local test_env="$1"
   if [[ "${test_env}" != "ci" && "${test_env}" != "local" ]]; then
     echo -e "${RED}test_env must be either 'local' or 'ci'"
     exit 1
diff --git a/test/shell/test_scalafmt_helper.sh b/test/shell/test_scalafmt_helper.sh
@@ -1,57 +1,60 @@
 backup_unformatted() {
-  FILE_PATH=$1
-  FILENAME=$2
-  cp $FILE_PATH/unformatted/unformatted-$FILENAME.scala $FILE_PATH/unformatted/unformatted-$FILENAME.backup.scala
+  local FILE_PATH="$1"
+  local FILENAME="$2"
+  cp "$FILE_PATH/unformatted/unformatted-$FILENAME.scala" \
+    "$FILE_PATH/unformatted/unformatted-$FILENAME.backup.scala"
 }
 
 restore_unformatted_before_exit() {
-  FILE_PATH=$1
-  FILENAME=$2
-  cp $FILE_PATH/unformatted/unformatted-$FILENAME.backup.scala $FILE_PATH/unformatted/unformatted-$FILENAME.scala
-  rm -f $FILE_PATH/unformatted/unformatted-$FILENAME.backup.scala
+  local FILE_PATH="$1"
+  local FILENAME="$2"
+  cp "$FILE_PATH/unformatted/unformatted-$FILENAME.backup.scala" \
+    "$FILE_PATH/unformatted/unformatted-$FILENAME.scala"
+  rm -f "$FILE_PATH/unformatted/unformatted-$FILENAME.backup.scala"
 }
 
 run_formatting() {
   set +e
 
-  PACKAGE_DIR=$1
-  RULE_TYPE=$2
-  FILENAME=$3
+  local PACKAGE_DIR="$1"
+  local RULE_TYPE="$2"
+  local FILENAME="$3"
 
   #on windows scalafmt targets need to be run using bash. 
   #TODO: improve the scalafmt funcitonality so we don't need to use the run_under mechanism
-  local run_under=""
+  local bazel_run=('bazel' 'run')
   if is_windows; then
-    run_under="--run_under=bash"
+    bazel_run+=('--run_under=bash')
   fi
 
-  bazel run //$PACKAGE_DIR:formatted-$RULE_TYPE.format-test $run_under
+  "${bazel_run[@]}" "//$PACKAGE_DIR:formatted-$RULE_TYPE.format-test"
   if [ $? -ne 0 ]; then
     echo -e "${RED} formatted-$RULE_TYPE.format-test should be a formatted target. $NC"
     exit 1
   fi
 
-  bazel run //$PACKAGE_DIR:unformatted-$RULE_TYPE.format-test $run_under
+  "${bazel_run[@]}" "//$PACKAGE_DIR:unformatted-$RULE_TYPE.format-test"
   if [ $? -eq 0 ]; then
     echo -e "${RED} unformatted-$RULE_TYPE.format-test should be an unformatted target. $NC"
     exit 1
   fi
 
-  backup_unformatted $PACKAGE_DIR $FILENAME
+  backup_unformatted "$PACKAGE_DIR" "$FILENAME"
   # format unformatted*.scala
 
-  bazel run //$PACKAGE_DIR:unformatted-$RULE_TYPE.format $run_under
+  "${bazel_run[@]}" "//$PACKAGE_DIR:unformatted-$RULE_TYPE.format"
   if [ $? -ne 0 ]; then
     echo -e "${RED} unformatted-$RULE_TYPE.format should run formatting. $NC"
-    restore_unformatted_before_exit $PACKAGE_DIR $FILENAME
+    restore_unformatted_before_exit "$PACKAGE_DIR" "$FILENAME"
     exit 1
   fi
 
-  diff $FILE_PATH/unformatted/unformatted-$FILENAME.scala $FILE_PATH/formatted/formatted-$FILENAME.scala
+  diff "$PACKAGE_DIR/unformatted/unformatted-$FILENAME.scala" \
+    "$PACKAGE_DIR/formatted/formatted-$FILENAME.scala"
   if [ $? -ne 0 ]; then
     echo -e "${RED} unformatted-$FILENAME.scala should be the same as formatted-$FILENAME.scala after formatting. $NC"
-    restore_unformatted_before_exit $PACKAGE_DIR $FILENAME
+    restore_unformatted_before_exit "$PACKAGE_DIR" "$FILENAME"
     exit 1
   fi
-  restore_unformatted_before_exit $FILE_PATH $FILENAME
+  restore_unformatted_before_exit "$PACKAGE_DIR" "$FILENAME"
 }
