diff --git a/cmd/internal-tools/analyze/analysis.go b/cmd/internal-tools/analyze/analysis.go index 5789fac..f9f26c5 100644 --- a/cmd/internal-tools/analyze/analysis.go +++ b/cmd/internal-tools/analyze/analysis.go @@ -20,7 +20,10 @@ type armSummary struct { ExcludedByReason map[string]int `json:"excluded_by_reason,omitempty"` MissingSeeds []int64 `json:"missing_seeds,omitempty"` EventsHeldAtBudget int `json:"events_held_at_budget"` + EventsDetectedAfterOrigin int `json:"events_detected_after_origin"` MedianStepsToFirstViolation *float64 `json:"median_steps_to_first_violation"` + FirstQuartileSteps *float64 `json:"first_quartile_steps_to_first_violation"` + ThirdQuartileSteps *float64 `json:"third_quartile_steps_to_first_violation"` SurvivalCurve []survivalPoint `json:"survival_curve,omitempty"` ViolationRate *float64 `json:"violation_rate"` TotalSteps int `json:"total_steps"` @@ -154,6 +157,9 @@ func summarize(current arm) armSummary { if item.ClampedToBudget { summary.EventsHeldAtBudget++ } + if item.Violated && item.EventStep > item.OriginStep { + summary.EventsDetectedAfterOrigin++ + } if item.Violated { summary.Violated++ } else { @@ -170,6 +176,12 @@ func summarize(current arm) armSummary { if median, ok := medianSurvival(summary.SurvivalCurve); ok { summary.MedianStepsToFirstViolation = &median } + if lower, ok := quantileSurvival(summary.SurvivalCurve, 0.25); ok { + summary.FirstQuartileSteps = &lower + } + if upper, ok := quantileSurvival(summary.SurvivalCurve, 0.75); ok { + summary.ThirdQuartileSteps = &upper + } if summary.Usable > 0 { rate := float64(summary.Violated) / float64(summary.Usable) summary.ViolationRate = &rate diff --git a/cmd/internal-tools/analyze/analysis_test.go b/cmd/internal-tools/analyze/analysis_test.go index dd1e521..cddfd18 100644 --- a/cmd/internal-tools/analyze/analysis_test.go +++ b/cmd/internal-tools/analyze/analysis_test.go @@ -14,6 +14,7 @@ func violatingRun(seed int64, steps, origin int, properties ...string) classifie Actions: steps, MonotonicMillis: 60_000, OriginStep: origin, + EventStep: origin, Violated: true, ViolatedProperties: properties, } diff --git a/cmd/internal-tools/analyze/detection_test.go b/cmd/internal-tools/analyze/detection_test.go new file mode 100644 index 0000000..3bb829d --- /dev/null +++ b/cmd/internal-tools/analyze/detection_test.go @@ -0,0 +1,109 @@ +package main + +import ( + "bytes" + "io" + "path/filepath" + "strings" + "testing" +) + +// These records are the shape a real folio-web campaign produced: an +// `eventually` obligation armed on step 1, never satisfied, and reported when +// the run ended at the step budget. Timing that event by the step that armed it +// puts the first violation on step 1 and reports a median of one step to first +// violation for an arm that spent its whole budget before it could know. +func liveness(seed int64, budget int, properties ...string) map[string]any { + return map[string]any{ + "seed": seed, "exit_code": 0, "steps": budget, "actions": budget - 1, + "monotonic_millis": 15000, + "first_violation_origin_step": 1, + "first_violation_detected_step": budget, + "first_violation_reason": "eventually never satisfied", + "violated_properties": properties, + } +} + +func TestClassify_ObligationReportedAtTheRunEndIsTimedAtItsDetection(t *testing.T) { + detected := 40 + item := classify(runRecord{ + Seed: 2, Steps: 40, Actions: stepPointer(39), + FirstViolationOriginStep: stepPointer(1), + FirstViolationDetectedStep: &detected, + ViolatedProperties: []string{"someTransactionExists"}, + }, 40) + + if !item.Violated { + t.Fatal("run not marked as violated") + } + if item.OriginStep != 1 { + t.Errorf("origin step %d, want the step that armed the obligation", item.OriginStep) + } + if item.EventStep != 40 { + t.Errorf("event step %d, want the step the run could know, 40", item.EventStep) + } + current := arm{Budget: 40, Runs: []classifiedRun{item}} + observations := current.observations() + if len(observations) != 1 || !observations[0].Event || observations[0].Steps != 40 { + t.Errorf("observations %+v, want one event at 40", observations) + } +} + +// A safety property that trips under its own action is detected on the step +// that armed it, so nothing about the existing outcome moves. +func TestClassify_SafetyViolationKeepsItsOriginStep(t *testing.T) { + detected := 12 + item := classify(runRecord{ + Steps: 12, FirstViolationOriginStep: stepPointer(12), FirstViolationDetectedStep: &detected, + }, 400) + if item.EventStep != 12 || item.OriginStep != 12 { + t.Errorf("run %+v, want an event at 12", item) + } +} + +// A campaign written before the detected step was recorded still reads, and +// keeps timing its events at the origin. +func TestClassify_MissingDetectedStepKeepsTheOrigin(t *testing.T) { + item := classify(runRecord{Steps: 30, FirstViolationOriginStep: stepPointer(18)}, 400) + if item.EventStep != 18 { + t.Errorf("event step %d, want the origin step 18", item.EventStep) + } +} + +// The whole-pipeline form of the same thing, on the record shape a real web +// campaign wrote. Before the outcome was timed at detection this reported a +// median of 1 step to first violation. +func TestRun_LivenessFlushedAtTheBudgetDoesNotReportAOneStepMedian(t *testing.T) { + root := t.TempDir() + directory := filepath.Join(root, "seeded-web") + writeCampaign(t, directory, map[string]any{ + "arm": "seeded-web", "generator": "seeded", "platform": "web", + "max_steps": 40, "seeds": []int{1, 2, 3, 4, 5}, + }, []map[string]any{ + {"seed": 1, "exit_code": 0, "steps": 40, "actions": 38, "monotonic_millis": 13512}, + liveness(2, 40, "accountCreationReachable", "someTransactionExists"), + liveness(3, 40, "someTransactionExists"), + liveness(4, 40, "accountCreationReachable", "someTransactionExists"), + {"seed": 5, "exit_code": 0, "steps": 40, "actions": 40, "monotonic_millis": 15433}, + }) + + summary := armByName(t, analyseCampaigns(t, directory), "seeded-web") + if summary.MedianStepsToFirstViolation == nil { + t.Fatal("median undefined, want it at the budget") + } + if *summary.MedianStepsToFirstViolation != 40 { + t.Errorf("median %v steps to first violation, want 40: no run could know before the budget", + *summary.MedianStepsToFirstViolation) + } + if summary.EventsDetectedAfterOrigin != 3 { + t.Errorf("%d events detected after their origin, want 3", summary.EventsDetectedAfterOrigin) + } + + var stdout bytes.Buffer + if err := run([]string{directory}, &stdout, io.Discard); err != nil { + t.Fatal(err) + } + if !strings.Contains(stdout.String(), "timed 3 violation(s) at the step they were detected") { + t.Errorf("the report does not say the events were timed at detection\n%s", stdout.String()) + } +} diff --git a/cmd/internal-tools/analyze/incomplete_test.go b/cmd/internal-tools/analyze/incomplete_test.go new file mode 100644 index 0000000..d79c41b --- /dev/null +++ b/cmd/internal-tools/analyze/incomplete_test.go @@ -0,0 +1,155 @@ +package main + +import ( + "bytes" + "io" + "path/filepath" + "strings" + "testing" +) + +// A campaign that produced nothing still has a manifest, and the manifest is +// what makes the difference between an arm that ran nothing and an arm that was +// never scheduled. Reading one must report every intended seed as missing rather +// than an arm with a small clean sample. +func TestRun_EmptyCampaignIsReportedAsEverySeedMissing(t *testing.T) { + root := t.TempDir() + empty := filepath.Join(root, "empty") + writeCampaign(t, empty, map[string]any{ + "arm": "seeded", "max_steps": 400, "seeds": []int{1, 2, 3, 4, 5}, + }, nil) + + var stdout bytes.Buffer + if err := run([]string{empty}, &stdout, io.Discard); err != nil { + t.Fatal(err) + } + result := analyseCampaigns(t, empty) + summary := armByName(t, result, "seeded") + if summary.Recorded != 0 || summary.Usable != 0 { + t.Errorf("recorded %d usable %d, want none", summary.Recorded, summary.Usable) + } + if len(summary.MissingSeeds) != 5 { + t.Errorf("missing seeds %v, want all five", summary.MissingSeeds) + } + if summary.MedianStepsToFirstViolation != nil || summary.ViolationRate != nil { + t.Errorf("median %v violation rate %v, want neither from no runs", + summary.MedianStepsToFirstViolation, summary.ViolationRate) + } + if result.LogRank != nil || len(result.Pairwise) != 0 { + t.Errorf("log-rank %+v pairwise %v, want no tests", result.LogRank, result.Pairwise) + } + if !strings.Contains(stdout.String(), "seeded") { + t.Errorf("the empty arm is not in the report\n%s", stdout.String()) + } +} + +// A host that stopped part way through leaves a directory that looks complete. +// The seeds it never reached are the difference between a partial campaign and +// a smaller one, and the report has to carry that count. +func TestRun_PartialCampaignCountsTheSeedsTheHostNeverReached(t *testing.T) { + root := t.TempDir() + partial := filepath.Join(root, "partial") + var records []map[string]any + for seed := 1; seed <= 6; seed++ { + records = append(records, map[string]any{ + "seed": seed, "exit_code": 0, "steps": 400, "actions": 380, "monotonic_millis": 360000, + }) + } + writeCampaign(t, partial, map[string]any{ + "arm": "seeded", "max_steps": 400, + "seeds": []int{1, 2, 3, 4, 5, 6, 7, 8, 9, 10}, + }, records) + + summary := armByName(t, analyseCampaigns(t, partial), "seeded") + if summary.Usable != 6 { + t.Errorf("%d usable runs, want the 6 that landed", summary.Usable) + } + if len(summary.MissingSeeds) != 4 { + t.Errorf("missing seeds %v, want the 4 the host never reached", summary.MissingSeeds) + } + + var stdout bytes.Buffer + if err := run([]string{partial}, &stdout, io.Discard); err != nil { + t.Fatal(err) + } + if !strings.Contains(stdout.String(), "missing") { + t.Errorf("no missing-seed column in the report\n%s", stdout.String()) + } +} + +// The ablation is seed-matched, so a run lost on one arm removes its partner +// from the comparison too. Those seeds are named because a paired sample that +// silently shrinks is how a campaign reports a difference between two arms that +// were not in fact matched. +func TestRun_PairedComparisonNamesSeedsLostOnOneArm(t *testing.T) { + root := t.TempDir() + declared := []int{1, 2, 3, 4, 5, 6} + pre := filepath.Join(root, "pre") + post := filepath.Join(root, "post") + writeCampaign(t, pre, map[string]any{"arm": "pre", "max_steps": 400, "seeds": declared}, []map[string]any{ + {"seed": 1, "exit_code": 0, "steps": 300, "actions": 290, "monotonic_millis": 1000, "first_violation_origin_step": 300, "violated_properties": []string{"p"}}, + {"seed": 2, "exit_code": 0, "steps": 400, "actions": 390, "monotonic_millis": 1000}, + {"seed": 3, "exit_code": 0, "steps": 250, "actions": 240, "monotonic_millis": 1000, "first_violation_origin_step": 250, "violated_properties": []string{"p"}}, + {"seed": 4, "exit_code": -1, "timed_out": true, "actions": 0}, + }) + writeCampaign(t, post, map[string]any{"arm": "post", "max_steps": 400, "seeds": declared}, []map[string]any{ + {"seed": 1, "exit_code": 0, "steps": 40, "actions": 38, "monotonic_millis": 1000, "first_violation_origin_step": 40, "violated_properties": []string{"p"}}, + {"seed": 2, "exit_code": 0, "steps": 60, "actions": 55, "monotonic_millis": 1000, "first_violation_origin_step": 60, "violated_properties": []string{"p"}}, + {"seed": 3, "exit_code": 0, "steps": 50, "actions": 47, "monotonic_millis": 1000, "first_violation_origin_step": 50, "violated_properties": []string{"p"}}, + {"seed": 4, "exit_code": 0, "steps": 70, "actions": 66, "monotonic_millis": 1000, "first_violation_origin_step": 70, "violated_properties": []string{"p"}}, + }) + + result := analyseCampaigns(t, "--paired", pre, post) + if result.Paired == nil { + t.Fatal("no paired comparison") + } + if result.Paired.Pairs != 3 { + t.Errorf("%d pairs, want the 3 seeds usable on both arms", result.Paired.Pairs) + } + if len(result.Paired.UnpairedSeeds) != 1 || result.Paired.UnpairedSeeds[0] != 4 { + t.Errorf("unpaired seeds %v, want [4]", result.Paired.UnpairedSeeds) + } + for _, summary := range result.Arms { + if len(summary.MissingSeeds) != 2 { + t.Errorf("arm %s missing seeds %v, want seeds 5 and 6", summary.Arm, summary.MissingSeeds) + } + } + + var stdout bytes.Buffer + if err := run([]string{"--paired", pre, post}, &stdout, io.Discard); err != nil { + t.Fatal(err) + } + if !strings.Contains(stdout.String(), "usable in one arm only") { + t.Errorf("the report does not name the lost seed\n%s", stdout.String()) + } +} + +func TestRun_PairedRefusesAnythingOtherThanTwoArms(t *testing.T) { + root := t.TempDir() + var directories []string + for _, name := range []string{"a", "b", "c"} { + directory := filepath.Join(root, name) + writeCampaign(t, directory, map[string]any{"arm": name, "max_steps": 40, "seeds": []int{1}}, + []map[string]any{{"seed": 1, "exit_code": 0, "steps": 40, "actions": 40}}) + directories = append(directories, directory) + } + err := run(append([]string{"--paired"}, directories...), io.Discard, io.Discard) + if err == nil || !strings.Contains(err.Error(), "exactly two arms") { + t.Fatalf("error %v, want a refusal to pair three arms", err) + } +} + +func TestRun_PairedRefusesArmsThatShareNoSeed(t *testing.T) { + root := t.TempDir() + north := filepath.Join(root, "north") + south := filepath.Join(root, "south") + writeCampaign(t, north, map[string]any{"arm": "north", "max_steps": 40, "seeds": []int{1, 2}}, + []map[string]any{{"seed": 1, "exit_code": 0, "steps": 40, "actions": 40}}) + writeCampaign(t, south, map[string]any{"arm": "south", "max_steps": 40, "seeds": []int{3, 4}}, + []map[string]any{{"seed": 3, "exit_code": 0, "steps": 40, "actions": 40}}) + + err := run([]string{"--paired", north, south}, io.Discard, io.Discard) + if err == nil || !strings.Contains(err.Error(), "share no seed") { + t.Fatalf("error %v, want a refusal to pair arms that ran different seeds", err) + } +} diff --git a/cmd/internal-tools/analyze/load.go b/cmd/internal-tools/analyze/load.go index 36f8e83..3210f09 100644 --- a/cmd/internal-tools/analyze/load.go +++ b/cmd/internal-tools/analyze/load.go @@ -42,11 +42,16 @@ type runRecord struct { 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"` - FirstViolationOriginStep *int `json:"first_violation_origin_step"` - ViolatedProperties []string `json:"violated_properties"` + DurationMillis int64 `json:"duration_millis"` + TraceError string `json:"trace_error"` + Steps int `json:"steps"` + FirstViolationOriginStep *int `json:"first_violation_origin_step"` + // FirstViolationDetectedStep is the step the violation was reported on, + // which is the origin step for a safety property tripping under its own + // action and the end of the budget for an obligation that never discharged. + // It is what the survival analysis times the event by; see eventStep. + FirstViolationDetectedStep *int `json:"first_violation_detected_step"` + ViolatedProperties []string `json:"violated_properties"` // Actions is the count of steps that dispatched an action, and it is a // pointer so that a runs.jsonl written before the campaign tool counted // them is refused rather than read as an arm that acted zero times. The @@ -66,11 +71,14 @@ const ( ) type classifiedRun struct { - Seed int64 - Steps int - Actions int - MonotonicMillis int64 - OriginStep int + Seed int64 + Steps int + Actions int + MonotonicMillis int64 + OriginStep int + // EventStep is when the run could know, and it is what the survival + // analysis measures. It is the origin step whenever the two agree. + EventStep int Violated bool ClampedToBudget bool ViolatedProperties []string @@ -183,17 +191,37 @@ func classify(record runRecord, budget int) classifiedRun { return item } item.Violated = true - if origin > budget { + item.OriginStep = origin + item.EventStep = eventStep(record, origin) + if item.EventStep > budget { // The run-end finalize line reports obligations that never discharged // at an index one past the last executed step. That is a real detection // but not a real step, so it is held at the budget and counted. - origin = budget + item.EventStep = budget item.ClampedToBudget = true } - item.OriginStep = origin return item } +// eventStep is the step at which the run could know it had violated. A safety +// property tripping under its own action is detected on the step that armed it +// and the two agree. An obligation that never discharges is reported when the +// run ends, and timing that at the step that armed it would record a liveness +// failure flushed at the budget as a violation found on the first step, which +// is a number the run cannot support and which no censored run can be compared +// against: the budget is the clock the clean runs are censored on, so the events +// have to be on it too. A campaign written before the field existed carries no +// detected step and keeps the origin. +func eventStep(record runRecord, origin int) int { + if record.FirstViolationDetectedStep == nil { + return origin + } + if detected := *record.FirstViolationDetectedStep; detected > origin { + return detected + } + return origin +} + // groupArms folds every campaign directory into its arm. Two directories with // the same arm label are pooled, which is how a campaign split across hosts is // analysed, but they must agree on the step budget. @@ -250,15 +278,18 @@ func (a arm) observations() []observation { if item.ExcludedBecause != "" { continue } - if item.Violated { - result = append(result, observation{Steps: float64(item.OriginStep), Event: true}) - continue - } - result = append(result, observation{Steps: float64(a.Budget), Event: false}) + result = append(result, observationOf(item, a.Budget)) } return result } +func observationOf(item classifiedRun, budget int) observation { + if item.Violated { + return observation{Steps: float64(item.EventStep), Event: true} + } + return observation{Steps: float64(budget), Event: false} +} + // stepTimes is the observations flattened to plain numbers, censored runs held // at the budget. Holding them there rather than dropping them is conservative: // it can only understate how much sooner a violating arm finds its first diff --git a/cmd/internal-tools/analyze/load_test.go b/cmd/internal-tools/analyze/load_test.go index f4099dc..c787bd7 100644 --- a/cmd/internal-tools/analyze/load_test.go +++ b/cmd/internal-tools/analyze/load_test.go @@ -63,7 +63,7 @@ func TestClassify_ViolationIsAnEventAtTheOriginStep(t *testing.T) { // silently turned into a censored run. func TestClassify_ViolationPastTheBudgetIsHeldAtTheBudget(t *testing.T) { item := classify(runRecord{FirstViolationOriginStep: stepPointer(51)}, 50) - if !item.Violated || item.OriginStep != 50 || !item.ClampedToBudget { + if !item.Violated || item.EventStep != 50 || !item.ClampedToBudget { t.Errorf("run %+v, want a clamped event at 50", item) } } diff --git a/cmd/internal-tools/analyze/quantile.go b/cmd/internal-tools/analyze/quantile.go new file mode 100644 index 0000000..d63de23 --- /dev/null +++ b/cmd/internal-tools/analyze/quantile.go @@ -0,0 +1,17 @@ +package main + +// quantileSurvival is the smallest step count at which the product-limit +// estimate falls to or below 1-fraction, which is the fraction-th quantile of +// steps to first violation. It is undefined whenever the curve never falls that +// far, which is what an arm where most runs exhaust the budget produces, and the +// second return value says so rather than substituting a number the data does +// not contain. +func quantileSurvival(curve []survivalPoint, fraction float64) (float64, bool) { + threshold := 1 - fraction + for _, point := range curve { + if point.Survival <= threshold { + return point.Steps, true + } + } + return 0, false +} diff --git a/cmd/internal-tools/analyze/report.go b/cmd/internal-tools/analyze/report.go index f449f22..63bcff3 100644 --- a/cmd/internal-tools/analyze/report.go +++ b/cmd/internal-tools/analyze/report.go @@ -14,7 +14,7 @@ import ( func writeReport(result analysis, out io.Writer) { fmt.Fprintf(out, "primary outcome: %s\n\n", result.Outcome) - writeTable(out, []string{"arm", "runs", "violated", "censored", "excluded", "missing", "median steps", "violation rate"}, + writeTable(out, []string{"arm", "runs", "violated", "censored", "excluded", "missing", "median steps", "iqr steps", "violation rate"}, func(add func(...string)) { for _, summary := range result.Arms { add( @@ -25,6 +25,7 @@ func writeReport(result analysis, out io.Writer) { strconv.Itoa(summary.Excluded), strconv.Itoa(len(summary.MissingSeeds)), formatMedian(summary.MedianStepsToFirstViolation), + formatMedian(summary.FirstQuartileSteps)+" to "+formatMedian(summary.ThirdQuartileSteps), formatRatio(summary.ViolationRate, 3), ) } @@ -68,6 +69,13 @@ func writeReport(result analysis, out io.Writer) { summary.Arm, summary.EventsHeldAtBudget, summary.StepBudget) } } + for _, summary := range result.Arms { + if summary.EventsDetectedAfterOrigin > 0 { + fmt.Fprintf(out, "\n%s timed %d violation(s) at the step they were detected rather than the step that armed them, "+ + "which is what an obligation reported only when the run ended looks like", + summary.Arm, summary.EventsDetectedAfterOrigin) + } + } if len(result.Arms) > 0 { fmt.Fprintln(out) } diff --git a/cmd/internal-tools/analyze/survival.go b/cmd/internal-tools/analyze/survival.go index b107f2a..e8a4ff2 100644 --- a/cmd/internal-tools/analyze/survival.go +++ b/cmd/internal-tools/analyze/survival.go @@ -67,12 +67,7 @@ func kaplanMeier(observations []observation) []survivalPoint { // and the second return value says so: substituting a mean there would report a // number the data does not contain. func medianSurvival(curve []survivalPoint) (float64, bool) { - for _, point := range curve { - if point.Survival <= 0.5 { - return point.Steps, true - } - } - return 0, false + return quantileSurvival(curve, 0.5) } func distinctSteps(observations []observation) []float64 {