From eacf3fd11fce4ca88f6aec57d713cbfa047a905d Mon Sep 17 00:00:00 2001 From: PJ Date: Fri, 14 Aug 2026 17:43:12 +0530 Subject: [PATCH] fix(analyze): divide per-hour rates by time actually worked A host asleep mid-run tested nothing, and charging that sleep to an arm reports it slower for a reason unrelated to the arm. The legend also claimed wall clock while the number was monotonic. Campaigns written before the split are still read through the old field name so their run hours do not silently zero. Claude-Session: https://claude.ai/code/session_01A5KmftdEJ49A9z5mF5ESrX --- cmd/internal-tools/analyze/analysis.go | 2 +- cmd/internal-tools/analyze/analysis_test.go | 48 ++++++++++++++++++--- cmd/internal-tools/analyze/load.go | 27 +++++++++--- cmd/internal-tools/analyze/report.go | 3 +- 4 files changed, 67 insertions(+), 13 deletions(-) diff --git a/cmd/internal-tools/analyze/analysis.go b/cmd/internal-tools/analyze/analysis.go index 8789bd7..5789fac 100644 --- a/cmd/internal-tools/analyze/analysis.go +++ b/cmd/internal-tools/analyze/analysis.go @@ -150,7 +150,7 @@ func summarize(current arm) armSummary { // steps whose action was never dispatched. Only dispatched actions // exercised the app, so only they belong in a per-action rate. summary.TotalActions += item.Actions - summary.TotalRunHours += float64(item.DurationMillis) / float64(time.Hour/time.Millisecond) + summary.TotalRunHours += float64(item.MonotonicMillis) / float64(time.Hour/time.Millisecond) if item.ClampedToBudget { summary.EventsHeldAtBudget++ } diff --git a/cmd/internal-tools/analyze/analysis_test.go b/cmd/internal-tools/analyze/analysis_test.go index 565cace..dd1e521 100644 --- a/cmd/internal-tools/analyze/analysis_test.go +++ b/cmd/internal-tools/analyze/analysis_test.go @@ -2,6 +2,7 @@ package main import ( "math" + "path/filepath" "testing" "time" ) @@ -11,7 +12,7 @@ func violatingRun(seed int64, steps, origin int, properties ...string) classifie Seed: seed, Steps: steps, Actions: steps, - DurationMillis: 60_000, + MonotonicMillis: 60_000, OriginStep: origin, Violated: true, ViolatedProperties: properties, @@ -19,7 +20,7 @@ func violatingRun(seed int64, steps, origin int, properties ...string) classifie } func cleanRun(seed int64, steps int) classifiedRun { - return classifiedRun{Seed: seed, Steps: steps, Actions: steps, DurationMillis: 60_000} + return classifiedRun{Seed: seed, Steps: steps, Actions: steps, MonotonicMillis: 60_000} } func TestSummarize_ArmWhereNoRunViolated(t *testing.T) { @@ -85,9 +86,9 @@ func TestSummarize_CountsDispatchedActionsNotSteps(t *testing.T) { Name: "declines", Budget: 40, Runs: []classifiedRun{ - {Seed: 1, Steps: 40, Actions: 10, DurationMillis: 3_600_000, + {Seed: 1, Steps: 40, Actions: 10, MonotonicMillis: 3_600_000, Violated: true, OriginStep: 12, ViolatedProperties: []string{"cartTotal"}}, - {Seed: 2, Steps: 40, Actions: 6, DurationMillis: 3_600_000}, + {Seed: 2, Steps: 40, Actions: 6, MonotonicMillis: 3_600_000}, }, }) if summary.TotalSteps != 80 { @@ -110,7 +111,7 @@ func TestSummarize_ArmThatDispatchedNothingHasNoPerActionRate(t *testing.T) { Name: "inert", Budget: 20, Runs: []classifiedRun{ - {Seed: 1, Steps: 20, Actions: 0, DurationMillis: 3_600_000, + {Seed: 1, Steps: 20, Actions: 0, MonotonicMillis: 3_600_000, Violated: true, OriginStep: 3, ViolatedProperties: []string{"cartTotal"}}, }, }) @@ -125,6 +126,43 @@ func TestSummarize_ArmThatDispatchedNothingHasNoPerActionRate(t *testing.T) { } } +func runHoursFor(t *testing.T, record map[string]any) float64 { + t.Helper() + directory := filepath.Join(t.TempDir(), "campaign") + record["seed"] = 1 + writeCampaign(t, directory, + map[string]any{"arm": "seeded", "max_steps": 50, "seeds": []int{1}}, + []map[string]any{record}) + arms, err := groupArms([]string{directory}) + if err != nil { + t.Fatal(err) + } + return summarize(arms[0]).TotalRunHours +} + +// A host asleep mid-run advanced the wall clock while testing nothing, so the +// sleep has no place in the denominator of a per-hour rate. +func TestSummarize_RunHoursCountTheTimeWorkedNotTheTimeThatPassed(t *testing.T) { + hours := runHoursFor(t, map[string]any{ + "exit_code": 0, "steps": 50, "actions": 50, + "monotonic_millis": 3_600_000, "wall_clock_millis": 5_400_000, + }) + if hours != 1 { + t.Errorf("run hours %v, want the 1 hour worked rather than the 1.5 hours that passed", hours) + } +} + +// Campaigns recorded before the two clocks were split gave the same monotonic +// reading the name duration_millis, and their hours still have to count. +func TestSummarize_RunHoursReadCampaignsWrittenBeforeTheClocksWereSplit(t *testing.T) { + hours := runHoursFor(t, map[string]any{ + "exit_code": 0, "steps": 50, "actions": 50, "duration_millis": 3_600_000, + }) + if hours != 1 { + t.Errorf("run hours %v, want 1 from the older duration_millis field", hours) + } +} + func TestSummarize_ArmWithNoUsableRunsAfterExclusions(t *testing.T) { summary := summarize(arm{ Name: "broken", diff --git a/cmd/internal-tools/analyze/load.go b/cmd/internal-tools/analyze/load.go index 3b9aa3c..36f8e83 100644 --- a/cmd/internal-tools/analyze/load.go +++ b/cmd/internal-tools/analyze/load.go @@ -30,10 +30,18 @@ type manifest struct { // runRecord mirrors the fields analyze reads from one line of runs.jsonl. type runRecord struct { - Seed int64 `json:"seed"` - ExitCode int `json:"exit_code"` - LaunchError string `json:"launch_error"` - TimedOut bool `json:"timed_out"` + Seed int64 `json:"seed"` + ExitCode int `json:"exit_code"` + LaunchError string `json:"launch_error"` + TimedOut bool `json:"timed_out"` + // MonotonicMillis is how long the run worked, and it is what every + // per-hour rate here divides by: a host asleep mid-run tested nothing, so + // charging that time to the arm would report it as slower for a reason + // that has nothing to do with the arm. The wall clock the campaign also + // records answers the other question, how much time passed. + MonotonicMillis int64 `json:"monotonic_millis"` + // DurationMillis is the name campaigns written before the two clocks were + // split gave the same monotonic reading, so those files still read. DurationMillis int64 `json:"duration_millis"` TraceError string `json:"trace_error"` Steps int `json:"steps"` @@ -61,7 +69,7 @@ type classifiedRun struct { Seed int64 Steps int Actions int - DurationMillis int64 + MonotonicMillis int64 OriginStep int Violated bool ClampedToBudget bool @@ -130,13 +138,20 @@ func loadCampaign(directory string) (manifest, []runRecord, error) { return declared, records, nil } +func (r runRecord) workingMillis() int64 { + if r.MonotonicMillis != 0 { + return r.MonotonicMillis + } + return r.DurationMillis +} + // classify turns one record into the run the analysis works with, deciding // whether it is usable and, if it is, whether it is an event or censored. func classify(record runRecord, budget int) classifiedRun { item := classifiedRun{ Seed: record.Seed, Steps: record.Steps, - DurationMillis: record.DurationMillis, + MonotonicMillis: record.workingMillis(), ViolatedProperties: slices.Clone(record.ViolatedProperties), } if record.Actions != nil { diff --git a/cmd/internal-tools/analyze/report.go b/cmd/internal-tools/analyze/report.go index ced1ee6..f449f22 100644 --- a/cmd/internal-tools/analyze/report.go +++ b/cmd/internal-tools/analyze/report.go @@ -31,7 +31,8 @@ func writeReport(result analysis, out io.Writer) { }) fmt.Fprintln(out) - fmt.Fprintln(out, "a detection is one distinct property violated in one run; run hours sum the per-run wall clock") + fmt.Fprintln(out, "a detection is one distinct property violated in one run; run hours sum the time the runs worked,") + fmt.Fprintln(out, "on the monotonic clock, so a host that slept mid-run is not charged for the sleep") fmt.Fprintln(out, "actions count the steps that dispatched one; the rest chose nothing or had the choice thrown away") writeTable(out, []string{"arm", "steps", "actions", "run hours", "detections", "defects/1k actions", "defects/hour", "distinct defects", "found in one run"}, func(add func(...string)) {