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)) {