run_logged.sh (2370B)
1 #!/usr/bin/env bash 2 set -u 3 4 if [ "$#" -lt 2 ]; then 5 echo "usage: run_logged.sh <label> <command> [args...]" >&2 6 exit 2 7 fi 8 9 label="$1" 10 shift 11 12 root="$(cd "$(dirname "$0")/../.." && pwd)" 13 log_dir="$root/build/test/tier1/logs" 14 log="$log_dir/$label.log" 15 mkdir -p "$log_dir" 16 17 . "$root/test/tier1/timing.sh" 18 19 print_child_timings() { 20 max=${T1_TIMING_LINES:-8} 21 timings=$( 22 awk ' 23 /^tier1\/[^:]+: / { 24 cur = $0 25 sub(/^tier1\/[^:]+: /, "", cur) 26 next 27 } 28 /^[[:space:]]+ok: / { 29 if (match($0, /\(([0-9]+)ms\)/)) { 30 ms = substr($0, RSTART + 1, RLENGTH - 4) 31 name = cur 32 if ($0 ~ /^[[:space:]]+ok: [^\/]/) { 33 name = $0 34 sub(/^[[:space:]]+ok: /, "", name) 35 sub(/[[:space:]]+\([0-9]+ms\).*$/, "", name) 36 } 37 if (name != "") printf "%s\t%s\n", ms, name 38 } 39 } 40 /^[^:]+: time / { 41 for (i = 3; i <= NF; ++i) { 42 split($i, kv, "=") 43 if (kv[1] != "" && kv[2] ~ /^[0-9]+ms$/) { 44 sub(/ms$/, "", kv[2]) 45 printf "%s\t%s\n", kv[2], kv[1] 46 } 47 } 48 } 49 ' "$log" | sort -nr | head -n "$max" 50 ) 51 [ -n "$timings" ] || return 0 52 printf ' slow steps: ' 53 printf '%s\n' "$timings" | 54 awk -F '\t' '{ printf "%s%s=%sms", sep, $2, $1; sep=", " } END { printf "\n" }' 55 } 56 57 start_ms=$(t1_now_ms) 58 "$@" >"$log" 2>&1 59 rc=$? 60 dur_ms=$(t1_elapsed_ms "$start_ms" "$(t1_now_ms)") 61 62 if [ "$rc" -ne 0 ]; then 63 printf 'T1 %s failed after %sms; tail of %s:\n' "$label" "$dur_ms" "$log" >&2 64 tail -100 "$log" >&2 || true 65 exit "$rc" 66 fi 67 skips="$(sed -n 's/^[^:][^:]*: skipped: //p' "$log" | tr '\n' ' ' | sed -e 's/[[:space:]][[:space:]]*/ /g' -e 's/^ //' -e 's/ $//')" 68 if [ -n "$skips" ]; then 69 nskip="$(printf '%s\n' "$skips" | wc -w | tr -d '[:space:]')" 70 printf 'T1 %-18s OK %sms (%s skip: %s)\n' "$label" "$dur_ms" "$nskip" "$skips" 71 if t1_slow_timing_enabled; then 72 print_child_timings 73 fi 74 exit 0 75 fi 76 printf 'T1 %-18s OK %sms\n' "$label" "$dur_ms" 77 if t1_slow_timing_enabled; then 78 print_child_timings 79 fi