diff --git a/cmd/internal-tools/campaign/campaign.go b/cmd/internal-tools/campaign/campaign.go index e022732..dce9206 100644 --- a/cmd/internal-tools/campaign/campaign.go +++ b/cmd/internal-tools/campaign/campaign.go @@ -51,25 +51,48 @@ func executeCommand(ctx context.Context, binary string, arguments []string, outp // escalation would land while the run was still doing what it was asked. const runShutdownGrace = 30 * time.Second -// runRecord is one line of runs.jsonl. +// runRecord is one line of runs.jsonl. MonotonicMillis is how long the run +// worked and WallClockMillis is how much time passed; they answer different +// questions and differ by however long the host slept mid-run, which an +// unattended overnight sweep is exactly where to expect. type runRecord struct { - Seed int64 `json:"seed"` - Device string `json:"device,omitempty"` - ExitCode int `json:"exit_code"` - LaunchError string `json:"launch_error,omitempty"` - TimedOut bool `json:"timed_out,omitempty"` - StartedAt time.Time `json:"started_at"` - DurationMillis int64 `json:"duration_millis"` - RunDirectory string `json:"run_directory,omitempty"` - TraceError string `json:"trace_error,omitempty"` + Seed int64 `json:"seed"` + Device string `json:"device,omitempty"` + ExitCode int `json:"exit_code"` + LaunchError string `json:"launch_error,omitempty"` + TimedOut bool `json:"timed_out,omitempty"` + StartedAt time.Time `json:"started_at"` + MonotonicMillis int64 `json:"monotonic_millis"` + WallClockMillis int64 `json:"wall_clock_millis"` + RunDirectory string `json:"run_directory,omitempty"` + TraceError string `json:"trace_error,omitempty"` traceSummary } +// clocks reads the two measures a run is timed on. The monotonic clock does +// not advance while the host is asleep, so on its own it reports a run that +// slept through a quarter of an hour as a quarter of an hour shorter than it +// was; the wall clock advances but can be stepped by the host. +type clocks struct { + monotonicNow func() time.Time + wallClockNow func() time.Time +} + +func systemClocks() clocks { + return clocks{ + monotonicNow: time.Now, + // Round(0) drops the monotonic reading time.Now carries, so + // subtracting two of these readings uses the wall clock. + wallClockNow: func() time.Time { return time.Now().Round(0) }, + } +} + type campaign struct { configuration config executor commandExecutor stdout io.Writer records io.Writer + clocks clocks mutex sync.Mutex failures int unreadable int @@ -105,7 +128,7 @@ func runCampaign(ctx context.Context, configuration config, executor commandExec } defer recordsFile.Close() - sweep := &campaign{configuration: configuration, executor: executor, stdout: stdout, records: recordsFile} + sweep := &campaign{configuration: configuration, executor: executor, stdout: stdout, records: recordsFile, clocks: systemClocks()} fmt.Fprintf(stdout, "campaign %s: %d seeds, %d worker(s), %s\n", configuration.arm, len(configuration.seeds), len(workerDevices(configuration.devices)), configuration.outputDirectory) sweep.sweep(ctx) @@ -188,12 +211,14 @@ func (c *campaign) runSeed(ctx context.Context, seed int64, device string) runRe runCtx, cancelRun := context.WithTimeout(ctx, c.configuration.runTimeout) defer cancelRun() - start := time.Now() + monotonicStart := c.clocks.monotonicNow() + wallClockStart := c.clocks.wallClockNow() exitCode, runErr := c.executor(runCtx, c.configuration.sanderlingPath, runArguments(c.configuration, seedText, device), logFile) if runCtx.Err() != nil && ctx.Err() == nil { record.TimedOut = true } - record.DurationMillis = time.Since(start).Milliseconds() + record.MonotonicMillis = c.clocks.monotonicNow().Sub(monotonicStart).Milliseconds() + record.WallClockMillis = c.clocks.wallClockNow().Sub(wallClockStart).Milliseconds() record.ExitCode = exitCode if runErr != nil { record.LaunchError = runErr.Error() @@ -222,9 +247,10 @@ func (c *campaign) report(record runRecord) { if err := json.NewEncoder(c.records).Encode(record); err != nil { fmt.Fprintf(c.stdout, "warning: seed %d record: %v\n", record.Seed, err) } - fmt.Fprintf(c.stdout, "seed=%d device=%q outcome=%s steps=%d exit=%d duration=%s\n", + fmt.Fprintf(c.stdout, "seed=%d device=%q outcome=%s steps=%d exit=%d monotonic=%s wall_clock=%s\n", record.Seed, record.Device, outcome(record), record.Steps, record.ExitCode, - time.Duration(record.DurationMillis)*time.Millisecond) + time.Duration(record.MonotonicMillis)*time.Millisecond, + time.Duration(record.WallClockMillis)*time.Millisecond) } func outcome(record runRecord) string { diff --git a/cmd/internal-tools/campaign/campaign_test.go b/cmd/internal-tools/campaign/campaign_test.go index 23fbdcf..9d044f6 100644 --- a/cmd/internal-tools/campaign/campaign_test.go +++ b/cmd/internal-tools/campaign/campaign_test.go @@ -69,6 +69,51 @@ func writeFakeRun(t *testing.T, arguments []string, steps []trace.Step) { writeRunDirectory(t, argumentValue(arguments, "--output"), "20260101-000000", steps) } +// readings hands out the given instants in turn, so a test can script a clock +// that jumps across a host sleep independently of one that stops through it. +func readings(instants ...time.Time) func() time.Time { + var index int + return func() time.Time { + instant := instants[min(index, len(instants)-1)] + index++ + return instant + } +} + +// A sleeping host stops the monotonic clock and not the wall clock, so a run +// timed on the monotonic clock alone reports the sleep as time that never +// passed. The record carries both, named for the clock each came from. +func TestRunSeed_RecordsTheTimeWorkedAndTheTimeThatPassed(t *testing.T) { + directory := t.TempDir() + startedAt := time.Date(2026, 8, 14, 2, 0, 0, 0, time.UTC) + var records bytes.Buffer + sweep := &campaign{ + configuration: testConfiguration(t, directory, "--seeds", "1"), + executor: func(context.Context, string, []string, io.Writer) (int, error) { + return 0, nil + }, + stdout: io.Discard, + records: &records, + clocks: clocks{ + monotonicNow: readings(startedAt, startedAt.Add(2*time.Minute)), + wallClockNow: readings(startedAt, startedAt.Add(17*time.Minute)), + }, + } + + sweep.report(sweep.runSeed(context.Background(), 1, "")) + + var written map[string]any + if err := json.Unmarshal(records.Bytes(), &written); err != nil { + t.Fatalf("decode %q: %v", records.String(), err) + } + if written["monotonic_millis"] != float64((2 * time.Minute).Milliseconds()) { + t.Errorf("monotonic_millis %v, want the two minutes of work", written["monotonic_millis"]) + } + if written["wall_clock_millis"] != float64((17 * time.Minute).Milliseconds()) { + t.Errorf("wall_clock_millis %v, want the seventeen minutes that passed", written["wall_clock_millis"]) + } +} + func TestRunCampaign_RecordsDispatchedActionsNotSteps(t *testing.T) { directory := t.TempDir() configuration := testConfiguration(t, directory, "--seeds", "1")