Post-review fixes, more comments, perf improvements and output redire…

…ction

rs/execution_environment/benches/run-all-benchmarks.sh

@@ -3,16 +3,20 @@ set -ue
 ##
 ## Top-level script to run all execution and embedder benchmarks.
 ## Usage:
-##     ./rs/execution_environment/benches/run-all-benchmarks.sh
+##     ./rs/execution_environment/benches/run-all-benchmarks.sh | tee summary.txt
+##
+## The best (minimum) results are located in the `*.min`` files in the current directory.
+## These should be manually copied to `rs/execution_environment/benches/baseline/`.
+## A summary of the results is printed to the standard output.
 ##
 
 printf "%-12s := %s\n" \
-    "REPEAT" "${REPEAT:=9}"
+    "REPEAT" "${REPEAT:=9}" >&2
 
 RUN_BENCHMARK="${0%/*}/run-benchmark.sh"
-[ -x "${RUN_BENCHMARK}" ] || (echo "Error accessing script: ${RUN_BENCHMARK}" && exit 1)
+[ -x "${RUN_BENCHMARK}" ] || (echo "Error accessing script: ${RUN_BENCHMARK}" >&2 && exit 1)
 SUMMARIZE_RESULTS="${0%/*}/summarize-results.sh"
-[ -x "${SUMMARIZE_RESULTS}" ] || (echo "Error accessing script: ${SUMMARIZE_RESULTS}" && exit 1)
+[ -x "${SUMMARIZE_RESULTS}" ] || (echo "Error accessing script: ${SUMMARIZE_RESULTS}" >&2 && exit 1)
 
 run() {
     local i="${1}"
@@ -30,14 +34,14 @@ run() {
     [ -f "${min_file}" ] || counter="-1"
     # Execute benchmark if needed.
     if [ "${counter}" -lt "${i}" ]; then
-        echo "==> Running ${name} benchmarks ($((counter + 1)) of ${REPEAT})"
+        echo "==> Running ${name} benchmarks ($((counter + 1)) of ${REPEAT})" >&2
         QUICK="${quick}" BENCH="${bench}" MIN_FILE="${min_file}" FILTER="${filter}" \
             "${RUN_BENCHMARK}"
         echo "$((counter + 1))" >"${counter_file}"
     fi
     # Summarize results if the benchmark was executed or if it's the final iteration.
     if [ "${counter}" -lt "${i}" -o "${i}" = "${REPEAT}" ]; then
-        echo "==> Summarizing ${name} results:"
+        echo "==> Summarizing ${name} results:" >&2
         NAME="${name}" MIN_FILE="${min_file}" "${SUMMARIZE_RESULTS}"
     fi
 }

rs/execution_environment/benches/run-benchmark.sh

@@ -2,11 +2,11 @@
 set -ue
 ##
 ## Helper script to run the specified `BENCH`
-## and store the best (min) results in the `MIN_FILE`.
+## and store the best (minimum) results in the `MIN_FILE`.
 ##
 
 DEPENDENCIES="awk bash bazel rg sed tail tee"
-which ${DEPENDENCIES} >/dev/null || (echo "Error checking dependencies: ${DEPENDENCIES}" && exit 1)
+which ${DEPENDENCIES} >/dev/null || (echo "Error checking dependencies: ${DEPENDENCIES}" >&2 && exit 1)
 
 QUICK="${QUICK:-no}"
 [ "${QUICK}" = "no" ] || BENCH_ARGS="--quick --output-format=bencher"
@@ -16,43 +16,46 @@ printf "    %-12s := %s\n" \
     "BENCH_ARGS" "${BENCH_ARGS:=--warm-up-time=1 --measurement-time=1 --output-format=bencher}" \
     "FILTER" "${FILTER:=}" \
     "MIN_FILE" "${MIN_FILE:=${0##*/}.min}" \
-    "LOG_FILE" "${LOG_FILE:=${MIN_FILE%.*}.log}"
+    "LOG_FILE" "${LOG_FILE:=${MIN_FILE%.*}.log}" >&2
 
 TMP_FILE="${TMP_FILE:-${MIN_FILE%.*}.tmp}"
 
+# Run the benchmark and capture its output in the `LOG_FILE`.
 bash -c "set -o pipefail; \
     bazel run '${BENCH}' -- ${FILTER} ${BENCH_ARGS} \
         2>&1 | tee '${LOG_FILE}' | rg '^(test .* )?bench:' --line-buffered \
-        | sed -uEe 's/^test (.+) ... bench: +/    > bench: \1 /' -Ee 's/^bench: +/    > quick: /'" \
+        | sed -uEe 's/^test (.+) ... bench: +/> bench: \1 /' -Ee 's/^bench: +/> quick: /'" \
     || (
         echo "Error running the benchmark:"
-        tail -10 "${LOG_FILE}" | sed 's/^/    ! /'
+        tail -10 "${LOG_FILE}" | sed 's/^/! /'
         echo "For more details see: ${LOG_FILE}"
         exit 1
-    )
+    ) >&2
 
 if ! [ -s "${MIN_FILE}" ]; then
