scripts/stage-timing.sh

162 lines

1#!/usr/bin/env bash

2# stage-timing.sh (Issue 10-051) -- a sourced library, not run directly.

4# WHAT (for a CEO): the pipeline used to print hand-typed guesses for how long

5# each stage takes ("~42 hours"). Those guesses rot -- a faster GPU or a new

6# embedding backend changes the real time, but the printed number never does.

7# This records how long each stage ACTUALLY took on THIS machine, keeps the last

8# few, and lets the menu show the real average instead of a stale guess.

10# WHERE: timings live in ${DIR}/.stage-timings -- a hidden plain-text file modelled

11# on .file-index-counter. One [section] per stage, holding up to RING_SIZE bare

12# integers (seconds), the oldest rolling off when a newer one is recorded. The

13# numbers are a function of the operator's hardware and run count, so the file is

14# gitignored -- useless to share.

15#

16# HOW it stays honest: a stage is only recorded when it COMPLETES successfully.

17# A run that errors or is Ctrl-C'd logs nothing -- a partial "time-until-failure"

18# would drag the average down and make the next estimate lie optimistically.

19#

20# FUNCTIONS (source this file, then call):

21# timed_stage <stage> <cmd...> run cmd; record its wall-clock iff it succeeds

22# stage_timing_record <stage> <seconds> append a timing (oldest rolls off past the ring)

23# stage_timing_mean <stage> print the integer mean, or "" if no history

24# stage_timing_count <stage> print how many timings are stored for the stage

25# stage_timing_format_seconds <int> "45s" / "12m 30s" / "2h 14m" / "1d 18h"

26# stage_timing_label <stage> <fallback> the pre-flight estimate string (measured or fallback)

27#

28# Usage: DIR=/path/to/project; source "${DIR}/scripts/stage-timing.sh"

30# {{{ configuration

31# ${DIR} is the project root. run.sh sets it before sourcing; the hardcoded value

32# is the fallback so the library is usable standalone. STAGE_TIMINGS_FILE is

33# overridable (the tests point it at a temp file).

34DIR="${DIR:-/mnt/mtwo/programming/ai-stuff/neocities-modernization}"

35STAGE_TIMINGS_FILE="${STAGE_TIMINGS_FILE:-${DIR}/.stage-timings}"

36# Ring size: how many recent timings to keep per stage. 5 balances a smooth mean

37# against reacting to a real change (e.g. a backend that halved the embed time):

38# larger is smoother but slower to track reality; smaller is noisier but quicker.

39STAGE_TIMING_RING_SIZE="${STAGE_TIMING_RING_SIZE:-5}"

40# }}}

42# {{{ stage_timing_record <stage> <seconds>

43# Append <seconds> to the [stage] section, keep only the last RING_SIZE entries

44# (oldest off the top), and write the whole file back atomically (temp + mv) so a

45# reader never sees a torn file. Creates the section -- and the file -- if absent.

46# Missing/unwritable file is a no-op: timing is a nice-to-have, never a contract.

47stage_timing_record() {

48 local stage="$1" secs="$2"

49 [ -n "$stage" ] || return 0

50 [ -n "$secs" ] || return 0

51 case "$secs" in (*[!0-9]*|'') return 0;; esac # only non-negative integers

52 local tmp

53 tmp="$(mktemp "${STAGE_TIMINGS_FILE}.XXXXXX" 2>/dev/null)" || return 0

54 # On the very first record the file does not exist yet; read /dev/null so awk

55 # has a valid (empty) input and the END block still creates the section.

56 local src="$STAGE_TIMINGS_FILE"

57 [ -f "$src" ] || src=/dev/null

58 awk -v stage="$stage" -v secs="$secs" -v ring="$STAGE_TIMING_RING_SIZE" '

59 # Collect existing sections (in original order) and their integer entries.

60 /^\[.*\]$/ { name = $0; sub(/^\[/, "", name); sub(/\]$/, "", name);

61 if (!(name in cnt)) { ord[++norder] = name; cnt[name] = 0 }

62 cur = name; next }

63 /^[0-9]+$/ { if (cur != "") { cnt[cur]++; val[cur, cnt[cur]] = $0 } next }

64 # comments and blank lines are dropped; we re-emit a fresh header below.

65 END {

66 if (!(stage in cnt)) { ord[++norder] = stage; cnt[stage] = 0 }

67 cnt[stage]++; val[stage, cnt[stage]] = secs # append the new timing

68 print "# Stage timing ring buffer (Issue 10-051). Each section holds the last"

69 print "# " ring " wall-clock durations (in seconds) for that stage; the oldest rolls"

70 print "# off when a newer one is recorded. Hardware-specific -- do not commit."

71 print ""

72 for (i = 1; i <= norder; i++) {

73 s = ord[i]

74 print "[" s "]"

75 start = (cnt[s] > ring) ? cnt[s] - ring + 1 : 1 # keep only the last `ring`

76 for (j = start; j <= cnt[s]; j++) print val[s, j]

77 print ""

78 }

79 }

80 ' "$src" 2>/dev/null > "$tmp" || { rm -f "$tmp"; return 0; }

81 mv -f "$tmp" "$STAGE_TIMINGS_FILE" 2>/dev/null || rm -f "$tmp"

82}

