|
| 1 | +// Package measurements keeps a run's own timings so a report cannot invent them. |
| 2 | +// |
| 3 | +// THE FAILURE THIS EXISTS FOR. A measured run finished a benchmark and reported |
| 4 | +// a table of test timings that no command in the session had produced. The same |
| 5 | +// test read 0.86s in one paste and 4.20s in the next with nothing said about the |
| 6 | +// difference, a -race overhead moved from +3.7% to +133% between two tellings of |
| 7 | +// the same result, and the column summed to an exact total no real transcript |
| 8 | +// lands on. A prompt rule — "re-run every command before you paste it" — is the |
| 9 | +// obvious answer and the weak one: a model that is willing to write numbers it |
| 10 | +// did not measure is equally willing to say it re-ran them. |
| 11 | +// |
| 12 | +// The harness is not. Every command's output passed through this process and was |
| 13 | +// written to the session log, so the run's real numbers are already here. This |
| 14 | +// package reads them back and compares them against what the answer claims, |
| 15 | +// which is the one check a model cannot satisfy by asserting harder. |
| 16 | +// |
| 17 | +// DELIBERATELY LOOSE. Timings vary between runs for honest reasons — a loaded |
| 18 | +// machine, a warm cache, a different -count. The tolerance below is a 50% band, |
| 19 | +// which lets ordinary variation through and catches 0.86s reported as 4.20s. The |
| 20 | +// cost of a false positive is high (a tripwire that cries wolf is turned off, and |
| 21 | +// then it catches nothing), and the cost of a false negative is one uncaught |
| 22 | +// number, so this errs firmly toward silence. |
| 23 | +package measurements |
| 24 | + |
| 25 | +import ( |
| 26 | + "math" |
| 27 | + "regexp" |
| 28 | + "sort" |
| 29 | + "strconv" |
| 30 | + "strings" |
| 31 | + "sync" |
| 32 | +) |
| 33 | + |
| 34 | +// Measurement is one timing a command reported: what was measured, and how long |
| 35 | +// it took in seconds. |
| 36 | +type Measurement struct { |
| 37 | + Name string |
| 38 | + Seconds float64 |
| 39 | +} |
| 40 | + |
| 41 | +// Conflict is a number an answer states that the session never recorded. |
| 42 | +type Conflict struct { |
| 43 | + Name string |
| 44 | + // Claimed is the value the answer gave, in seconds. |
| 45 | + Claimed float64 |
| 46 | + // Recorded is every value this session actually observed for Name, sorted. |
| 47 | + Recorded []float64 |
| 48 | +} |
| 49 | + |
| 50 | +var ( |
| 51 | + // `ok github.com/x/y 8.337s` and its FAIL twin. Not anchored at the end: |
| 52 | + // a coverage or cached suffix may follow. |
| 53 | + goTestPackageLine = regexp.MustCompile(`(?m)^(?:ok|FAIL)\s+(\S+)\s+([0-9]+(?:\.[0-9]+)?)s(?:\s|$)`) |
| 54 | + // `--- PASS: TestFoo (0.30s)`, at any indentation, including subtests. |
| 55 | + goTestCaseLine = regexp.MustCompile(`(?m)^\s*--- (?:PASS|FAIL|SKIP):\s+(\S+)\s+\(([0-9]+(?:\.[0-9]+)?)s\)`) |
| 56 | + // A duration as an answer would write it, in seconds or milliseconds. |
| 57 | + claimedDuration = regexp.MustCompile(`([0-9]+(?:\.[0-9]+)?)\s*(ms|s)\b`) |
| 58 | +) |
| 59 | + |
| 60 | +// ParseGoTest pulls every timing out of `go test` output. |
| 61 | +// |
| 62 | +// Two shapes only — the per-package result line and the per-case `--- PASS` |
| 63 | +// line. Benchmarks report ns/op rather than a duration and are NOT read here: |
| 64 | +// guessing at a unit would put wrong numbers in the ledger, and a ledger that is |
| 65 | +// itself unreliable is worse than none. |
| 66 | +func ParseGoTest(text string) []Measurement { |
| 67 | + if strings.TrimSpace(text) == "" { |
| 68 | + return nil |
| 69 | + } |
| 70 | + var out []Measurement |
| 71 | + for _, pattern := range []*regexp.Regexp{goTestPackageLine, goTestCaseLine} { |
| 72 | + for _, match := range pattern.FindAllStringSubmatch(text, -1) { |
| 73 | + seconds, err := strconv.ParseFloat(match[2], 64) |
| 74 | + if err != nil { |
| 75 | + continue |
| 76 | + } |
| 77 | + name := strings.TrimSpace(match[1]) |
| 78 | + if name == "" { |
| 79 | + continue |
| 80 | + } |
| 81 | + out = append(out, Measurement{Name: name, Seconds: seconds}) |
| 82 | + } |
| 83 | + } |
| 84 | + return out |
| 85 | +} |
| 86 | + |
| 87 | +// Ledger is every timing this run observed, and which conflicts it has already |
| 88 | +// raised. |
| 89 | +// |
| 90 | +// A nil Ledger is a working no-op, so a caller that does not want the check |
| 91 | +// holds nil and still calls every method unconditionally. |
| 92 | +type Ledger struct { |
| 93 | + mu sync.Mutex |
| 94 | + observed map[string][]float64 |
| 95 | + raised map[string]bool |
| 96 | +} |
| 97 | + |
| 98 | +func NewLedger() *Ledger { |
| 99 | + return &Ledger{observed: map[string][]float64{}, raised: map[string]bool{}} |
| 100 | +} |
| 101 | + |
| 102 | +// Record reads any timings out of a command's output and remembers them. |
| 103 | +// Returns how many it took, which is what a test asserts on. |
| 104 | +func (l *Ledger) Record(text string) int { |
| 105 | + if l == nil { |
| 106 | + return 0 |
| 107 | + } |
| 108 | + found := ParseGoTest(text) |
| 109 | + if len(found) == 0 { |
| 110 | + return 0 |
| 111 | + } |
| 112 | + l.mu.Lock() |
| 113 | + defer l.mu.Unlock() |
| 114 | + for _, m := range found { |
| 115 | + l.observed[m.Name] = append(l.observed[m.Name], m.Seconds) |
| 116 | + } |
| 117 | + return len(found) |
| 118 | +} |
| 119 | + |
| 120 | +// tolerance reports whether two timings are close enough to be the same result |
| 121 | +// measured twice. A 50% band with a small absolute floor: ordinary variation and |
| 122 | +// sub-centisecond jitter pass, a fivefold difference does not. |
| 123 | +func tolerance(a, b float64) bool { |
| 124 | + spread := math.Max(math.Abs(a), math.Abs(b)) * 0.5 |
| 125 | + if spread < 0.05 { |
| 126 | + spread = 0.05 |
| 127 | + } |
| 128 | + return math.Abs(a-b) <= spread |
| 129 | +} |
| 130 | + |
| 131 | +// Conflicts reports numbers in claim that contradict what this session recorded. |
| 132 | +// |
| 133 | +// ONLY NAMES THE LEDGER ALREADY KNOWS are considered, and only when the claim |
| 134 | +// puts a duration next to one on the same line. An answer that mentions a test |
| 135 | +// without timing it, or that reports something never measured here, produces |
| 136 | +// nothing — this check exists to catch a number that DISAGREES with the |
| 137 | +// transcript, not to demand that every number have one. |
| 138 | +// |
| 139 | +// Each name is reported at most once per Ledger. A second pass over the same |
| 140 | +// answer is silent, so the caller can feed a correction back to the model |
| 141 | +// without the possibility of a loop. |
| 142 | +func (l *Ledger) Conflicts(claim string) []Conflict { |
| 143 | + if l == nil || strings.TrimSpace(claim) == "" { |
| 144 | + return nil |
| 145 | + } |
| 146 | + l.mu.Lock() |
| 147 | + defer l.mu.Unlock() |
| 148 | + |
| 149 | + var out []Conflict |
| 150 | + for name, recorded := range l.observed { |
| 151 | + if l.raised[name] || len(recorded) == 0 { |
| 152 | + continue |
| 153 | + } |
| 154 | + claimed, ok := claimedSecondsFor(claim, name) |
| 155 | + if !ok { |
| 156 | + continue |
| 157 | + } |
| 158 | + agrees := false |
| 159 | + for _, seen := range recorded { |
| 160 | + if tolerance(claimed, seen) { |
| 161 | + agrees = true |
| 162 | + break |
| 163 | + } |
| 164 | + } |
| 165 | + if agrees { |
| 166 | + continue |
| 167 | + } |
| 168 | + values := append([]float64(nil), recorded...) |
| 169 | + sort.Float64s(values) |
| 170 | + out = append(out, Conflict{Name: name, Claimed: claimed, Recorded: values}) |
| 171 | + } |
| 172 | + // Deterministic order: this text reaches a model, and a set that reshuffles |
| 173 | + // between identical runs is a diff nobody can read. |
| 174 | + sort.Slice(out, func(i, j int) bool { return out[i].Name < out[j].Name }) |
| 175 | + for _, conflict := range out { |
| 176 | + l.raised[conflict.Name] = true |
| 177 | + } |
| 178 | + return out |
| 179 | +} |
| 180 | + |
| 181 | +// claimedSecondsFor finds the duration an answer puts beside a name, searching |
| 182 | +// the remainder of each line the name appears on. Same line only: a number three |
| 183 | +// paragraphs away is not this name's timing, and pairing them would invent a |
| 184 | +// disagreement rather than find one. |
| 185 | +func claimedSecondsFor(claim, name string) (float64, bool) { |
| 186 | + for _, line := range strings.Split(claim, "\n") { |
| 187 | + index := strings.Index(line, name) |
| 188 | + if index < 0 { |
| 189 | + continue |
| 190 | + } |
| 191 | + match := claimedDuration.FindStringSubmatch(line[index+len(name):]) |
| 192 | + if match == nil { |
| 193 | + continue |
| 194 | + } |
| 195 | + value, err := strconv.ParseFloat(match[1], 64) |
| 196 | + if err != nil { |
| 197 | + continue |
| 198 | + } |
| 199 | + if match[2] == "ms" { |
| 200 | + value /= 1000 |
| 201 | + } |
| 202 | + return value, true |
| 203 | + } |
| 204 | + return 0, false |
| 205 | +} |
| 206 | + |
| 207 | +// Nudge renders conflicts as the correction a model is asked to act on. Empty |
| 208 | +// when there is nothing to say, so the caller can test the string itself. |
| 209 | +func Nudge(conflicts []Conflict) string { |
| 210 | + if len(conflicts) == 0 { |
| 211 | + return "" |
| 212 | + } |
| 213 | + var b strings.Builder |
| 214 | + if len(conflicts) == 1 { |
| 215 | + b.WriteString("One number in your answer does not match what this session recorded.\n") |
| 216 | + } else { |
| 217 | + b.WriteString("Some numbers in your answer do not match what this session recorded.\n") |
| 218 | + } |
| 219 | + for _, conflict := range conflicts { |
| 220 | + b.WriteString(" - ") |
| 221 | + b.WriteString(conflict.Name) |
| 222 | + b.WriteString(": your answer says ") |
| 223 | + b.WriteString(formatSeconds(conflict.Claimed)) |
| 224 | + b.WriteString("; the commands actually run in this session reported ") |
| 225 | + for i, value := range conflict.Recorded { |
| 226 | + if i > 0 { |
| 227 | + b.WriteString(", ") |
| 228 | + } |
| 229 | + b.WriteString(formatSeconds(value)) |
| 230 | + } |
| 231 | + b.WriteString(".\n") |
| 232 | + } |
| 233 | + b.WriteString("Re-run the command and report what it prints. If both numbers are real, give both and say what changed between them — " + |
| 234 | + "do not replace one with the other silently. If the number was not measured in this session, say so plainly instead of stating it as a result.") |
| 235 | + return b.String() |
| 236 | +} |
| 237 | + |
| 238 | +func formatSeconds(value float64) string { |
| 239 | + return strconv.FormatFloat(value, 'f', -1, 64) + "s" |
| 240 | +} |
0 commit comments