-    echo "    Storing results in ${MIN_FILE}"
-    cat "${LOG_FILE}" | rg "^test .* bench:" >"${MIN_FILE}" || echo "    No results (quick run?)"
+    echo "    Storing results in ${MIN_FILE}" >&2
+    cat "${LOG_FILE}" | rg "^test .* bench:" >"${MIN_FILE}" \
+        || echo "    No results found in ${LOG_FILE} (quick run?)" >&2
 else
-    echo "    Merging ${LOG_FILE} into ${MIN_FILE}"
+    echo "    Merging ${LOG_FILE} into ${MIN_FILE}" >&2
     rm -f "${TMP_FILE}"
     cat "${LOG_FILE}" | rg "^test .* bench:" | while read new_bench; do
-        name=$(echo "${new_bench}" | sed -E 's/^test (.+) ... bench:.*/\1/')
-        new_result=$(echo "${new_bench}" | sed -E 's/.*bench: +([0-9]+) ns.*/\1/')
+        name="${new_bench#test }"
+        name="${name% ... bench:*}"
+        new_result_ns="${new_bench#* ... bench: }"
+        new_result_ns="${new_result_ns% ns/iter*}"
 
-        min_bench=$(rg -F " ${name} " "${MIN_FILE}" || true)
-        matches=$(echo "${min_bench}" | wc -l)
-        [ "${matches}" -le 1 ] || (echo "Error matching ${name} times in ${MIN_FILE}" && exit 1)
-        min_result=$(echo "${min_bench}" | sed -E 's/.*bench: +([0-9]+) ns.*/\1/')
+        min_bench=$(rg -F "test ${name} ... bench:" "${MIN_FILE}" || true)
+        min_result_ns="${min_bench#* ... bench: }"
+        min_result_ns="${min_result_ns% ns/iter*}"
 
-        if [ -z "${min_result}" ] || [ "${new_result}" -lt "${min_result}" ]; then
-            echo "    - improved ${name} time: $((new_result / 1000)) µs"
+        if [ -z "${min_result_ns}" ] || [ "${new_result_ns}" -lt "${min_result_ns}" ]; then
+            echo "^ improved: ${name} time: $((new_result_ns / 1000)) µs"
             min_bench="${new_bench}"
         fi
         echo "${min_bench}" >>"${TMP_FILE}"
     done
-    echo "    Updating results in ${MIN_FILE}"
-    mv -f "${TMP_FILE}" "${MIN_FILE}" 2>/dev/null || echo "    No results (quick run?)"
+    echo "    Updating results in ${MIN_FILE}" >&2
+    mv -f "${TMP_FILE}" "${MIN_FILE}" 2>/dev/null || echo "    No results to update (quick run?)" >&2
 fi
 rm -f "${LOG_FILE}"

rs/execution_environment/benches/summarize-results.sh

@@ -6,48 +6,69 @@ set -ue
 ##
 
 DEPENDENCIES="awk rg sed"
-which ${DEPENDENCIES} >/dev/null || (echo "Error checking dependencies: ${DEPENDENCIES}" && exit 1)
+which ${DEPENDENCIES} >/dev/null || (echo "Error checking dependencies: ${DEPENDENCIES}" >&2 && exit 1)
 
 printf "    %-12s := %s\n" \
     "MIN_FILE" "${MIN_FILE:=${0##*/}.min}" \
-    "BASELINE_DIR" "${BASELINE_DIR:=${0%/*}/baseline}"
+    "BASELINE_DIR" "${BASELINE_DIR:=${0%/*}/baseline}" >&2
 
 NAME="${NAME:-${MIN_FILE%.*}}"
+TMP_FILE="${TMP_FILE:-${MIN_FILE%.*}.tmp}"
 
 if [ ! -s "${MIN_FILE}" ]; then
-    echo "    No results to summarize in ${MIN_FILE} (quick run?)" && exit 0
+    echo "    No results to summarize in ${MIN_FILE} (quick run?)" >&2 && exit 0
 fi