83# }}}

85# {{{ stage_timing_mean <stage> -- integer mean of the section, or "" if none

86stage_timing_mean() {

87 local stage="$1"

88 [ -f "$STAGE_TIMINGS_FILE" ] || return 0

89 awk -v stage="$stage" '

90 /^\[.*\]$/ { name = $0; sub(/^\[/, "", name); sub(/\]$/, "", name); cur = name; next }

91 /^[0-9]+$/ { if (cur == stage) { sum += $0; n++ } next }

92 END { if (n > 0) printf "%d\n", int(sum / n + 0.5) }

93 ' "$STAGE_TIMINGS_FILE" 2>/dev/null

94}

95# }}}

97# {{{ stage_timing_count <stage> -- number of timings stored for the stage

98stage_timing_count() {

99 local stage="$1"

100 [ -f "$STAGE_TIMINGS_FILE" ] || { echo 0; return 0; }

101 awk -v stage="$stage" '

102 /^\[.*\]$/ { name = $0; sub(/^\[/, "", name); sub(/\]$/, "", name); cur = name; next }

103 /^[0-9]+$/ { if (cur == stage) n++ ; next }

104 END { print n + 0 }

105 ' "$STAGE_TIMINGS_FILE" 2>/dev/null

106}

107# }}}

108

109# {{{ stage_timing_format_seconds <int> -- human-readable duration

110# 45 -> "45s", 750 -> "12m 30s", 8040 -> "2h 14m 0s", 151200 -> "1d 18h 0m".

111# Three units of resolution once an hour or more is involved (h m s, or d h m),

112# two below that (m s). Showing the seconds slot at the hour scale keeps every

113# row the same shape, which the pre-flight table relies on to line the times up.

114stage_timing_format_seconds() {

115 local s="$1"

116 case "$s" in (*[!0-9]*|'') return 0;; esac

117 if [ "$s" -lt 60 ]; then echo "${s}s"

118 elif [ "$s" -lt 3600 ]; then echo "$((s / 60))m $((s % 60))s"

119 elif [ "$s" -lt 86400 ]; then echo "$((s / 3600))h $(((s % 3600) / 60))m $((s % 60))s"

120 else echo "$((s / 86400))d $(((s % 86400) / 3600))h $(((s % 3600) / 60))m"

121 fi

122}

123# }}}

124

125# {{{ stage_timing_label <stage> <magnitude> -- the pre-flight estimate string

126# Measured history wins and prints a real average: "(avg 2h 14m, last 3 runs)".

127# Before any run, the caller passes a coarse MAGNITUDE word (short/medium/long)

128# instead of a specific number -- a word can't rot the way "~42 hours" did when

129# the GPU path made it minutes, and the avg+count format makes it obvious which

130# lines are measured and which are still a guess. Empty magnitude -> print

131# nothing (the stage line stays bare until it has run once).

132stage_timing_label() {

133 local stage="$1" magnitude="$2"

134 local mean count

135 mean="$(stage_timing_mean "$stage")"

136 if [ -n "$mean" ]; then

137 count="$(stage_timing_count "$stage")"

138 local plural="s"; [ "$count" = "1" ] && plural=""

139 echo "(avg $(stage_timing_format_seconds "$mean"), last ${count} run${plural})"

140 elif [ -n "$magnitude" ]; then

141 echo "(${magnitude})"

142 fi

143}

144# }}}

145

146# {{{ timed_stage <stage> <cmd...> -- run a stage, record its time iff it succeeds

147# The generic wrapper used at run.sh's dispatch call sites, so each stage need not

148# be edited individually. Records ONLY on a zero exit -- a failed or interrupted

149# stage logs nothing (see "stays honest" above).

150timed_stage() {

151 local stage="$1"; shift

152 local start_ts; start_ts="$(date +%s)"

153 "$@"

154 local rc=$?

155 if [ "$rc" -eq 0 ]; then

156 local end_ts; end_ts="$(date +%s)"

157 stage_timing_record "$stage" "$((end_ts - start_ts))"

158 fi

159 return "$rc"

160}

161# }}}

162