fix(campaign): record both clocks a run was measured on

Duration came from the monotonic clock, which does not advance while a host
sleeps: one calibration run under-reported by about 15 minutes. A run now
carries monotonic_millis for how long it worked and wall_clock_millis for how
much time passed, which is what makes a sleep visible at all.

Claude-Session: https://claude.ai/code/session_01A5KmftdEJ49A9z5mF5ESrX
This commit is contained in:
pj committed 2026-08-14 17:43:12 +05:30
1 parent 95a474339e
commit c63a2e4897
2 files changed
+78 -7

No files matched your search

+33 -7
View File
@@ -51,7 +51,10 @@ func executeCommand(ctx context.Context, binary string, arguments []string, outp
// escalation would land while the run was still doing what it was asked. // escalation would land while the run was still doing what it was asked.
const runShutdownGrace = 30 * time.Second 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 { type runRecord struct {
Seed int64 `json:"seed"` Seed int64 `json:"seed"`
Device string `json:"device,omitempty"` Device string `json:"device,omitempty"`
@@ -59,17 +62,37 @@ type runRecord struct {
LaunchError string `json:"launch_error,omitempty"` LaunchError string `json:"launch_error,omitempty"`
TimedOut bool `json:"timed_out,omitempty"` TimedOut bool `json:"timed_out,omitempty"`
StartedAt time.Time `json:"started_at"` StartedAt time.Time `json:"started_at"`
DurationMillis int64 `json:"duration_millis"` MonotonicMillis int64 `json:"monotonic_millis"`
WallClockMillis int64 `json:"wall_clock_millis"`
RunDirectory string `json:"run_directory,omitempty"` RunDirectory string `json:"run_directory,omitempty"`
TraceError string `json:"trace_error,omitempty"` TraceError string `json:"trace_error,omitempty"`
traceSummary 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 { type campaign struct {
configuration config configuration config
executor commandExecutor executor commandExecutor
stdout io.Writer stdout io.Writer
records io.Writer records io.Writer
clocks clocks
mutex sync.Mutex mutex sync.Mutex
failures int failures int
unreadable int unreadable int
@@ -105,7 +128,7 @@ func runCampaign(ctx context.Context, configuration config, executor commandExec
} }
defer recordsFile.Close() 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", fmt.Fprintf(stdout, "campaign %s: %d seeds, %d worker(s), %s\n",
configuration.arm, len(configuration.seeds), len(workerDevices(configuration.devices)), configuration.outputDirectory) configuration.arm, len(configuration.seeds), len(workerDevices(configuration.devices)), configuration.outputDirectory)
sweep.sweep(ctx) 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) runCtx, cancelRun := context.WithTimeout(ctx, c.configuration.runTimeout)
defer cancelRun() 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) exitCode, runErr := c.executor(runCtx, c.configuration.sanderlingPath, runArguments(c.configuration, seedText, device), logFile)
if runCtx.Err() != nil && ctx.Err() == nil { if runCtx.Err() != nil && ctx.Err() == nil {
record.TimedOut = true 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 record.ExitCode = exitCode
if runErr != nil { if runErr != nil {
record.LaunchError = runErr.Error() record.LaunchError = runErr.Error()
@@ -222,9 +247,10 @@ func (c *campaign) report(record runRecord) {
if err := json.NewEncoder(c.records).Encode(record); err != nil { 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, "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, 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 { func outcome(record runRecord) string {
@@ -69,6 +69,51 @@ func writeFakeRun(t *testing.T, arguments []string, steps []trace.Step) {
writeRunDirectory(t, argumentValue(arguments, "--output"), "20260101-000000", steps) 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) { func TestRunCampaign_RecordsDispatchedActionsNotSteps(t *testing.T) {
directory := t.TempDir() directory := t.TempDir()
configuration := testConfiguration(t, directory, "--seeds", "1") configuration := testConfiguration(t, directory, "--seeds", "1")