-[ -d "${BASELINE_DIR}" ] || (echo "Error accessing directory: ${BASELINE_DIR}" && exit 1)
-
 BASELINE_FILE="${BASELINE_DIR}/${MIN_FILE##*/}"
 if [ ! -s "${BASELINE_FILE}" ]; then
-    echo "No baseline found: ${BASELINE_FILE}" && exit 0
+    echo "    No baseline found in ${BASELINE_FILE}" >&2 && exit 0
 fi
 
-total_baseline="0"
-total_new="0"
+echo_diff() {
+    diff=$(((${2} - ${1}) * 100 * 10 / ${1}))
+    awk "BEGIN { print (${diff})^2 <= (2 * 10)^2 ? 0 : ${diff} / 10 }"
+}
+
+# Compare the `MIN_FILE` to `BASELINE_FILE`.
+total_baseline_ns="0"
+total_new_ns="0"
+rm -f "${TMP_FILE}"
+# Example content:
+#   test update/wasm64/baseline/empty loop ... bench:     2720243 ns/iter (+/- 48904)
 while read min_bench; do
-    name=$(echo "${min_bench}" | sed -E 's/^test (.+) ... bench:.*/\1/')
-    new_result=$(echo "${min_bench}" | sed -E 's/.*bench: +([0-9]+) ns.*/\1/')
+    name="${min_bench#test }"
+    name="${name% ... bench:*}"
+    new_result_ns="${min_bench#* ... bench: }"
+    new_result_ns="${new_result_ns% ns/iter*}"
 
-    baseline_bench=$(rg -F " ${name} " "${BASELINE_FILE}" || true)
-    matches=$(echo "${baseline_bench}" | wc -l)
-    [ "${matches}" -le 1 ] || (echo "Error matching ${name} times in ${BASELINE_FILE}" && exit 1)
-    baseline_result=$(echo "${baseline_bench}" | sed -E 's/.*bench: +([0-9]+) ns.*/\1/')
+    baseline_bench=$(rg -F "test ${name} ... bench:" "${BASELINE_FILE}" || true)
+    baseline_result_ns="${baseline_bench#* ... bench: }"
+    baseline_result_ns="${baseline_result_ns% ns/iter*}"
 
-    if [ -n "${new_result}" -a -n "${baseline_result}" ]; then
-        total_baseline=$((total_baseline + baseline_result))
-        total_new=$((total_new + new_result))
+    if [ -n "${new_result_ns}" -a -n "${baseline_result_ns}" ]; then
+        total_baseline_ns=$((total_baseline_ns + baseline_result_ns))
+        total_new_ns=$((total_new_ns + new_result_ns))
+        echo "$(echo_diff "${baseline_result_ns}" "${new_result_ns}") ${name}" >>"${TMP_FILE}"
     fi
 done <"${MIN_FILE}"
+
+# Produce a summary.
 baseline_commit=$(git rev-list --abbrev-commit -1 HEAD "${BASELINE_FILE}" | head -c 9)
 min_commit=$(git rev-list --abbrev-commit -1 HEAD | head -c 9)
-diff=$((diff = (total_new - total_baseline) * 100 * 10 / total_baseline))
-diff=$(echo "${diff}" | awk '{ print $0^2 <= (2 * 10)^2 ? 0 : $0 / 10 }')
-total_new_ms=$((total_new / 1000 / 1000))
-printf "    = ${baseline_commit}..${min_commit}: ${NAME}: total time: ${total_new_ms} ms "
-case "${diff}" in
+total_diff=$(echo_diff "${total_baseline_ns}" "${total_new_ns}")
+printf "= ${baseline_commit}..${min_commit}: ${NAME} total time: $((total_new_ns / 1000 / 1000)) ms "
+case "${total_diff}" in
     0) echo "(no change)" ;;
-    -*) echo "(improved by ${diff}%)" ;;
-    *) echo "(regressed by ${diff}%)" ;;
+    -*) echo "(improved by ${total_diff}%)" ;;
+    *) echo "(regressed by ${total_diff}%)" ;;
 esac
+
+# Produce top regressed/improved details.
+if [ "${total_diff}" != "0" ]; then
+    cat "${TMP_FILE}" | sort -rn | rg '^[1-9]' | head -5 | while read diff name; do
+        echo "+ ${name} time regressed by ${diff}%"
+    done
+    cat "${TMP_FILE}" | sort -n | rg '^-' | head -5 | while read diff name; do
+        echo "- ${name} time improved by ${diff}%"
+    done
+fi
+# rm -f "${TMP_FILE}"