From 2ec91f4493449db7e7190696bf8c2a6c64b23e52 Mon Sep 17 00:00:00 2001 From: Vasanthdev2004 Date: Thu, 16 Jul 2026 12:04:21 +0530 Subject: [PATCH 1/8] Add per-turn tracing and a turn-benchmark harness (Phase 0 baseline) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Introduce an opt-in `internal/trace` package that attributes a run's wall time to named spans — prompt build, provider connect/queue, generation, tool queue/execution, permission wait, verification, compaction, persistence — plus counters for model requests, tool calls, retries, reconnects, compactions, completion nudges, acceptance checks, model switches, and input/cached/output tokens. The recorder is nil-safe (a nil *Recorder is a no-op), so every stamp site can call it unguarded; an untraced run is byte-identical to today. The recorder threads into agent.Run via a new `Options.Trace` field and a single `trace.WithContext` assignment, so the shared providerio seam (connect around client.Do, queue around OAuth resolve, first token at the first non-keepalive SSE payload) reaches it through `trace.FromContext` without any provider-interface change. All instrumentation is opt-in: when `Options.Trace` is nil the hot path is untouched. Headless `zero exec` gains `--trace ` (and `ZERO_TRACE=`), writing an agenteval-contract-compatible NDJSON trace (`-` for stderr). The trace is pure observation; enabling it does not change behavior. A new per-turn benchmark harness extends `internal/perfbench` (reusing the existing TaskSet/NumericStats/subprocess runner shapes): `RunTurnBench` aggregates per-span median/P95 across iterations, ranks the top three controllable latency sources by share of attributed time, rolls up per task class, and totals tokens/counts. A checked-in 42-task manifest across seven classes (nav, edit, fix, refactor, longproc, longctx, parallel) and local offline fixtures back it, and `make baseline` runs it against the built `zero`, writing `internal/perfbench/reports/baseline.json`. The report is machine-specific and regenerated, not hand-edited. The manifest is JSON rather than YAML to avoid adding a dependency; per-task verification targets the specific test (`go test -run `) so fix tasks are independent. Each task is a fresh `zero exec` process, so iterations are cold-start samples; a warm in-process path is left for follow-up. Verified: `go build ./...`, `go vet ./...`, `gofmt -l` clean on touched files; `go test -race` green for internal/trace, internal/agent, internal/perfbench, and cmd/zero-perf-bench. --- Makefile | 18 +- cmd/zero-perf-bench/main.go | 4 + cmd/zero-perf-bench/turn.go | 238 +++ internal/agent/compaction.go | 7 + internal/agent/loop.go | 51 +- internal/agent/reconnect.go | 11 + internal/agent/types.go | 8 + internal/cli/exec.go | 56 + internal/cli/exec_parse.go | 9 + internal/perfbench/manifests/baseline.json | 60 + internal/perfbench/reports/.gitkeep | 0 internal/perfbench/reports/README.md | 40 + internal/perfbench/taskbench.go | 5 +- internal/perfbench/testdata/fix/bugs.go | 89 ++ internal/perfbench/testdata/fix/bugs_test.go | 68 + internal/perfbench/testdata/longctx/big.go | 1287 +++++++++++++++++ internal/perfbench/testdata/longproc/main.go | 21 + .../perfbench/testdata/longproc/main_test.go | 15 + internal/perfbench/testdata/nav/README.md | 3 + internal/perfbench/testdata/nav/config.json | 5 + internal/perfbench/testdata/nav/main.go | 24 + internal/perfbench/testdata/parallel/a.txt | 4 + internal/perfbench/testdata/parallel/b.txt | 4 + internal/perfbench/testdata/parallel/c.txt | 4 + .../perfbench/testdata/parallel/config1.json | 1 + .../perfbench/testdata/parallel/config2.json | 1 + .../perfbench/testdata/parallel/config3.json | 1 + .../perfbench/testdata/parallel/config4.json | 1 + .../perfbench/testdata/parallel/config5.json | 1 + .../perfbench/testdata/parallel/config6.json | 1 + internal/perfbench/testdata/parallel/d.txt | 4 + .../perfbench/testdata/parallel/dir1/notes.md | 1 + .../perfbench/testdata/parallel/dir2/notes.md | 1 + .../perfbench/testdata/parallel/dir3/notes.md | 1 + .../perfbench/testdata/parallel/dir4/notes.md | 1 + .../perfbench/testdata/parallel/dir5/notes.md | 1 + .../perfbench/testdata/parallel/dir6/notes.md | 1 + internal/perfbench/testdata/parallel/e.txt | 4 + internal/perfbench/testdata/parallel/f.txt | 4 + internal/perfbench/testdata/refactor/main.go | 55 + internal/perfbench/turn_bench.go | 434 ++++++ internal/perfbench/turn_bench_test.go | 302 ++++ internal/providers/providerio/auth.go | 7 + internal/providers/providerio/providerio.go | 4 + internal/providers/providerio/retry.go | 7 + internal/trace/context.go | 25 + internal/trace/emit.go | 153 ++ internal/trace/parse.go | 91 ++ internal/trace/recorder.go | 187 +++ internal/trace/trace.go | 152 ++ internal/trace/trace_test.go | 268 ++++ 51 files changed, 3736 insertions(+), 4 deletions(-) create mode 100644 cmd/zero-perf-bench/turn.go create mode 100644 internal/perfbench/manifests/baseline.json create mode 100644 internal/perfbench/reports/.gitkeep create mode 100644 internal/perfbench/reports/README.md create mode 100644 internal/perfbench/testdata/fix/bugs.go create mode 100644 internal/perfbench/testdata/fix/bugs_test.go create mode 100644 internal/perfbench/testdata/longctx/big.go create mode 100644 internal/perfbench/testdata/longproc/main.go create mode 100644 internal/perfbench/testdata/longproc/main_test.go create mode 100644 internal/perfbench/testdata/nav/README.md create mode 100644 internal/perfbench/testdata/nav/config.json create mode 100644 internal/perfbench/testdata/nav/main.go create mode 100644 internal/perfbench/testdata/parallel/a.txt create mode 100644 internal/perfbench/testdata/parallel/b.txt create mode 100644 internal/perfbench/testdata/parallel/c.txt create mode 100644 internal/perfbench/testdata/parallel/config1.json create mode 100644 internal/perfbench/testdata/parallel/config2.json create mode 100644 internal/perfbench/testdata/parallel/config3.json create mode 100644 internal/perfbench/testdata/parallel/config4.json create mode 100644 internal/perfbench/testdata/parallel/config5.json create mode 100644 internal/perfbench/testdata/parallel/config6.json create mode 100644 internal/perfbench/testdata/parallel/d.txt create mode 100644 internal/perfbench/testdata/parallel/dir1/notes.md create mode 100644 internal/perfbench/testdata/parallel/dir2/notes.md create mode 100644 internal/perfbench/testdata/parallel/dir3/notes.md create mode 100644 internal/perfbench/testdata/parallel/dir4/notes.md create mode 100644 internal/perfbench/testdata/parallel/dir5/notes.md create mode 100644 internal/perfbench/testdata/parallel/dir6/notes.md create mode 100644 internal/perfbench/testdata/parallel/e.txt create mode 100644 internal/perfbench/testdata/parallel/f.txt create mode 100644 internal/perfbench/testdata/refactor/main.go create mode 100644 internal/perfbench/turn_bench.go create mode 100644 internal/perfbench/turn_bench_test.go create mode 100644 internal/trace/context.go create mode 100644 internal/trace/emit.go create mode 100644 internal/trace/parse.go create mode 100644 internal/trace/recorder.go create mode 100644 internal/trace/trace.go create mode 100644 internal/trace/trace_test.go diff --git a/Makefile b/Makefile index 91fa72bf6..4e9734450 100644 --- a/Makefile +++ b/Makefile @@ -1,7 +1,7 @@ # Zero build/test/lint targets. AGENTS.md says "Build with `make`" and "Run `make # lint` before opening a PR" — these targets back those instructions. .DEFAULT_GOAL := build -.PHONY: build build-all test test-race vet fmt fmt-check lint tidy clean help +.PHONY: build build-all test test-race vet fmt fmt-check lint tidy clean baseline help # Build the main CLI binary into ./zero. build: @@ -40,5 +40,19 @@ clean: rm -f zero go clean ./... +# Run the per-turn benchmark harness over the checked-in baseline manifest and +# write the JSON result to internal/perfbench/reports/baseline.json. Requires a +# built `zero` binary and a model; set ZERO_BENCH_MODEL (required) and +# ZERO_BENCH_BINARY (defaults to ./zero) to configure the run. The report is +# machine-specific and regenerated, not hand-edited. +baseline: build + @if [ -z "$(ZERO_BENCH_MODEL)" ]; then echo "Set ZERO_BENCH_MODEL (and optionally ZERO_BENCH_BINARY) before running 'make baseline'"; exit 2; fi + @ZERO_BIN="$${ZERO_BENCH_BINARY:-./zero}"; \ + go run ./cmd/zero-perf-bench turn \ + --suite internal/perfbench/manifests/baseline.json \ + --model $(ZERO_BENCH_MODEL) \ + --binary "$$ZERO_BIN" \ + --output internal/perfbench/reports/baseline.json + help: - @echo "Targets: build (default), build-all, test, test-quick, vet, fmt, fmt-check, lint, tidy, clean" + @echo "Targets: build (default), build-all, test, test-quick, vet, fmt, fmt-check, lint, tidy, clean, baseline" diff --git a/cmd/zero-perf-bench/main.go b/cmd/zero-perf-bench/main.go index 436afebfb..121eca9fa 100644 --- a/cmd/zero-perf-bench/main.go +++ b/cmd/zero-perf-bench/main.go @@ -39,6 +39,9 @@ func run(args []string, getenv func(string) string, stdout io.Writer, stderr io. if len(args) > 0 && args[0] == "tasks" { return runTasksCommand(args[1:], getenv, stdout, stderr) } + if len(args) > 0 && args[0] == "turn" { + return runTurnCommand(args[1:], getenv, stdout, stderr) + } options, err := parseArgs(args, getenv) if err != nil { _, _ = fmt.Fprintln(stderr, err.Error()) @@ -206,6 +209,7 @@ func helpText() string { return strings.Join([]string{ "Usage: zero-perf-bench [options]", " zero-perf-bench tasks [options] (Terminal-Bench-style task harness; see `tasks --help`)", + " zero-perf-bench turn [options] (per-turn tracing benchmark; see `turn --help`)", "", "Options:", " --iterations Measured samples to collect (default: 5)", diff --git a/cmd/zero-perf-bench/turn.go b/cmd/zero-perf-bench/turn.go new file mode 100644 index 000000000..0286e8c0b --- /dev/null +++ b/cmd/zero-perf-bench/turn.go @@ -0,0 +1,238 @@ +package main + +import ( + "bytes" + "context" + "fmt" + "io" + "os" + "path/filepath" + "strings" + + "github.com/Gitlawb/zero/internal/perfbench" +) + +// turnOptions configures the `zero-perf-bench turn` subcommand: the per-turn +// benchmark harness that runs ZERO headlessly with --trace, parses each turn's +// NDJSON trace, and records per-span latency plus the top controllable latency +// sources — the Phase 0 baseline's "do not proceed until" criterion. +type turnOptions struct { + SuitePath string + Model string + Mode string + SelfCorrect bool + Binary string + Iterations int + Version string + Commit string + Output string + JSON bool + DryRun bool + Help bool +} + +func runTurnCommand(args []string, getenv func(string) string, stdout io.Writer, stderr io.Writer) int { + options, err := parseTurnArgs(args, getenv) + if err != nil { + _, _ = fmt.Fprintln(stderr, err.Error()) + return 2 + } + if options.Help { + _, _ = fmt.Fprint(stdout, turnHelpText()) + return 0 + } + + set, err := perfbench.LoadTaskSet(options.SuitePath) + if err != nil { + _, _ = fmt.Fprintln(stderr, "[zero] Turn benchmark failed: "+err.Error()) + return 1 + } + + // The dry-run path records a zero-iteration run without a binary, so the + // manifest loads and the report path is exercised in CI without a model. + if options.DryRun { + _, _ = fmt.Fprintln(stdout, "[zero] turn benchmark: dry run (no agent invoked)") + return 0 + } + + binary, err := perfbench.ResolveBinary(options.Binary) + if err != nil { + _, _ = fmt.Fprintln(stderr, "[zero] Turn benchmark failed: "+err.Error()) + return 2 + } + + result, err := perfbench.RunTurnBench(context.Background(), set, perfbench.TurnBenchConfig{ + Model: options.Model, + Mode: options.Mode, + SelfCorrect: options.SelfCorrect, + Version: options.Version, + Commit: options.Commit, + Iterations: options.Iterations, + Runner: perfbench.NewTurnExecRunner(binary), + }) + if err != nil { + _, _ = fmt.Fprintln(stderr, "[zero] Turn benchmark failed: "+err.Error()) + return 1 + } + + if options.Output != "" { + if err := writeTurnReport(options.Output, result); err != nil { + _, _ = fmt.Fprintln(stderr, "[zero] Turn benchmark failed: "+err.Error()) + return 1 + } + } + if options.JSON { + if err := perfbench.WriteTurnBenchJSON(stdout, result); err != nil { + _, _ = fmt.Fprintln(stderr, "[zero] Turn benchmark failed: "+err.Error()) + return 1 + } + return 0 + } + _, _ = fmt.Fprintln(stdout, perfbench.FormatTurnBenchSummary(result)) + return 0 +} + +func parseTurnArgs(args []string, getenv func(string) string) (turnOptions, error) { + options := turnOptions{ + Iterations: 1, + Version: strings.TrimSpace(getenv("ZERO_BENCH_VERSION")), + Commit: strings.TrimSpace(getenv("ZERO_BENCH_COMMIT")), + } + for index := 0; index < len(args); index++ { + arg := args[index] + flag, inlineValue := splitFlagValue(arg) + switch flag { + case "--suite": + value, next, err := readOptionValue(args, inlineValue, index, flag) + if err != nil { + return options, err + } + options.SuitePath = value + index = next + case "--model": + value, next, err := readOptionValue(args, inlineValue, index, flag) + if err != nil { + return options, err + } + options.Model = value + index = next + case "--mode": + value, next, err := readOptionValue(args, inlineValue, index, flag) + if err != nil { + return options, err + } + options.Mode = value + index = next + case "--binary": + value, next, err := readOptionValue(args, inlineValue, index, flag) + if err != nil { + return options, err + } + options.Binary = value + index = next + case "--iterations": + value, next, err := readOptionValue(args, inlineValue, index, flag) + if err != nil { + return options, err + } + parsed, err := parsePositiveInteger(flag, value) + if err != nil { + return options, err + } + options.Iterations = parsed + index = next + case "--version": + value, next, err := readOptionValue(args, inlineValue, index, flag) + if err != nil { + return options, err + } + options.Version = value + index = next + case "--commit": + value, next, err := readOptionValue(args, inlineValue, index, flag) + if err != nil { + return options, err + } + options.Commit = value + index = next + case "--output": + value, next, err := readOptionValue(args, inlineValue, index, flag) + if err != nil { + return options, err + } + options.Output = value + index = next + case "--self-correct": + if strings.Contains(arg, "=") { + return options, fmt.Errorf("%s does not accept a value", flag) + } + options.SelfCorrect = true + case "--json": + if strings.Contains(arg, "=") { + return options, fmt.Errorf("%s does not accept a value", flag) + } + options.JSON = true + case "--dry-run": + if strings.Contains(arg, "=") { + return options, fmt.Errorf("%s does not accept a value", flag) + } + options.DryRun = true + case "-h", "--help": + if strings.Contains(arg, "=") { + return options, fmt.Errorf("%s does not accept a value", flag) + } + options.Help = true + default: + return options, fmt.Errorf("unknown option: %s", arg) + } + } + if options.Help { + return options, nil + } + if strings.TrimSpace(options.SuitePath) == "" { + return options, fmt.Errorf("--suite is required") + } + if strings.TrimSpace(options.Model) == "" && !options.DryRun { + return options, fmt.Errorf("--model is required (or pass --dry-run)") + } + return options, nil +} + +func writeTurnReport(path string, result perfbench.TurnBenchResult) error { + if dir := filepath.Dir(path); dir != "" { + if err := os.MkdirAll(dir, 0o755); err != nil { + return err + } + } + var buffer bytes.Buffer + if err := perfbench.WriteTurnBenchJSON(&buffer, result); err != nil { + return err + } + return os.WriteFile(path, buffer.Bytes(), 0o644) +} + +func turnHelpText() string { + return strings.Join([]string{ + "Usage: zero-perf-bench turn [options]", + "", + "Runs ZERO headlessly with --trace against a per-turn benchmark task set and", + "records per-span latency plus the top controllable latency sources (the", + "Phase 0 baseline's \"do not proceed until\" criterion). Each task is a fresh", + "`zero exec` process, so iterations are cold-start samples; a warm path needs", + "an in-process runner (future work).", + "", + "Options:", + " --suite Task set JSON file (required)", + " --model Model to run (required unless --dry-run)", + " --mode Exec mode preset to apply", + " --self-correct Enable the post-edit verify-and-correct loop", + " --binary Path to the `zero` binary (default: zero on PATH / repo root)", + " --iterations Times to run each task (default: 1)", + " --version Record the ZERO version (default: $ZERO_BENCH_VERSION)", + " --commit Record the ZERO commit (default: $ZERO_BENCH_COMMIT)", + " --output Write the JSON result to path", + " --json Print only the JSON result", + " --dry-run Load the manifest and exit without invoking the agent", + " -h, --help Show this help", + }, "\n") + "\n" +} diff --git a/internal/agent/compaction.go b/internal/agent/compaction.go index 75e353cf0..7c87c16a4 100644 --- a/internal/agent/compaction.go +++ b/internal/agent/compaction.go @@ -6,6 +6,7 @@ import ( "errors" "strings" + "github.com/Gitlawb/zero/internal/trace" "github.com/Gitlawb/zero/internal/zeroruntime" ) @@ -418,6 +419,9 @@ func (state *compactionState) maybeCompact( PreserveLast: state.preserveLast, Summarize: summarizeClosure(ctx, provider, state.onUsage), }) + if r := trace.FromContext(ctx); r != nil && err == nil { + r.Counter(trace.CounterCompactionCount, 1) + } if err != nil { // Summarizer failed: keep the original history. The reactive path (or a // later turn) can try again; we never drop messages on failure here. @@ -462,6 +466,9 @@ func (state *compactionState) recover( PreserveLast: state.preserveLast, Summarize: summarizeClosure(ctx, provider, state.onUsage), }) + if r := trace.FromContext(ctx); r != nil && compactErr == nil { + r.Counter(trace.CounterCompactionCount, 1) + } if compactErr != nil { // A genuine compaction attempt was made (and failed): the budget is spent // so the loop gives up rather than retrying a failing summarizer forever. diff --git a/internal/agent/loop.go b/internal/agent/loop.go index 2ea4ac0bd..8310a72ca 100644 --- a/internal/agent/loop.go +++ b/internal/agent/loop.go @@ -15,6 +15,7 @@ import ( "github.com/Gitlawb/zero/internal/sandbox" "github.com/Gitlawb/zero/internal/streamjson" "github.com/Gitlawb/zero/internal/tools" + "github.com/Gitlawb/zero/internal/trace" "github.com/Gitlawb/zero/internal/zeroruntime" ) @@ -114,6 +115,26 @@ func Run(ctx context.Context, prompt string, provider Provider, options Options) return Result{}, errors.New("agent provider is required") } + // Tracing is opt-in. When a recorder is wired, thread it into ctx so the + // providerio seam and reconnect helper can reach it via trace.FromContext, + // mark the run's start, and wrap OnUsage so token counters accumulate for + // free alongside the existing per-request plumbing. nil recorder leaves the + // loop byte-identical: FromContext returns nil, the no-op stamps cost + // nothing, and the OnUsage wrapper is not installed. + if options.Trace != nil { + ctx = trace.WithContext(ctx, options.Trace) + options.Trace.Start() + originalOnUsage := options.OnUsage + options.OnUsage = func(usage Usage) { + if originalOnUsage != nil { + originalOnUsage(usage) + } + options.Trace.Counter(trace.CounterInputTokens, int64(usage.InputTokens)) + options.Trace.Counter(trace.CounterCachedInputTokens, int64(usage.CachedInputTokens)) + options.Trace.Counter(trace.CounterOutputTokens, int64(usage.OutputTokens)) + } + } + maxTurns := options.MaxTurns if maxTurns <= 0 { maxTurns = 12 @@ -184,12 +205,20 @@ func Run(ctx context.Context, prompt string, provider Provider, options Options) // the tool-definition tokens (they ride on every request) in its estimate. // partitionTools depends only on registry/permissions/options/loaded, not on // the messages, so computing it before compaction is safe. + // Build the per-turn tool list first so proactive compaction can include + // the tool-definition tokens (they ride on every request) in its estimate. + // partitionTools depends only on registry/permissions/options/loaded, not on + // the messages, so computing it before compaction is safe. + promptBuildSpan := options.Trace.Span(trace.SpanPromptBuild) exposed, _ := partitionToolsCached(registry, permissionMode, options, loaded, toolDefCache) + promptBuildSpan.End() // PROACTIVE compaction: if the history is approaching the model's // context window, summarize the oldest middle before building the // request. A no-op when ContextWindow == 0 (compaction disabled). + compactionSpan := options.Trace.Span(trace.SpanCompaction) messages = compactor.maybeCompact(ctx, provider, messages, exposed) + compactionSpan.End() request := zeroruntime.CompletionRequest{ Messages: copyMessages(messages), Tools: exposed, @@ -297,14 +326,18 @@ func Run(ctx context.Context, prompt string, provider Provider, options Options) if retryStreamErr != nil { return collected, retryStreamErr } + genSpan := options.Trace.Span(trace.SpanGeneration) collected = zeroruntime.CollectStreamWithOptions(ctx, retryStream, zeroruntime.CollectOptions{ OnUsage: options.OnUsage, }) + genSpan.End() } return collected, nil } + generationSpan := options.Trace.Span(trace.SpanGeneration) collected := zeroruntime.CollectStreamWithOptions(ctx, stream, forwardingOpts) + generationSpan.End() if collected.Error != "" { updated, stop := recoverStreamError(collected) collected = updated @@ -357,7 +390,9 @@ func Run(ctx context.Context, prompt string, provider Provider, options Options) result.Messages = copyMessages(messages) return result, retryErr } + stallGenSpan := options.Trace.Span(trace.SpanGeneration) collected = zeroruntime.CollectStreamWithOptions(ctx, retryStream, forwardingOpts) + stallGenSpan.End() } if collected.Error != "" { // Route a reissued stream's non-stall error through the SAME recovery as @@ -459,6 +494,7 @@ func Run(ctx context.Context, prompt string, provider Provider, options Options) if cue || planPending { if continueNudges < maxContinueNudges { continueNudges++ + options.Trace.Counter(trace.CounterCompletionNudges, 1) reason := "your message ended mid-step" if !cue { reason = "pending plan items remain — finish them, or mark them complete with update_plan if you are done" @@ -488,6 +524,7 @@ func Run(ctx context.Context, prompt string, provider Provider, options Options) // (no admission, no cue) then finalizes as success on the next turn. if options.SelfCorrect != nil && !acceptanceRequested { acceptanceRequested = true + options.Trace.Counter(trace.CounterAcceptanceChecks, 1) messages = append(messages, zeroruntime.Message{ Role: zeroruntime.MessageRoleUser, Content: acceptanceVerificationNudge(), @@ -548,20 +585,26 @@ func Run(ctx context.Context, prompt string, provider Provider, options Options) runEnd++ } if runEnd-index >= 2 { + batchSpan := options.Trace.Span(trace.SpanToolExecution) precomputed = executeParallelReadBatch(ctx, registry, collected.ToolCalls, index, runEnd, permissionMode, options) + batchSpan.End() precomputedStart, precomputedEnd = index, runEnd } } if options.OnToolCall != nil { options.OnToolCall(call) } + options.Trace.StampFirstUsefulAction() var toolResult ToolResult var abortErr error if index >= precomputedStart && index < precomputedEnd { toolResult, abortErr = precomputed[index-precomputedStart].result, precomputed[index-precomputedStart].abortErr } else { + toolSpan := options.Trace.Span(trace.SpanToolExecution) toolResult, abortErr = executeToolCall(ctx, registry, call, permissionMode, options) + toolSpan.End() } + options.Trace.Counter(trace.CounterToolCalls, 1) if options.OnToolResult != nil { options.OnToolResult(toolResult) } @@ -666,6 +709,7 @@ func Run(ctx context.Context, prompt string, provider Provider, options Options) // context-window sizing, and usage attribution follow the new model. provider = newProvider options.Model = turnRequestedModel + options.Trace.Counter(trace.CounterModelSwitches, 1) // KNOWN LIMITATION (deferred): the compactor's context-window budget // is fixed at run start from options.ContextWindow and is NOT updated // here, so a switch to a model with a different window keeps compacting @@ -764,6 +808,7 @@ func finalAnswerAfterMaxTurns(ctx context.Context, provider Provider, messages [ if err != nil { return "", messages, "" } + finalGenSpan := options.Trace.Span(trace.SpanGeneration) collected := zeroruntime.CollectStreamWithOptions(ctx, stream, zeroruntime.CollectOptions{ OnText: options.OnText, OnReasoning: options.OnReasoning, @@ -771,6 +816,7 @@ func finalAnswerAfterMaxTurns(ctx context.Context, provider Provider, messages [ OnToolCallStart: options.OnToolCallStart, OnToolCallDelta: options.OnToolCallDelta, }) + finalGenSpan.End() if ctx.Err() != nil || collected.Error != "" || strings.TrimSpace(collected.Text) == "" { return "", messages, "" } @@ -1874,7 +1920,10 @@ func requestPermission(ctx context.Context, request PermissionRequest, options O if options.OnPermissionRequest == nil { return PermissionDecision{Action: PermissionDecisionDeny, Reason: request.Reason}, nil } - return options.OnPermissionRequest(ctx, request) + permSpan := options.Trace.Span(trace.SpanPermissionWait) + decision, err := options.OnPermissionRequest(ctx, request) + permSpan.End() + return decision, err } func normalizePermissionDecisionAction(action PermissionDecisionAction) PermissionDecisionAction { diff --git a/internal/agent/reconnect.go b/internal/agent/reconnect.go index 54b339ec2..766e2f398 100644 --- a/internal/agent/reconnect.go +++ b/internal/agent/reconnect.go @@ -8,6 +8,7 @@ import ( "time" "github.com/Gitlawb/zero/internal/errhint" + "github.com/Gitlawb/zero/internal/trace" "github.com/Gitlawb/zero/internal/zeroruntime" ) @@ -74,14 +75,21 @@ func stallRetryNoticeFor(options Options) reconnectNotifier { // already past its deadline is returned immediately (no retry) — those have // their own handling (compaction for context-limit, image-rejection, etc.). func streamWithReconnect(ctx context.Context, provider Provider, request zeroruntime.CompletionRequest, notify reconnectNotifier) (<-chan zeroruntime.StreamEvent, error) { + recorder := trace.FromContext(ctx) stream, err := provider.StreamCompletion(ctx, request) if err == nil { + if recorder != nil { + recorder.Counter(trace.CounterModelRequests, 1) + } return stream, nil } for attempt := 1; attempt <= maxStreamReconnects; attempt++ { if !shouldReconnect(ctx, err) { return nil, err } + if recorder != nil { + recorder.Counter(trace.CounterReconnectCount, 1) + } if notify != nil { notify(attempt, maxStreamReconnects) } @@ -90,6 +98,9 @@ func streamWithReconnect(ctx context.Context, provider Provider, request zerorun } stream, err = provider.StreamCompletion(ctx, request) if err == nil { + if recorder != nil { + recorder.Counter(trace.CounterModelRequests, 1) + } return stream, nil } } diff --git a/internal/agent/types.go b/internal/agent/types.go index 1b12e0c78..a65f01281 100644 --- a/internal/agent/types.go +++ b/internal/agent/types.go @@ -7,6 +7,7 @@ import ( "github.com/Gitlawb/zero/internal/sandbox" "github.com/Gitlawb/zero/internal/streamjson" "github.com/Gitlawb/zero/internal/tools" + "github.com/Gitlawb/zero/internal/trace" "github.com/Gitlawb/zero/internal/zeroruntime" ) @@ -279,6 +280,13 @@ type Options struct { // request), so every existing caller is unaffected. A returned error is // non-fatal: the run continues on the current model. ModelSwitcher func(ctx context.Context, modelID string) (Provider, error) + // Trace, when set, records per-turn timing for the run: the loop stamps + // spans (prompt build, generation, tool execution, permission wait, + // compaction, provider connect) and counters (model requests, tool calls, + // retries, tokens) into it. nil DISABLES tracing entirely — every stamp is + // nil-safe and the loop is byte-identical to an untraced run. The caller + // owns the recorder: Run stamps into it but does not Finish or emit it. + Trace *trace.Recorder // SelfCorrect, when set, runs a post-edit verify-and-correct cycle after a // mutating tool call: it verifies the changed files (LSP diagnostics + project // tests) and feeds failures back to the model to fix, bounded by an attempt diff --git a/internal/cli/exec.go b/internal/cli/exec.go index 3d553dee7..99ef6306e 100644 --- a/internal/cli/exec.go +++ b/internal/cli/exec.go @@ -25,6 +25,7 @@ import ( "github.com/Gitlawb/zero/internal/specmode" "github.com/Gitlawb/zero/internal/streamjson" "github.com/Gitlawb/zero/internal/tools" + "github.com/Gitlawb/zero/internal/trace" "github.com/Gitlawb/zero/internal/usage" "github.com/Gitlawb/zero/internal/worktrees" "github.com/Gitlawb/zero/internal/zeroruntime" @@ -124,6 +125,12 @@ type execOptions struct { // additional write roots for this run. Unioned with // config.SandboxConfig.AdditionalWriteRoots at scope construction time. addDirs []string + // tracePath, when set, writes a per-turn NDJSON trace (agenteval-compatible) + // to the given file path — or to stderr when the value is "-". Falls back to + // the ZERO_TRACE env var when the flag is absent. Off by default: a run + // without it leaves agent.Options.Trace nil and is byte-identical to before. + // The trace is pure observation — enabling it does not change agent behavior. + tracePath string } type execUsageError struct { @@ -474,6 +481,21 @@ func runExec(args []string, stdout io.Writer, stderr io.Writer, deps appDeps) in if err != nil { return writeAppError(stderr, "failed to create run id: "+err.Error(), exitCrash) } + // Per-turn tracing is opt-in (--trace or ZERO_TRACE=). The + // recorder is stamped throughout agent.Run and the providerio seam; the run + // itself is byte-identical to an untraced run. We finish + emit on every exit + // path via the defer below. "-" writes NDJSON to stderr; otherwise the path + // is created/truncated. A failure to emit is logged to stderr, never fatal. + tracePath := resolveTracePath(options) + var traceRecorder *trace.Recorder + if tracePath != "" { + traceRecorder = trace.NewRecorder(preparedSession.Session.SessionID, runID, "") + defer func() { + if err := emitTrace(traceRecorder, tracePath, stderr); err != nil { + fmt.Fprintf(stderr, "[zero] failed to write trace: %s\n", err) + } + }() + } writer := execEventWriter{ stdout: stdout, stderr: stderr, @@ -556,6 +578,7 @@ func runExec(args []string, stdout io.Writer, stderr io.Writer, deps appDeps) in Model: resolved.Provider.Model, ModelSwitcher: modelSwitcher, ReasoningEffort: forwardEffort, + Trace: traceRecorder, Cwd: workspaceRoot, Images: images, Registry: registry, @@ -1237,3 +1260,36 @@ func execNotifyMode(options execOptions, resolved config.ResolvedConfig) string } return resolved.Notify.Mode } + +// resolveTracePath returns the trace destination for this run: the --trace flag +// value when set, else the ZERO_TRACE env var, else "" (tracing off). A value of +// "-" means "write to stderr". +func resolveTracePath(options execOptions) string { + if v := strings.TrimSpace(options.tracePath); v != "" { + return v + } + if v := strings.TrimSpace(os.Getenv("ZERO_TRACE")); v != "" { + return v + } + return "" +} + +// emitTrace finishes the recorder and writes the NDJSON trace to dest ("-" => +// stderr, otherwise a file path created/truncated). A nil recorder is a no-op +// (tracing off). The trace is best-effort: a write error is returned to the +// caller, which logs it but never fails the run. +func emitTrace(recorder *trace.Recorder, dest string, stderr io.Writer) error { + if recorder == nil || dest == "" { + return nil + } + finished := recorder.Finish() + if strings.TrimSpace(dest) == "-" { + return trace.WriteNDJSON(stderr, finished) + } + file, err := os.Create(dest) + if err != nil { + return err + } + defer file.Close() + return trace.WriteNDJSON(file, finished) +} diff --git a/internal/cli/exec_parse.go b/internal/cli/exec_parse.go index 88be880e5..907cababc 100644 --- a/internal/cli/exec_parse.go +++ b/internal/cli/exec_parse.go @@ -32,6 +32,15 @@ func parseExecArgs(args []string) (execOptions, bool, error) { options.noNotify = true case arg == "--no-completion-gate": options.noCompletionGate = true + case arg == "--trace": + value, next, err := nextFlagValue(args, index, arg) + if err != nil { + return options, false, err + } + options.tracePath = value + index = next + case strings.HasPrefix(arg, "--trace="): + options.tracePath = strings.TrimSpace(strings.TrimPrefix(arg, "--trace=")) case arg == "--notify": value, next, err := nextFlagValue(args, index, arg) if err != nil { diff --git a/internal/perfbench/manifests/baseline.json b/internal/perfbench/manifests/baseline.json new file mode 100644 index 000000000..9848a698a --- /dev/null +++ b/internal/perfbench/manifests/baseline.json @@ -0,0 +1,60 @@ +{ + "id": "zero-baseline-turn", + "name": "Zero per-turn baseline (Phase 0)", + "tasks": [ + {"id": "nav-01", "name": "list repo files", "class": "nav", "prompt": "List the files in this repository and report their count. Do not modify anything.", "workspaceFixture": "../testdata/nav"}, + {"id": "nav-02", "name": "find a function", "class": "nav", "prompt": "Find the function named 'greet' and report the file and line it is defined on. Do not modify anything.", "workspaceFixture": "../testdata/nav"}, + {"id": "nav-03", "name": "summarize module", "class": "nav", "prompt": "Read main.go and summarize what this program does in two sentences. Do not modify anything.", "workspaceFixture": "../testdata/nav"}, + {"id": "nav-04", "name": "count tests", "class": "nav", "prompt": "Count the test functions (functions whose names start with Test) in this repository and report the number. Do not modify anything.", "workspaceFixture": "../testdata/nav"}, + {"id": "nav-05", "name": "locate a string", "class": "nav", "prompt": "Find every occurrence of the string 'TODO' in the repository and report the files. Do not modify anything.", "workspaceFixture": "../testdata/nav"}, + {"id": "nav-06", "name": "describe package", "class": "nav", "prompt": "Describe the exported API of this package by reading the source. Do not modify anything.", "workspaceFixture": "../testdata/nav"}, + {"id": "nav-07", "name": "trace a call", "class": "nav", "prompt": "Trace which function calls which other function starting from main. Do not modify anything.", "workspaceFixture": "../testdata/nav"}, + {"id": "nav-08", "name": "find imports", "class": "nav", "prompt": "List every third-party import used by this repository. Do not modify anything.", "workspaceFixture": "../testdata/nav"}, + {"id": "nav-09", "name": "report config", "class": "nav", "prompt": "Read config.json and report the keys it contains. Do not modify anything.", "workspaceFixture": "../testdata/nav"}, + {"id": "nav-10", "name": "doc lookup", "class": "nav", "prompt": "Find the doc comment on the greet function and quote it. Do not modify anything.", "workspaceFixture": "../testdata/nav"}, + + {"id": "edit-01", "name": "rename a constant", "class": "edit", "prompt": "Rename the constant MaxRetries to RetryLimit everywhere it appears.", "workspaceFixture": "../testdata/edit", "verificationCommand": ["grep", "-R", "RetryLimit", "."]}, + {"id": "edit-02", "name": "fix a typo", "class": "edit", "prompt": "Fix the typo in the comment above the greet function ('receieves' should be 'receives').", "workspaceFixture": "../testdata/edit", "verificationCommand": ["bash", "-c", "! grep -R receieves ."]}, + {"id": "edit-03", "name": "add a field", "class": "edit", "prompt": "Add a string field named Label to the Config struct in main.go.", "workspaceFixture": "../testdata/edit", "verificationCommand": ["grep", "-R", "Label", "."]}, + {"id": "edit-04", "name": "bump a version", "class": "edit", "prompt": "Change the version string in version.go from 1.0.0 to 1.1.0.", "workspaceFixture": "../testdata/edit", "verificationCommand": ["grep", "-R", "1.1.0", "."]}, + {"id": "edit-05", "name": "remove a log line", "class": "edit", "prompt": "Remove the line that prints 'debug: starting'.", "workspaceFixture": "../testdata/edit", "verificationCommand": ["bash", "-c", "! grep -R 'debug: starting' ."]}, + {"id": "edit-06", "name": "add a license header", "class": "edit", "prompt": "Add a comment line '// SPDX-License-Identifier: MIT' at the top of main.go.", "workspaceFixture": "../testdata/edit", "verificationCommand": ["grep", "-R", "SPDX-License-Identifier", "."]}, + {"id": "edit-07", "name": "change a default", "class": "edit", "prompt": "Change the default value of the Port constant from 8080 to 9090.", "workspaceFixture": "../testdata/edit", "verificationCommand": ["grep", "-R", "9090", "."]}, + {"id": "edit-08", "name": "add a getter", "class": "edit", "prompt": "Add a method func (c *Config) GetLabel() string that returns c.Label.", "workspaceFixture": "../testdata/edit", "verificationCommand": ["grep", "-R", "GetLabel", "."]}, + {"id": "edit-09", "name": "wrap an error", "class": "edit", "prompt": "In the load function, wrap the returned error with fmt.Errorf so it includes 'load failed'.", "workspaceFixture": "../testdata/edit", "verificationCommand": ["grep", "-R", "load failed", "."]}, + {"id": "edit-10", "name": "update a message", "class": "edit", "prompt": "Change the printed greeting from 'hello' to 'hello, world'.", "workspaceFixture": "../testdata/edit", "verificationCommand": ["grep", "-R", "hello, world", "."]}, + + {"id": "fix-01", "name": "off-by-one", "class": "fix", "prompt": "In bugs.go the Sum function has an off-by-one error that skips the last element; fix the loop so it sums all elements.", "workspaceFixture": "../testdata/fix", "verificationCommand": ["go", "test", "-run", "TestSumIncludesLastElement", "./..."]}, + {"id": "fix-02", "name": "nil deref", "class": "fix", "prompt": "In bugs.go DefaultConfig returns nil and Port() dereferences it; make DefaultConfig return a valid Config with Port 8080.", "workspaceFixture": "../testdata/fix", "verificationCommand": ["go", "test", "-run", "TestPortReturnsDefault", "./..."]}, + {"id": "fix-03", "name": "wrong operator", "class": "fix", "prompt": "In bugs.go Max uses the wrong inequality and returns the smaller value; fix it to return the larger.", "workspaceFixture": "../testdata/fix", "verificationCommand": ["go", "test", "-run", "TestMaxReturnsLarger", "./..."]}, + {"id": "fix-04", "name": "truncated read", "class": "fix", "prompt": "In bugs.go ReadFirst returns only a single character instead of the full content; fix it to return the whole string.", "workspaceFixture": "../testdata/fix", "verificationCommand": ["go", "test", "-run", "TestReadFirstReturnsFullContent", "./..."]}, + {"id": "fix-05", "name": "swapped args", "class": "fix", "prompt": "In bugs.go Divide swaps its operands; fix the order so Divide(10,2) returns 5.", "workspaceFixture": "../testdata/fix", "verificationCommand": ["go", "test", "-run", "TestDivideOrder", "./..."]}, + {"id": "fix-06", "name": "missing return", "class": "fix", "prompt": "In bugs.go Classify is missing a return for the high case; add it so Classify(500) returns \"high\".", "workspaceFixture": "../testdata/fix", "verificationCommand": ["go", "test", "-run", "TestClassifyHigh", "./..."]}, + {"id": "fix-07", "name": "wrong format verb", "class": "fix", "prompt": "In bugs.go Label uses the %d format verb for a string; fix it to use %s.", "workspaceFixture": "../testdata/fix", "verificationCommand": ["go", "test", "-run", "TestLabelUsesString", "./..."]}, + {"id": "fix-08", "name": "race on counter", "class": "fix", "prompt": "In bugs.go the global counter is incremented without synchronization; guard it with a mutex.", "workspaceFixture": "../testdata/fix", "verificationCommand": ["go", "test", "-race", "-run", "TestCounterRace", "./..."]}, + + {"id": "refactor-01", "name": "extract helper", "class": "refactor", "prompt": "Extract the duplicated greeting logic into a single helper function and call it from both sites.", "workspaceFixture": "../testdata/refactor", "verificationCommand": ["go", "build", "./..."]}, + {"id": "refactor-02", "name": "split a file", "class": "refactor", "prompt": "Split main.go into two files: one for Config, one for the rest, keeping the package building.", "workspaceFixture": "../testdata/refactor", "verificationCommand": ["go", "build", "./..."]}, + {"id": "refactor-03", "name": "rename package", "class": "refactor", "prompt": "Rename the package from app to zeroapp everywhere and keep it building.", "workspaceFixture": "../testdata/refactor", "verificationCommand": ["go", "build", "./..."]}, + {"id": "refactor-04", "name": "introduce a type", "class": "refactor", "prompt": "Introduce a named type for the map[string]int used in stats.go and update its users.", "workspaceFixture": "../testdata/refactor", "verificationCommand": ["go", "build", "./..."]}, + {"id": "refactor-05", "name": "inline a wrapper", "class": "refactor", "prompt": "Inline the thin wrapper function into its single caller and remove it.", "workspaceFixture": "../testdata/refactor", "verificationCommand": ["go", "build", "./..."]}, + {"id": "refactor-06", "name": "consolidate errors", "class": "refactor", "prompt": "Consolidate the repeated error-construction blocks into a single helper.", "workspaceFixture": "../testdata/refactor", "verificationCommand": ["go", "build", "./..."]}, + + {"id": "longproc-01", "name": "long build", "class": "longproc", "prompt": "Run the build command and report whether it succeeds. Do not modify anything.", "workspaceFixture": "../testdata/longproc"}, + {"id": "longproc-02", "name": "long test", "class": "longproc", "prompt": "Run go test ./... and report the result. Do not modify anything.", "workspaceFixture": "../testdata/longproc"}, + {"id": "longproc-03", "name": "bench run", "class": "longproc", "prompt": "Run go test -bench=. -benchtime=1x and report the benchmark numbers. Do not modify anything.", "workspaceFixture": "../testdata/longproc"}, + {"id": "longproc-04", "name": "vet run", "class": "longproc", "prompt": "Run go vet ./... and report the output. Do not modify anything.", "workspaceFixture": "../testdata/longproc"}, + + {"id": "longctx-01", "name": "summarize large file", "class": "longctx", "prompt": "Read the large generated file big.go and summarize its structure. Do not modify anything.", "workspaceFixture": "../testdata/longctx"}, + {"id": "longctx-02", "name": "find in large file", "class": "longctx", "prompt": "In big.go, find every function that returns an error and list them. Do not modify anything.", "workspaceFixture": "../testdata/longctx"}, + {"id": "longctx-03", "name": "cross-file question", "class": "longctx", "prompt": "Read all .go files and report which two functions share the same name across files. Do not modify anything.", "workspaceFixture": "../testdata/longctx"}, + {"id": "longctx-04", "name": "trace through large file", "class": "longctx", "prompt": "Starting from Handle, trace the call path through big.go and report the chain. Do not modify anything.", "workspaceFixture": "../testdata/longctx"}, + + {"id": "parallel-01", "name": "read six files", "class": "parallel", "prompt": "Read a.txt, b.txt, c.txt, d.txt, e.txt, and f.txt, then report the first line of each. Do not modify anything.", "workspaceFixture": "../testdata/parallel"}, + {"id": "parallel-02", "name": "grep six patterns", "class": "parallel", "prompt": "Search for 'alpha', 'beta', 'gamma', 'delta', 'epsilon', and 'zeta' across the repo and report which files contain each. Do not modify anything.", "workspaceFixture": "../testdata/parallel"}, + {"id": "parallel-03", "name": "list six dirs", "class": "parallel", "prompt": "List the contents of dir1, dir2, dir3, dir4, dir5, and dir6. Do not modify anything.", "workspaceFixture": "../testdata/parallel"}, + {"id": "parallel-04", "name": "stat six files", "class": "parallel", "prompt": "Report the line count of a.txt, b.txt, c.txt, d.txt, e.txt, and f.txt. Do not modify anything.", "workspaceFixture": "../testdata/parallel"}, + {"id": "parallel-05", "name": "read configs", "class": "parallel", "prompt": "Read config1.json, config2.json, config3.json, config4.json, config5.json, and config6.json and report each top-level key. Do not modify anything.", "workspaceFixture": "../testdata/parallel"}, + {"id": "parallel-06", "name": "summarize six", "class": "parallel", "prompt": "Read the six .txt files and give a one-line summary of each. Do not modify anything.", "workspaceFixture": "../testdata/parallel"} + ] +} \ No newline at end of file diff --git a/internal/perfbench/reports/.gitkeep b/internal/perfbench/reports/.gitkeep new file mode 100644 index 000000000..e69de29bb diff --git a/internal/perfbench/reports/README.md b/internal/perfbench/reports/README.md new file mode 100644 index 000000000..b33f491cf --- /dev/null +++ b/internal/perfbench/reports/README.md @@ -0,0 +1,40 @@ +# Per-turn benchmark reports + +This directory holds generated per-turn benchmark reports. It is **not** a +checked-in source of truth for performance — the numbers are machine- and +model-specific, so a single snapshot here would mislead rather than inform. + +## Generating a baseline + +Run the harness over the checked-in manifest: + +``` +make baseline ZERO_BENCH_MODEL= # uses ./zero +make baseline ZERO_BENCH_MODEL= ZERO_BENCH_BINARY=/path/to/zero +``` + +This builds `zero`, then runs `zero-perf-bench turn` over +`internal/perfbench/manifests/baseline.json`, capturing each turn's trace +(`zero exec --trace `) and writing the aggregated result to +`reports/baseline.json`. + +The JSON report is self-describing: model, mode, self-correct flag, version, +commit, date, per-span median/P95, the **top three controllable latency sources** +ranked by share of attributed time, per-class roll-ups, and token/count totals. +That top-three list is the Phase 0 baseline's "do not proceed until" criterion — +it names where a turn actually spends time so later optimization work is +targeted, not guessed. + +## What to commit + +Commit the manifest and fixtures (`manifests/`, `../testdata/`), not a generated +`baseline.json`. A generated report belongs in a PR description or a shared +dashboard as evidence for one configuration, not in the tree as a durable +expectation. `.gitkeep` keeps the directory present between runs. + +## Caveats + +- Each task is a fresh `zero exec` process, so iterations are **cold-start** + samples. A warm path (reusing an in-process agent) is future work. +- Mutating tasks (edit/fix/refactor) modify their fixture in place; repeatable + runs reset the fixtures from a clean checkout first. \ No newline at end of file diff --git a/internal/perfbench/taskbench.go b/internal/perfbench/taskbench.go index 19bb8a347..c23342a97 100644 --- a/internal/perfbench/taskbench.go +++ b/internal/perfbench/taskbench.go @@ -32,10 +32,13 @@ type TaskSet struct { // BenchTask is one benchmark task. WorkspaceFixture is the relative path of the // task's starting workspace; VerificationCommand (optional) is the command the -// default runner executes to decide pass/fail after ZERO finishes. +// default runner executes to decide pass/fail after ZERO finishes. Class groups +// the task for the turn-benchmark's per-group latency breakdown (e.g. "nav", +// "edit", "fix"); it is optional and ignored by the pass/fail runner. type BenchTask struct { ID string `json:"id"` Name string `json:"name,omitempty"` + Class string `json:"class,omitempty"` Prompt string `json:"prompt"` WorkspaceFixture string `json:"workspaceFixture,omitempty"` VerificationCommand []string `json:"verificationCommand,omitempty"` diff --git a/internal/perfbench/testdata/fix/bugs.go b/internal/perfbench/testdata/fix/bugs.go new file mode 100644 index 000000000..3395a4752 --- /dev/null +++ b/internal/perfbench/testdata/fix/bugs.go @@ -0,0 +1,89 @@ +// Package fix holds deliberately buggy functions for the bug-fix benchmark +// tasks. Each function is covered by its own test (see bugs_test.go) and each +// task verifies with `go test -run `, so the tasks are independent: +// the initial package compiles and the targeted test fails until the named bug +// is fixed. Every bug is fixable without changing a function signature, so the +// test files compile in both the buggy and the fixed state. +package fix + +import "fmt" + +// Sum returns the sum of all elements. BUG: off-by-one — skips the last element. +func Sum(xs []int) int { + total := 0 + for i := 0; i < len(xs)-1; i++ { + total += xs[i] + } + return total +} + +// DefaultConfig returns the default configuration. BUG: returns nil, which +// Port() then dereferences. +func DefaultConfig() *Config { + return nil +} + +// Config holds demo settings. +type Config struct { + Port int +} + +// Port returns the configured port. BUG: panics when DefaultConfig() is nil. +func Port() int { + return DefaultConfig().Port +} + +// Max returns the larger of a and b. BUG: uses the wrong inequality and returns +// the smaller value. +func Max(a, b int) int { + if a < b { + return a + } + return b +} + +// ReadFirst returns the first byte of the given file's content as a string. BUG: +// returns only a single character instead of the full content. +func ReadFirst(content string) string { + if len(content) == 0 { + return "" + } + return string(content[0]) +} + +// Divide returns a divided by b. BUG: the operands are swapped. +func Divide(a, b int) int { + return b / a +} + +// Classify returns "low", "mid", or "high". BUG: the "high" branch is missing a +// return, so high values fall through to the default "". +func Classify(n int) string { + if n < 10 { + return "low" + } + if n < 100 { + return "mid" + } + // BUG: missing return for the high case + return "" +} + +// Label returns a display label for the given name. BUG: uses the %d format +// verb for a string, producing the wrong text. +func Label(name string) string { + return fmt.Sprintf("user-%d", name) +} + +// counter is a shared, unsynchronized counter. BUG: Inc is not goroutine-safe. +var counter int + +// Inc increments the shared counter. +func Inc() { + counter++ +} + +// Count returns the current counter value. +func Count() int { + return counter +} diff --git a/internal/perfbench/testdata/fix/bugs_test.go b/internal/perfbench/testdata/fix/bugs_test.go new file mode 100644 index 000000000..8596661cd --- /dev/null +++ b/internal/perfbench/testdata/fix/bugs_test.go @@ -0,0 +1,68 @@ +package fix + +import ( + "sync" + "testing" +) + +func TestSumIncludesLastElement(t *testing.T) { + if got := Sum([]int{1, 2, 3, 4}); got != 10 { + t.Fatalf("Sum = %d, want 10", got) + } +} + +func TestPortReturnsDefault(t *testing.T) { + if got := Port(); got != 8080 { + t.Fatalf("Port() = %d, want 8080 (DefaultConfig returned nil)", got) + } +} + +func TestMaxReturnsLarger(t *testing.T) { + if got := Max(3, 7); got != 7 { + t.Fatalf("Max(3,7) = %d, want 7", got) + } +} + +func TestReadFirstReturnsFullContent(t *testing.T) { + if got := ReadFirst("hello"); got != "hello" { + t.Fatalf("ReadFirst = %q, want %q", got, "hello") + } +} + +func TestDivideOrder(t *testing.T) { + if got := Divide(10, 2); got != 5 { + t.Fatalf("Divide(10,2) = %d, want 5", got) + } +} + +func TestClassifyHigh(t *testing.T) { + if got := Classify(500); got != "high" { + t.Fatalf("Classify(500) = %q, want %q", got, "high") + } +} + +func TestLabelUsesString(t *testing.T) { + if got := Label("alice"); got != "user-alice" { + t.Fatalf("Label = %q, want %q", got, "user-alice") + } +} + +// TestCounterRace exercises Inc concurrently. Run with `go test -race`: +// the unsynchronized counter trips the race detector until a mutex is added. +func TestCounterRace(t *testing.T) { + counter = 0 + var wg sync.WaitGroup + for i := 0; i < 200; i++ { + wg.Add(1) + go func() { + defer wg.Done() + for j := 0; j < 100; j++ { + Inc() + } + }() + } + wg.Wait() + if got := Count(); got != 20000 { + t.Fatalf("Count = %d, want 20000", got) + } +} diff --git a/internal/perfbench/testdata/longctx/big.go b/internal/perfbench/testdata/longctx/big.go new file mode 100644 index 000000000..0e55a2ea6 --- /dev/null +++ b/internal/perfbench/testdata/longctx/big.go @@ -0,0 +1,1287 @@ +// Package longctx is a generated large-file fixture for long-context benchmark +// tasks. The body is machine-generated; do not edit by hand. +package longctx + +import "errors" + +var errBad = errors.New("bad") + +// Handle001 is handler number 001; it returns an error for odd inputs. +func Handle001(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 1, nil +} + +// Handle002 is handler number 002; it returns an error for odd inputs. +func Handle002(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 2, nil +} + +// Handle003 is handler number 003; it returns an error for odd inputs. +func Handle003(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 3, nil +} + +// Handle004 is handler number 004; it returns an error for odd inputs. +func Handle004(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 4, nil +} + +// Handle005 is handler number 005; it returns an error for odd inputs. +func Handle005(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 5, nil +} + +// Handle006 is handler number 006; it returns an error for odd inputs. +func Handle006(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 6, nil +} + +// Handle007 is handler number 007; it returns an error for odd inputs. +func Handle007(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 7, nil +} + +// Handle008 is handler number 008; it returns an error for odd inputs. +func Handle008(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 8, nil +} + +// Handle009 is handler number 009; it returns an error for odd inputs. +func Handle009(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 9, nil +} + +// Handle010 is handler number 010; it returns an error for odd inputs. +func Handle010(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 10, nil +} + +// Handle011 is handler number 011; it returns an error for odd inputs. +func Handle011(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 11, nil +} + +// Handle012 is handler number 012; it returns an error for odd inputs. +func Handle012(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 12, nil +} + +// Handle013 is handler number 013; it returns an error for odd inputs. +func Handle013(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 13, nil +} + +// Handle014 is handler number 014; it returns an error for odd inputs. +func Handle014(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 14, nil +} + +// Handle015 is handler number 015; it returns an error for odd inputs. +func Handle015(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 15, nil +} + +// Handle016 is handler number 016; it returns an error for odd inputs. +func Handle016(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 16, nil +} + +// Handle017 is handler number 017; it returns an error for odd inputs. +func Handle017(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 17, nil +} + +// Handle018 is handler number 018; it returns an error for odd inputs. +func Handle018(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 18, nil +} + +// Handle019 is handler number 019; it returns an error for odd inputs. +func Handle019(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 19, nil +} + +// Handle020 is handler number 020; it returns an error for odd inputs. +func Handle020(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 20, nil +} + +// Handle021 is handler number 021; it returns an error for odd inputs. +func Handle021(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 21, nil +} + +// Handle022 is handler number 022; it returns an error for odd inputs. +func Handle022(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 22, nil +} + +// Handle023 is handler number 023; it returns an error for odd inputs. +func Handle023(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 23, nil +} + +// Handle024 is handler number 024; it returns an error for odd inputs. +func Handle024(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 24, nil +} + +// Handle025 is handler number 025; it returns an error for odd inputs. +func Handle025(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 25, nil +} + +// Handle026 is handler number 026; it returns an error for odd inputs. +func Handle026(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 26, nil +} + +// Handle027 is handler number 027; it returns an error for odd inputs. +func Handle027(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 27, nil +} + +// Handle028 is handler number 028; it returns an error for odd inputs. +func Handle028(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 28, nil +} + +// Handle029 is handler number 029; it returns an error for odd inputs. +func Handle029(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 29, nil +} + +// Handle030 is handler number 030; it returns an error for odd inputs. +func Handle030(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 30, nil +} + +// Handle031 is handler number 031; it returns an error for odd inputs. +func Handle031(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 31, nil +} + +// Handle032 is handler number 032; it returns an error for odd inputs. +func Handle032(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 32, nil +} + +// Handle033 is handler number 033; it returns an error for odd inputs. +func Handle033(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 33, nil +} + +// Handle034 is handler number 034; it returns an error for odd inputs. +func Handle034(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 34, nil +} + +// Handle035 is handler number 035; it returns an error for odd inputs. +func Handle035(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 35, nil +} + +// Handle036 is handler number 036; it returns an error for odd inputs. +func Handle036(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 36, nil +} + +// Handle037 is handler number 037; it returns an error for odd inputs. +func Handle037(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 37, nil +} + +// Handle038 is handler number 038; it returns an error for odd inputs. +func Handle038(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 38, nil +} + +// Handle039 is handler number 039; it returns an error for odd inputs. +func Handle039(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 39, nil +} + +// Handle040 is handler number 040; it returns an error for odd inputs. +func Handle040(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 40, nil +} + +// Handle041 is handler number 041; it returns an error for odd inputs. +func Handle041(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 41, nil +} + +// Handle042 is handler number 042; it returns an error for odd inputs. +func Handle042(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 42, nil +} + +// Handle043 is handler number 043; it returns an error for odd inputs. +func Handle043(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 43, nil +} + +// Handle044 is handler number 044; it returns an error for odd inputs. +func Handle044(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 44, nil +} + +// Handle045 is handler number 045; it returns an error for odd inputs. +func Handle045(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 45, nil +} + +// Handle046 is handler number 046; it returns an error for odd inputs. +func Handle046(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 46, nil +} + +// Handle047 is handler number 047; it returns an error for odd inputs. +func Handle047(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 47, nil +} + +// Handle048 is handler number 048; it returns an error for odd inputs. +func Handle048(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 48, nil +} + +// Handle049 is handler number 049; it returns an error for odd inputs. +func Handle049(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 49, nil +} + +// Handle050 is handler number 050; it returns an error for odd inputs. +func Handle050(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 50, nil +} + +// Handle051 is handler number 051; it returns an error for odd inputs. +func Handle051(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 51, nil +} + +// Handle052 is handler number 052; it returns an error for odd inputs. +func Handle052(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 52, nil +} + +// Handle053 is handler number 053; it returns an error for odd inputs. +func Handle053(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 53, nil +} + +// Handle054 is handler number 054; it returns an error for odd inputs. +func Handle054(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 54, nil +} + +// Handle055 is handler number 055; it returns an error for odd inputs. +func Handle055(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 55, nil +} + +// Handle056 is handler number 056; it returns an error for odd inputs. +func Handle056(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 56, nil +} + +// Handle057 is handler number 057; it returns an error for odd inputs. +func Handle057(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 57, nil +} + +// Handle058 is handler number 058; it returns an error for odd inputs. +func Handle058(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 58, nil +} + +// Handle059 is handler number 059; it returns an error for odd inputs. +func Handle059(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 59, nil +} + +// Handle060 is handler number 060; it returns an error for odd inputs. +func Handle060(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 60, nil +} + +// Handle061 is handler number 061; it returns an error for odd inputs. +func Handle061(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 61, nil +} + +// Handle062 is handler number 062; it returns an error for odd inputs. +func Handle062(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 62, nil +} + +// Handle063 is handler number 063; it returns an error for odd inputs. +func Handle063(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 63, nil +} + +// Handle064 is handler number 064; it returns an error for odd inputs. +func Handle064(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 64, nil +} + +// Handle065 is handler number 065; it returns an error for odd inputs. +func Handle065(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 65, nil +} + +// Handle066 is handler number 066; it returns an error for odd inputs. +func Handle066(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 66, nil +} + +// Handle067 is handler number 067; it returns an error for odd inputs. +func Handle067(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 67, nil +} + +// Handle068 is handler number 068; it returns an error for odd inputs. +func Handle068(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 68, nil +} + +// Handle069 is handler number 069; it returns an error for odd inputs. +func Handle069(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 69, nil +} + +// Handle070 is handler number 070; it returns an error for odd inputs. +func Handle070(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 70, nil +} + +// Handle071 is handler number 071; it returns an error for odd inputs. +func Handle071(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 71, nil +} + +// Handle072 is handler number 072; it returns an error for odd inputs. +func Handle072(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 72, nil +} + +// Handle073 is handler number 073; it returns an error for odd inputs. +func Handle073(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 73, nil +} + +// Handle074 is handler number 074; it returns an error for odd inputs. +func Handle074(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 74, nil +} + +// Handle075 is handler number 075; it returns an error for odd inputs. +func Handle075(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 75, nil +} + +// Handle076 is handler number 076; it returns an error for odd inputs. +func Handle076(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 76, nil +} + +// Handle077 is handler number 077; it returns an error for odd inputs. +func Handle077(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 77, nil +} + +// Handle078 is handler number 078; it returns an error for odd inputs. +func Handle078(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 78, nil +} + +// Handle079 is handler number 079; it returns an error for odd inputs. +func Handle079(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 79, nil +} + +// Handle080 is handler number 080; it returns an error for odd inputs. +func Handle080(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 80, nil +} + +// Handle081 is handler number 081; it returns an error for odd inputs. +func Handle081(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 81, nil +} + +// Handle082 is handler number 082; it returns an error for odd inputs. +func Handle082(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 82, nil +} + +// Handle083 is handler number 083; it returns an error for odd inputs. +func Handle083(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 83, nil +} + +// Handle084 is handler number 084; it returns an error for odd inputs. +func Handle084(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 84, nil +} + +// Handle085 is handler number 085; it returns an error for odd inputs. +func Handle085(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 85, nil +} + +// Handle086 is handler number 086; it returns an error for odd inputs. +func Handle086(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 86, nil +} + +// Handle087 is handler number 087; it returns an error for odd inputs. +func Handle087(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 87, nil +} + +// Handle088 is handler number 088; it returns an error for odd inputs. +func Handle088(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 88, nil +} + +// Handle089 is handler number 089; it returns an error for odd inputs. +func Handle089(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 89, nil +} + +// Handle090 is handler number 090; it returns an error for odd inputs. +func Handle090(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 90, nil +} + +// Handle091 is handler number 091; it returns an error for odd inputs. +func Handle091(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 91, nil +} + +// Handle092 is handler number 092; it returns an error for odd inputs. +func Handle092(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 92, nil +} + +// Handle093 is handler number 093; it returns an error for odd inputs. +func Handle093(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 93, nil +} + +// Handle094 is handler number 094; it returns an error for odd inputs. +func Handle094(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 94, nil +} + +// Handle095 is handler number 095; it returns an error for odd inputs. +func Handle095(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 95, nil +} + +// Handle096 is handler number 096; it returns an error for odd inputs. +func Handle096(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 96, nil +} + +// Handle097 is handler number 097; it returns an error for odd inputs. +func Handle097(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 97, nil +} + +// Handle098 is handler number 098; it returns an error for odd inputs. +func Handle098(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 98, nil +} + +// Handle099 is handler number 099; it returns an error for odd inputs. +func Handle099(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 99, nil +} + +// Handle100 is handler number 100; it returns an error for odd inputs. +func Handle100(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 100, nil +} + +// Handle101 is handler number 101; it returns an error for odd inputs. +func Handle101(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 101, nil +} + +// Handle102 is handler number 102; it returns an error for odd inputs. +func Handle102(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 102, nil +} + +// Handle103 is handler number 103; it returns an error for odd inputs. +func Handle103(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 103, nil +} + +// Handle104 is handler number 104; it returns an error for odd inputs. +func Handle104(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 104, nil +} + +// Handle105 is handler number 105; it returns an error for odd inputs. +func Handle105(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 105, nil +} + +// Handle106 is handler number 106; it returns an error for odd inputs. +func Handle106(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 106, nil +} + +// Handle107 is handler number 107; it returns an error for odd inputs. +func Handle107(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 107, nil +} + +// Handle108 is handler number 108; it returns an error for odd inputs. +func Handle108(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 108, nil +} + +// Handle109 is handler number 109; it returns an error for odd inputs. +func Handle109(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 109, nil +} + +// Handle110 is handler number 110; it returns an error for odd inputs. +func Handle110(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 110, nil +} + +// Handle111 is handler number 111; it returns an error for odd inputs. +func Handle111(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 111, nil +} + +// Handle112 is handler number 112; it returns an error for odd inputs. +func Handle112(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 112, nil +} + +// Handle113 is handler number 113; it returns an error for odd inputs. +func Handle113(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 113, nil +} + +// Handle114 is handler number 114; it returns an error for odd inputs. +func Handle114(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 114, nil +} + +// Handle115 is handler number 115; it returns an error for odd inputs. +func Handle115(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 115, nil +} + +// Handle116 is handler number 116; it returns an error for odd inputs. +func Handle116(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 116, nil +} + +// Handle117 is handler number 117; it returns an error for odd inputs. +func Handle117(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 117, nil +} + +// Handle118 is handler number 118; it returns an error for odd inputs. +func Handle118(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 118, nil +} + +// Handle119 is handler number 119; it returns an error for odd inputs. +func Handle119(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 119, nil +} + +// Handle120 is handler number 120; it returns an error for odd inputs. +func Handle120(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 120, nil +} + +// Handle121 is handler number 121; it returns an error for odd inputs. +func Handle121(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 121, nil +} + +// Handle122 is handler number 122; it returns an error for odd inputs. +func Handle122(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 122, nil +} + +// Handle123 is handler number 123; it returns an error for odd inputs. +func Handle123(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 123, nil +} + +// Handle124 is handler number 124; it returns an error for odd inputs. +func Handle124(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 124, nil +} + +// Handle125 is handler number 125; it returns an error for odd inputs. +func Handle125(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 125, nil +} + +// Handle126 is handler number 126; it returns an error for odd inputs. +func Handle126(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 126, nil +} + +// Handle127 is handler number 127; it returns an error for odd inputs. +func Handle127(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 127, nil +} + +// Handle128 is handler number 128; it returns an error for odd inputs. +func Handle128(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 128, nil +} + +// Handle129 is handler number 129; it returns an error for odd inputs. +func Handle129(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 129, nil +} + +// Handle130 is handler number 130; it returns an error for odd inputs. +func Handle130(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 130, nil +} + +// Handle131 is handler number 131; it returns an error for odd inputs. +func Handle131(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 131, nil +} + +// Handle132 is handler number 132; it returns an error for odd inputs. +func Handle132(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 132, nil +} + +// Handle133 is handler number 133; it returns an error for odd inputs. +func Handle133(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 133, nil +} + +// Handle134 is handler number 134; it returns an error for odd inputs. +func Handle134(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 134, nil +} + +// Handle135 is handler number 135; it returns an error for odd inputs. +func Handle135(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 135, nil +} + +// Handle136 is handler number 136; it returns an error for odd inputs. +func Handle136(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 136, nil +} + +// Handle137 is handler number 137; it returns an error for odd inputs. +func Handle137(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 137, nil +} + +// Handle138 is handler number 138; it returns an error for odd inputs. +func Handle138(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 138, nil +} + +// Handle139 is handler number 139; it returns an error for odd inputs. +func Handle139(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 139, nil +} + +// Handle140 is handler number 140; it returns an error for odd inputs. +func Handle140(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 140, nil +} + +// Handle141 is handler number 141; it returns an error for odd inputs. +func Handle141(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 141, nil +} + +// Handle142 is handler number 142; it returns an error for odd inputs. +func Handle142(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 142, nil +} + +// Handle143 is handler number 143; it returns an error for odd inputs. +func Handle143(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 143, nil +} + +// Handle144 is handler number 144; it returns an error for odd inputs. +func Handle144(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 144, nil +} + +// Handle145 is handler number 145; it returns an error for odd inputs. +func Handle145(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 145, nil +} + +// Handle146 is handler number 146; it returns an error for odd inputs. +func Handle146(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 146, nil +} + +// Handle147 is handler number 147; it returns an error for odd inputs. +func Handle147(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 147, nil +} + +// Handle148 is handler number 148; it returns an error for odd inputs. +func Handle148(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 148, nil +} + +// Handle149 is handler number 149; it returns an error for odd inputs. +func Handle149(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 149, nil +} + +// Handle150 is handler number 150; it returns an error for odd inputs. +func Handle150(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 150, nil +} + +// Handle151 is handler number 151; it returns an error for odd inputs. +func Handle151(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 151, nil +} + +// Handle152 is handler number 152; it returns an error for odd inputs. +func Handle152(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 152, nil +} + +// Handle153 is handler number 153; it returns an error for odd inputs. +func Handle153(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 153, nil +} + +// Handle154 is handler number 154; it returns an error for odd inputs. +func Handle154(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 154, nil +} + +// Handle155 is handler number 155; it returns an error for odd inputs. +func Handle155(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 155, nil +} + +// Handle156 is handler number 156; it returns an error for odd inputs. +func Handle156(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 156, nil +} + +// Handle157 is handler number 157; it returns an error for odd inputs. +func Handle157(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 157, nil +} + +// Handle158 is handler number 158; it returns an error for odd inputs. +func Handle158(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 158, nil +} + +// Handle159 is handler number 159; it returns an error for odd inputs. +func Handle159(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 159, nil +} + +// Handle160 is handler number 160; it returns an error for odd inputs. +func Handle160(n int) (int, error) { + if n%2 == 1 { + return 0, errBad + } + return n + 160, nil +} diff --git a/internal/perfbench/testdata/longproc/main.go b/internal/perfbench/testdata/longproc/main.go new file mode 100644 index 000000000..d1a3e0a4c --- /dev/null +++ b/internal/perfbench/testdata/longproc/main.go @@ -0,0 +1,21 @@ +// Package longproc is a small buildable workspace for the long-running-process +// benchmark tasks, which run build/test/vet/bench commands against it. +package longproc + +import "fmt" + +// Version is the demo build's version string. +const Version = "1.0.0" + +// Process simulates a bounded unit of work for the benchmark task. +func Process(n int) int { + total := 0 + for i := 0; i < n; i++ { + total += i + } + return total +} + +func main() { + fmt.Println("longproc fixture", Version, Process(100)) +} diff --git a/internal/perfbench/testdata/longproc/main_test.go b/internal/perfbench/testdata/longproc/main_test.go new file mode 100644 index 000000000..1443d94a3 --- /dev/null +++ b/internal/perfbench/testdata/longproc/main_test.go @@ -0,0 +1,15 @@ +package longproc + +import "testing" + +func TestProcess(t *testing.T) { + if got := Process(100); got != 4950 { + t.Fatalf("Process(100) = %d, want 4950", got) + } +} + +func BenchmarkProcess(b *testing.B) { + for i := 0; i < b.N; i++ { + Process(100) + } +} diff --git a/internal/perfbench/testdata/nav/README.md b/internal/perfbench/testdata/nav/README.md new file mode 100644 index 000000000..bf69eaf81 --- /dev/null +++ b/internal/perfbench/testdata/nav/README.md @@ -0,0 +1,3 @@ +# nav fixture + +Small read-only workspace for navigation/classification benchmark tasks. \ No newline at end of file diff --git a/internal/perfbench/testdata/nav/config.json b/internal/perfbench/testdata/nav/config.json new file mode 100644 index 000000000..6d6369b04 --- /dev/null +++ b/internal/perfbench/testdata/nav/config.json @@ -0,0 +1,5 @@ +{ + "port": 8080, + "name": "nav-fixture", + "retries": 3 +} \ No newline at end of file diff --git a/internal/perfbench/testdata/nav/main.go b/internal/perfbench/testdata/nav/main.go new file mode 100644 index 000000000..0cdac9707 --- /dev/null +++ b/internal/perfbench/testdata/nav/main.go @@ -0,0 +1,24 @@ +// Package nav is a small read-only fixture for navigation tasks. +package nav + +import "fmt" + +// MaxRetries is the configured retry limit for the demo client. +const MaxRetries = 3 + +// Config holds the demo client's settings. +type Config struct { + Port int + Name string +} + +// greet returns a greeting for the given name. +// receieves is a deliberate typo present in the fixture (see edit tasks). +func greet(name string) string { + return fmt.Sprintf("hello, %s", name) +} + +// main is the fixture entry point. +func main() { + fmt.Println(greet("world")) +} diff --git a/internal/perfbench/testdata/parallel/a.txt b/internal/perfbench/testdata/parallel/a.txt new file mode 100644 index 000000000..7a021ffac --- /dev/null +++ b/internal/perfbench/testdata/parallel/a.txt @@ -0,0 +1,4 @@ +first line of a.txt +second line of a.txt +third line of a.txt +alpha alpha alpha diff --git a/internal/perfbench/testdata/parallel/b.txt b/internal/perfbench/testdata/parallel/b.txt new file mode 100644 index 000000000..89b64cd27 --- /dev/null +++ b/internal/perfbench/testdata/parallel/b.txt @@ -0,0 +1,4 @@ +first line of b.txt +second line of b.txt +third line of b.txt +beta beta beta diff --git a/internal/perfbench/testdata/parallel/c.txt b/internal/perfbench/testdata/parallel/c.txt new file mode 100644 index 000000000..8e842abed --- /dev/null +++ b/internal/perfbench/testdata/parallel/c.txt @@ -0,0 +1,4 @@ +first line of c.txt +second line of c.txt +third line of c.txt +gamma gamma gamma diff --git a/internal/perfbench/testdata/parallel/config1.json b/internal/perfbench/testdata/parallel/config1.json new file mode 100644 index 000000000..c73cc9b75 --- /dev/null +++ b/internal/perfbench/testdata/parallel/config1.json @@ -0,0 +1 @@ +{ "id": 1, "key": "value-1", "enabled": true } diff --git a/internal/perfbench/testdata/parallel/config2.json b/internal/perfbench/testdata/parallel/config2.json new file mode 100644 index 000000000..f5d84e9da --- /dev/null +++ b/internal/perfbench/testdata/parallel/config2.json @@ -0,0 +1 @@ +{ "id": 2, "key": "value-2", "enabled": true } diff --git a/internal/perfbench/testdata/parallel/config3.json b/internal/perfbench/testdata/parallel/config3.json new file mode 100644 index 000000000..6a4a4f119 --- /dev/null +++ b/internal/perfbench/testdata/parallel/config3.json @@ -0,0 +1 @@ +{ "id": 3, "key": "value-3", "enabled": true } diff --git a/internal/perfbench/testdata/parallel/config4.json b/internal/perfbench/testdata/parallel/config4.json new file mode 100644 index 000000000..88b3e6506 --- /dev/null +++ b/internal/perfbench/testdata/parallel/config4.json @@ -0,0 +1 @@ +{ "id": 4, "key": "value-4", "enabled": true } diff --git a/internal/perfbench/testdata/parallel/config5.json b/internal/perfbench/testdata/parallel/config5.json new file mode 100644 index 000000000..eb4e47438 --- /dev/null +++ b/internal/perfbench/testdata/parallel/config5.json @@ -0,0 +1 @@ +{ "id": 5, "key": "value-5", "enabled": true } diff --git a/internal/perfbench/testdata/parallel/config6.json b/internal/perfbench/testdata/parallel/config6.json new file mode 100644 index 000000000..bc1aec9d2 --- /dev/null +++ b/internal/perfbench/testdata/parallel/config6.json @@ -0,0 +1 @@ +{ "id": 6, "key": "value-6", "enabled": true } diff --git a/internal/perfbench/testdata/parallel/d.txt b/internal/perfbench/testdata/parallel/d.txt new file mode 100644 index 000000000..f1e69229f --- /dev/null +++ b/internal/perfbench/testdata/parallel/d.txt @@ -0,0 +1,4 @@ +first line of d.txt +second line of d.txt +third line of d.txt +delta delta delta diff --git a/internal/perfbench/testdata/parallel/dir1/notes.md b/internal/perfbench/testdata/parallel/dir1/notes.md new file mode 100644 index 000000000..70e3079d7 --- /dev/null +++ b/internal/perfbench/testdata/parallel/dir1/notes.md @@ -0,0 +1 @@ +contents of dir1/notes.md diff --git a/internal/perfbench/testdata/parallel/dir2/notes.md b/internal/perfbench/testdata/parallel/dir2/notes.md new file mode 100644 index 000000000..776d8b05e --- /dev/null +++ b/internal/perfbench/testdata/parallel/dir2/notes.md @@ -0,0 +1 @@ +contents of dir2/notes.md diff --git a/internal/perfbench/testdata/parallel/dir3/notes.md b/internal/perfbench/testdata/parallel/dir3/notes.md new file mode 100644 index 000000000..bdf83de4c --- /dev/null +++ b/internal/perfbench/testdata/parallel/dir3/notes.md @@ -0,0 +1 @@ +contents of dir3/notes.md diff --git a/internal/perfbench/testdata/parallel/dir4/notes.md b/internal/perfbench/testdata/parallel/dir4/notes.md new file mode 100644 index 000000000..5f6ef0b11 --- /dev/null +++ b/internal/perfbench/testdata/parallel/dir4/notes.md @@ -0,0 +1 @@ +contents of dir4/notes.md diff --git a/internal/perfbench/testdata/parallel/dir5/notes.md b/internal/perfbench/testdata/parallel/dir5/notes.md new file mode 100644 index 000000000..2f892cbc8 --- /dev/null +++ b/internal/perfbench/testdata/parallel/dir5/notes.md @@ -0,0 +1 @@ +contents of dir5/notes.md diff --git a/internal/perfbench/testdata/parallel/dir6/notes.md b/internal/perfbench/testdata/parallel/dir6/notes.md new file mode 100644 index 000000000..706c6eae1 --- /dev/null +++ b/internal/perfbench/testdata/parallel/dir6/notes.md @@ -0,0 +1 @@ +contents of dir6/notes.md diff --git a/internal/perfbench/testdata/parallel/e.txt b/internal/perfbench/testdata/parallel/e.txt new file mode 100644 index 000000000..376f0338a --- /dev/null +++ b/internal/perfbench/testdata/parallel/e.txt @@ -0,0 +1,4 @@ +first line of e.txt +second line of e.txt +third line of e.txt +epsilon epsilon epsilon diff --git a/internal/perfbench/testdata/parallel/f.txt b/internal/perfbench/testdata/parallel/f.txt new file mode 100644 index 000000000..655a27c5c --- /dev/null +++ b/internal/perfbench/testdata/parallel/f.txt @@ -0,0 +1,4 @@ +first line of f.txt +second line of f.txt +third line of f.txt +zeta zeta zeta diff --git a/internal/perfbench/testdata/refactor/main.go b/internal/perfbench/testdata/refactor/main.go new file mode 100644 index 000000000..c8ac0442a --- /dev/null +++ b/internal/perfbench/testdata/refactor/main.go @@ -0,0 +1,55 @@ +// Package refactor is the starting workspace for the multi-file refactor +// benchmark tasks. It is intentionally a little messy (duplicated logic, a +// bare map type, a thin wrapper) so the refactor prompts have real work to do. +// It builds cleanly at all times; the tasks keep it building. +package refactor + +import "fmt" + +// Config holds demo settings. +type Config struct { + Name string + Port int +} + +// GreetFromConfig returns a greeting using the config's name. +func GreetFromConfig(c Config) string { + return fmt.Sprintf("hello, %s", c.Name) +} + +// GreetByName returns a greeting using a bare name. BUG-note: this duplicates +// GreetFromConfig's formatting — refactor-01 extracts a shared helper. +func GreetByName(name string) string { + return fmt.Sprintf("hello, %s", name) +} + +// Wrapper is a thin wrapper around GreetByName — refactor-05 inlines it. +func Wrapper(name string) string { + return GreetByName(name) +} + +// stats is a bare map used across the file — refactor-04 introduces a named type. +var stats = map[string]int{} + +// Record bumps a stat by name. +func Record(name string) { + stats[name]++ +} + +// Lookup returns a stat by name. +func Lookup(name string) int { + return stats[name] +} + +// load failed wrapped error — refactor-06 consolidates these. +func firstError() error { + return fmt.Errorf("load failed: missing input") +} + +func secondError() error { + return fmt.Errorf("load failed: bad format") +} + +func buildError(ctx string) error { + return fmt.Errorf("load failed: %s", ctx) +} diff --git a/internal/perfbench/turn_bench.go b/internal/perfbench/turn_bench.go new file mode 100644 index 000000000..c60d20056 --- /dev/null +++ b/internal/perfbench/turn_bench.go @@ -0,0 +1,434 @@ +package perfbench + +import ( + "bytes" + "context" + "encoding/json" + "errors" + "fmt" + "io" + "os" + "os/exec" + "path/filepath" + "sort" + "strings" + "time" + + "github.com/Gitlawb/zero/internal/trace" +) + +// TurnSchemaVersion is the schema version of a published turn-benchmark result. +// Bump when the TurnBenchResult shape changes so consumers can detect drift. +const TurnSchemaVersion = 1 + +// TurnRunner runs one benchmark task and reports its outcome plus the captured +// per-turn trace. A non-nil Err means the run failed to execute (process crash); +// Passed reflects the verification result. Trace is the parsed NDJSON trace +// (nil when the run errored before emitting one). +type TurnRunner func(ctx context.Context, task BenchTask, rc RunContext) TurnTaskOutcome + +// TurnTaskOutcome is what a TurnRunner reports for one task iteration. +type TurnTaskOutcome struct { + Passed bool + VerifyErr string + WallMs float64 + Trace *trace.TurnTrace + Err error +} + +// TurnBenchConfig configures a turn-benchmark run. +type TurnBenchConfig struct { + Model string + Mode string + SelfCorrect bool + Version string + Commit string + // Iterations is how many times each task is run. The per-process `zero exec` + // runner is inherently cold-start, so this is the sample count for per-span + // median/P95 — a genuine warm path needs an in-process runner (future work). + Iterations int + // Runner executes one task iteration. Required. + Runner TurnRunner + // Now overrides the clock for the recorded date (tests inject a fixed time). + Now func() time.Time +} + +// SpanStats summarizes one span's duration across all measured task iterations. +type SpanStats struct { + Count int `json:"count"` + TotalMs float64 `json:"totalMs"` + MedianMs float64 `json:"medianMs"` + P95Ms float64 `json:"p95Ms"` + MaxMs float64 `json:"maxMs"` +} + +// LatencySource is one of the top controllable latency sources, ranked by total +// attributed time across the whole run. Share is its fraction of total attributed +// span time (not wall time — spans overlap, so shares need not sum to 1). +type LatencySource struct { + Span string `json:"span"` + TotalMs float64 `json:"totalMs"` + Share float64 `json:"share"` +} + +// ClassSummary is the per-class (task group) roll-up. +type ClassSummary struct { + Tasks int `json:"tasks"` + Passed int `json:"passed"` + WallMs NumericStats `json:"wallMs"` + SpanTotals map[string]float64 `json:"spanTotals"` +} + +// TurnBenchResult is the publishable turn-benchmark record. +type TurnBenchResult struct { + SchemaVersion int `json:"schemaVersion"` + Suite string `json:"suite"` + Model string `json:"model"` + Mode string `json:"mode,omitempty"` + SelfCorrect bool `json:"selfCorrect"` + Version string `json:"version,omitempty"` + Commit string `json:"commit,omitempty"` + Date string `json:"date"` + TasksAttempted int `json:"tasksAttempted"` + TasksPassed int `json:"tasksPassed"` + Iterations int `json:"iterations"` + PerSpan map[string]SpanStats `json:"perSpan"` + TopLatency []LatencySource `json:"topLatency"` + PerClass map[string]ClassSummary `json:"perClass"` + Totals TurnBenchTotals `json:"totals"` + Warnings []Warning `json:"warnings,omitempty"` +} + +// TurnBenchTotals aggregates token and count totals across the whole run. +type TurnBenchTotals struct { + InputTokens int64 `json:"inputTokens"` + CachedInputTokens int64 `json:"cachedInputTokens"` + OutputTokens int64 `json:"outputTokens"` + ModelRequests int64 `json:"modelRequests"` + ToolCalls int64 `json:"toolCalls"` + Retries int64 `json:"retries"` + Reconnects int64 `json:"reconnects"` + Compactions int64 `json:"compactions"` +} + +// RunTurnBench executes every task in the set with the configured runner and +// returns a self-describing per-turn result. It never aborts on a single task +// failure — every task is attempted and recorded. Per-span stats aggregate +// across iterations; the top three controllable latency sources are ranked by +// total attributed time. +func RunTurnBench(ctx context.Context, set TaskSet, cfg TurnBenchConfig) (TurnBenchResult, error) { + if len(set.Tasks) == 0 { + return TurnBenchResult{}, errors.New("task set has no tasks") + } + if strings.TrimSpace(cfg.Model) == "" { + return TurnBenchResult{}, errors.New("turn benchmark requires a model") + } + if cfg.Runner == nil { + return TurnBenchResult{}, errors.New("turn benchmark requires a runner") + } + iterations := cfg.Iterations + if iterations < 1 { + iterations = 1 + } + now := cfg.Now + if now == nil { + now = time.Now + } + rc := RunContext{Model: cfg.Model, Mode: cfg.Mode, SelfCorrect: cfg.SelfCorrect} + + perSpanSamples := map[string][]float64{} + classWalls := map[string][]float64{} + classSpanTotals := map[string]map[string]float64{} + classTasks := map[string]int{} + classPassed := map[string]int{} + var totals TurnBenchTotals + + result := TurnBenchResult{ + SchemaVersion: TurnSchemaVersion, + Suite: strings.TrimSpace(set.ID), + Model: strings.TrimSpace(cfg.Model), + Mode: strings.TrimSpace(cfg.Mode), + SelfCorrect: cfg.SelfCorrect, + Version: strings.TrimSpace(cfg.Version), + Commit: strings.TrimSpace(cfg.Commit), + Date: now().UTC().Format(time.RFC3339), + Iterations: iterations, + PerSpan: map[string]SpanStats{}, + PerClass: map[string]ClassSummary{}, + } + + for _, task := range set.Tasks { + if err := ctx.Err(); err != nil { + return result, err + } + class := strings.TrimSpace(task.Class) + if class == "" { + class = "default" + } + classTasks[class]++ + passedForTask := false + for iter := 0; iter < iterations; iter++ { + outcome := cfg.Runner(ctx, task, rc) + if outcome.Err != nil { + continue + } + if outcome.Passed { + passedForTask = true + } + wall := outcome.WallMs + if wall <= 0 && outcome.Trace != nil { + wall = float64(outcome.Trace.WallDuration().Microseconds()) / 1000 + } + if wall > 0 { + classWalls[class] = append(classWalls[class], wall) + } + if outcome.Trace != nil { + aggregateTotals(&totals, outcome.Trace) + for _, span := range outcome.Trace.Spans { + ms := float64(span.Duration.Microseconds()) / 1000 + perSpanSamples[span.Name] = append(perSpanSamples[span.Name], ms) + if classSpanTotals[class] == nil { + classSpanTotals[class] = map[string]float64{} + } + classSpanTotals[class][span.Name] += ms + } + } + } + result.TasksAttempted++ + if passedForTask { + result.TasksPassed++ + classPassed[class]++ + } + } + + for name, samples := range perSpanSamples { + result.PerSpan[name] = summarizeSpan(samples) + } + result.TopLatency = topLatencySources(result.PerSpan, 3) + for class := range classTasks { + walls := classWalls[class] + var wallStats NumericStats + if len(walls) > 0 { + wallStats = SummarizeSamples(walls) + } + result.PerClass[class] = ClassSummary{ + Tasks: classTasks[class], + Passed: classPassed[class], + WallMs: wallStats, + SpanTotals: classSpanTotals[class], + } + } + result.Totals = totals + return result, nil +} + +func summarizeSpan(samples []float64) SpanStats { + if len(samples) == 0 { + return SpanStats{} + } + stats := SummarizeSamples(samples) + total := 0.0 + for _, s := range samples { + total += s + } + return SpanStats{ + Count: len(samples), + TotalMs: RoundMetric(total), + MedianMs: stats.Median, + P95Ms: stats.P95, + MaxMs: stats.Max, + } +} + +func topLatencySources(perSpan map[string]SpanStats, top int) []LatencySource { + sources := make([]LatencySource, 0, len(perSpan)) + totalAttributed := 0.0 + for _, s := range perSpan { + totalAttributed += s.TotalMs + } + for name, s := range perSpan { + share := 0.0 + if totalAttributed > 0 { + share = s.TotalMs / totalAttributed + } + sources = append(sources, LatencySource{ + Span: name, + TotalMs: s.TotalMs, + Share: RoundMetric(share), + }) + } + sort.SliceStable(sources, func(i, j int) bool { + if sources[i].TotalMs != sources[j].TotalMs { + return sources[i].TotalMs > sources[j].TotalMs + } + return sources[i].Span < sources[j].Span + }) + if top > 0 && len(sources) > top { + sources = sources[:top] + } + return sources +} + +func aggregateTotals(totals *TurnBenchTotals, tr *trace.TurnTrace) { + totals.InputTokens += tr.Counter(trace.CounterInputTokens) + totals.CachedInputTokens += tr.Counter(trace.CounterCachedInputTokens) + totals.OutputTokens += tr.Counter(trace.CounterOutputTokens) + totals.ModelRequests += tr.Counter(trace.CounterModelRequests) + totals.ToolCalls += tr.Counter(trace.CounterToolCalls) + totals.Retries += tr.Counter(trace.CounterRetryCount) + totals.Reconnects += tr.Counter(trace.CounterReconnectCount) + totals.Compactions += tr.Counter(trace.CounterCompactionCount) +} + +// FormatTurnBenchSummary renders a human-readable turn-benchmark summary that +// names the top controllable latency sources — the baseline's "do not proceed +// until" criterion. +func FormatTurnBenchSummary(result TurnBenchResult) string { + lines := []string{ + "Zero turn benchmark: " + displayOrUnknown(result.Suite), + "model: " + displayOrUnknown(result.Model), + fmt.Sprintf("tasks: %d/%d passed across %d iteration(s)", result.TasksPassed, result.TasksAttempted, result.Iterations), + } + if result.Mode != "" { + lines = append(lines, "mode: "+result.Mode) + } + if len(result.TopLatency) > 0 { + lines = append(lines, "top latency sources:") + for _, src := range result.TopLatency { + lines = append(lines, fmt.Sprintf(" %-18s %10s %5.1f%%", src.Span, FormatMetric(src.TotalMs, "ms"), src.Share*100)) + } + } + lines = append(lines, fmt.Sprintf("totals: in=%d (cached %d) out=%d | requests=%d tools=%d retries=%d reconnects=%d compactions=%d", + result.Totals.InputTokens, result.Totals.CachedInputTokens, result.Totals.OutputTokens, + result.Totals.ModelRequests, result.Totals.ToolCalls, result.Totals.Retries, + result.Totals.Reconnects, result.Totals.Compactions)) + for _, class := range sortedClasses(result.PerClass) { + summary := result.PerClass[class] + median := FormatMetric(summary.WallMs.Median, "ms") + lines = append(lines, fmt.Sprintf(" [%s] %d/%d passed, wall median %s", class, summary.Passed, summary.Tasks, median)) + } + return strings.Join(lines, "\n") +} + +func sortedClasses(perClass map[string]ClassSummary) []string { + classes := make([]string, 0, len(perClass)) + for c := range perClass { + classes = append(classes, c) + } + sort.Strings(classes) + return classes +} + +// WriteTurnBenchJSON writes the indented JSON form of a turn-benchmark result. +func WriteTurnBenchJSON(w io.Writer, result TurnBenchResult) error { + encoder := json.NewEncoder(w) + encoder.SetIndent("", " ") + return encoder.Encode(result) +} + +// NewTurnExecRunner builds the production turn-benchmark runner: it invokes +// headless `zero exec` with stream-json output AND `--trace `, then +// parses the emitted NDJSON trace into a *trace.TurnTrace. binary is the path to +// the `zero` binary; extraArgs are appended to every invocation. Pass/fail is +// decided from the stream-json run_end exit code (and the task's +// VerificationCommand when present), exactly like NewExecRunner. +func NewTurnExecRunner(binary string, extraArgs ...string) TurnRunner { + return func(ctx context.Context, task BenchTask, rc RunContext) TurnTaskOutcome { + traceFile, err := os.CreateTemp("", "zero-turn-trace-*.ndjson") + if err != nil { + return TurnTaskOutcome{Err: fmt.Errorf("create trace file: %w", err)} + } + _ = traceFile.Close() + tracePath := traceFile.Name() + defer os.Remove(tracePath) + + args := buildTurnExecArgs(task, rc, tracePath, extraArgs) + cmd := exec.CommandContext(ctx, binary, args...) + cmd.Env = appendNoColor(os.Environ()) + if dir := strings.TrimSpace(task.WorkspaceFixture); dir != "" { + cmd.Dir = dir + } + var outBuf, errBuf bytes.Buffer + cmd.Stdout = &outBuf + cmd.Stderr = &errBuf + start := time.Now() + runErr := cmd.Run() + wallMs := float64(time.Since(start).Microseconds()) / 1000 + _ = runErr + + exitCode, haveExit := streamJSONExitCode(outBuf.Bytes()) + outcome := TurnTaskOutcome{WallMs: wallMs} + if haveExit && exitCode != 0 { + outcome.VerifyErr = fmt.Sprintf("agent run_end exit code %d", exitCode) + } else if !haveExit { + detail := strings.TrimSpace(errBuf.String()) + if detail == "" { + detail = "missing terminal run_end event" + } + outcome.Err = fmt.Errorf("zero exec failed: %s", detail) + return outcome + } + + // Parse the captured trace (best-effort: a missing/empty file is not fatal — + // the run still produced a pass/fail; the trace is the attribution layer). + if f, ferr := os.Open(tracePath); ferr == nil { + if tr, perr := trace.ReadNDJSON(f); perr == nil { + outcome.Trace = tr + } + _ = f.Close() + } + + if len(task.VerificationCommand) > 0 { + if vOutcome := runVerification(ctx, task); !vOutcome.Passed { + outcome.VerifyErr = strings.TrimSpace(vOutcome.Detail) + return outcome + } + } + outcome.Passed = true + return outcome + } +} + +func buildTurnExecArgs(task BenchTask, rc RunContext, tracePath string, extraArgs []string) []string { + args := []string{"exec", "--output-format", "stream-json", "--trace", tracePath} + if model := strings.TrimSpace(rc.Model); model != "" { + args = append(args, "--model", model) + } + if mode := strings.TrimSpace(rc.Mode); mode != "" { + args = append(args, "--mode", mode) + } + if rc.SelfCorrect { + args = append(args, "--self-correct") + } + args = append(args, extraArgs...) + args = append(args, task.Prompt) + return args +} + +// ResolveBinary locates the zero binary for a benchmark run: an explicit path +// when provided, else a `zero` (or zero.exe) on PATH, else a binary built into +// the repo root. Returns an error when none is found. +func ResolveBinary(explicit string) (string, error) { + if v := strings.TrimSpace(explicit); v != "" { + if _, err := os.Stat(v); err != nil { + return "", fmt.Errorf("trace binary not found: %w", err) + } + return v, nil + } + if path, err := exec.LookPath("zero"); err == nil { + return path, nil + } + if path, err := exec.LookPath("zero.exe"); err == nil { + return path, nil + } + cwd, err := os.Getwd() + if err == nil { + for _, name := range []string{"zero", "zero.exe"} { + candidate := filepath.Join(cwd, name) + if _, err := os.Stat(candidate); err == nil { + return candidate, nil + } + } + } + return "", errors.New("zero binary not found; build it first or pass an explicit path") +} diff --git a/internal/perfbench/turn_bench_test.go b/internal/perfbench/turn_bench_test.go new file mode 100644 index 000000000..6afb7a548 --- /dev/null +++ b/internal/perfbench/turn_bench_test.go @@ -0,0 +1,302 @@ +package perfbench + +import ( + "bytes" + "context" + "encoding/json" + "path/filepath" + "strings" + "testing" + "time" + + "github.com/Gitlawb/zero/internal/trace" +) + +// fakeTurnRunner returns a canned *trace.TurnTrace per task so the harness's +// aggregation logic can be exercised without a model or a binary. Each task +// yields one generation span (the dominant cost), one tool_execution span, and +// the counters the totals aggregate. +func fakeTurnRunner(canned map[string]*trace.TurnTrace) TurnRunner { + return func(ctx context.Context, task BenchTask, rc RunContext) TurnTaskOutcome { + tr, ok := canned[task.ID] + if !ok { + return TurnTaskOutcome{Err: errNoCanned} + } + wallMs := float64(tr.WallDuration().Microseconds()) / 1000 + return TurnTaskOutcome{Passed: true, WallMs: wallMs, Trace: tr} + } +} + +var errNoCanned = &cannedError{} + +type cannedError struct{} + +func (*cannedError) Error() string { return "no canned trace for task" } + +// cannedTrace builds a deterministic *trace.TurnTrace with the given spans and +// counters. Spans are recorded as fixed durations (no real timing) so the +// aggregation math is predictable in assertions. +func cannedTrace(genMs, toolMs int, tokens int64) *trace.TurnTrace { + r := trace.NewRecorder("sess", "run-1", "test") + r.Start() + r.RecordSpan(trace.SpanGeneration, time.Duration(genMs)*time.Millisecond) + r.RecordSpan(trace.SpanToolExecution, time.Duration(toolMs)*time.Millisecond) + r.Counter(trace.CounterInputTokens, tokens) + r.Counter(trace.CounterOutputTokens, tokens/2) + r.Counter(trace.CounterModelRequests, 1) + r.Counter(trace.CounterToolCalls, 1) + r.StampFirstToken() + return r.Finish() +} + +func TestRunTurnBenchAggregation(t *testing.T) { + set := TaskSet{ + ID: "fake-suite", + Tasks: []BenchTask{ + {ID: "t1", Class: "nav", Prompt: "p1"}, + {ID: "t2", Class: "nav", Prompt: "p2"}, + {ID: "t3", Class: "edit", Prompt: "p3"}, + }, + } + canned := map[string]*trace.TurnTrace{ + "t1": cannedTrace(100, 10, 1000), + "t2": cannedTrace(300, 10, 1000), + "t3": cannedTrace(200, 50, 2000), + } + cfg := TurnBenchConfig{ + Model: "fake-model", + Iterations: 1, + Runner: fakeTurnRunner(canned), + Now: func() time.Time { return time.Date(2026, 1, 2, 3, 4, 5, 0, time.UTC) }, + } + result, err := RunTurnBench(context.Background(), set, cfg) + if err != nil { + t.Fatalf("RunTurnBench: %v", err) + } + if result.TasksAttempted != 3 || result.TasksPassed != 3 { + t.Fatalf("attempted=%d passed=%d, want 3/3", result.TasksAttempted, result.TasksPassed) + } + if result.SchemaVersion != TurnSchemaVersion { + t.Fatalf("schemaVersion = %d, want %d", result.SchemaVersion, TurnSchemaVersion) + } + if result.Date != "2026-01-02T03:04:05Z" { + t.Fatalf("date = %q", result.Date) + } + + // Per-span: generation appears in all three (100+300+200=600ms), tool in all + // three (10+10+50=70ms). Count must equal the number of tasks * iterations. + gen := result.PerSpan[trace.SpanGeneration] + if gen.Count != 3 { + t.Fatalf("generation count = %d, want 3", gen.Count) + } + if gen.TotalMs != 600 { + t.Fatalf("generation totalMs = %v, want 600", gen.TotalMs) + } + tool := result.PerSpan[trace.SpanToolExecution] + if tool.TotalMs != 70 { + t.Fatalf("tool totalMs = %v, want 70", tool.TotalMs) + } + + // Top latency: generation (600) ranks above tool (70). Exactly two spans + // here, so both appear and generation is first. + if len(result.TopLatency) != 2 || result.TopLatency[0].Span != trace.SpanGeneration { + t.Fatalf("topLatency = %+v", result.TopLatency) + } + if result.TopLatency[0].Share <= result.TopLatency[1].Share { + t.Fatalf("top latency not ranked by share: %+v", result.TopLatency) + } + + // Totals: 3 model requests, 3 tool calls, input tokens 1000+1000+2000=4000. + if result.Totals.ModelRequests != 3 { + t.Fatalf("modelRequests = %d, want 3", result.Totals.ModelRequests) + } + if result.Totals.ToolCalls != 3 { + t.Fatalf("toolCalls = %d, want 3", result.Totals.ToolCalls) + } + if result.Totals.InputTokens != 4000 { + t.Fatalf("inputTokens = %d, want 4000", result.Totals.InputTokens) + } + if result.Totals.OutputTokens != 2000 { + t.Fatalf("outputTokens = %d, want 2000", result.Totals.OutputTokens) + } + + // Per-class: nav has two tasks, edit has one; both fully passed. + nav := result.PerClass["nav"] + if nav.Tasks != 2 || nav.Passed != 2 { + t.Fatalf("nav class = %+v", nav) + } + edit := result.PerClass["edit"] + if edit.Tasks != 1 || edit.Passed != 1 { + t.Fatalf("edit class = %+v", edit) + } +} + +func TestRunTurnBenchIterationsAggregates(t *testing.T) { + set := TaskSet{ + ID: "iter-suite", + Tasks: []BenchTask{{ID: "t1", Class: "nav", Prompt: "p1"}}, + } + canned := map[string]*trace.TurnTrace{"t1": cannedTrace(100, 10, 500)} + cfg := TurnBenchConfig{ + Model: "fake-model", + Iterations: 3, + Runner: fakeTurnRunner(canned), + Now: func() time.Time { return time.Date(2026, 1, 2, 3, 4, 5, 0, time.UTC) }, + } + result, err := RunTurnBench(context.Background(), set, cfg) + if err != nil { + t.Fatalf("RunTurnBench: %v", err) + } + if result.PerSpan[trace.SpanGeneration].Count != 3 { + t.Fatalf("generation count = %d, want 3 (one per iteration)", result.PerSpan[trace.SpanGeneration].Count) + } + if result.PerSpan[trace.SpanGeneration].TotalMs != 300 { + t.Fatalf("generation totalMs = %v, want 300", result.PerSpan[trace.SpanGeneration].TotalMs) + } +} + +func TestRunTurnBenchRequiresModelAndRunner(t *testing.T) { + set := TaskSet{ID: "s", Tasks: []BenchTask{{ID: "t", Prompt: "p"}}} + if _, err := RunTurnBench(context.Background(), set, TurnBenchConfig{Runner: fakeTurnRunner(nil)}); err == nil { + t.Fatal("expected error for missing model") + } + if _, err := RunTurnBench(context.Background(), set, TurnBenchConfig{Model: "m"}); err == nil { + t.Fatal("expected error for missing runner") + } + if _, err := RunTurnBench(context.Background(), TaskSet{ID: "empty"}, TurnBenchConfig{Model: "m", Runner: fakeTurnRunner(nil)}); err == nil { + t.Fatal("expected error for empty task set") + } +} + +func TestTopLatencySourcesRanksByTotalAndCapsTopN(t *testing.T) { + perSpan := map[string]SpanStats{ + "a": {TotalMs: 100}, + "b": {TotalMs: 500}, + "c": {TotalMs: 300}, + "d": {TotalMs: 50}, + } + top := topLatencySources(perSpan, 3) + if len(top) != 3 { + t.Fatalf("len = %d, want 3", len(top)) + } + wantOrder := []string{"b", "c", "a"} + for i, w := range wantOrder { + if top[i].Span != w { + t.Fatalf("top[%d] = %q, want %q", i, top[i].Span, w) + } + } + // Shares sum to 1 across all four (100+500+300+50=950); the top-3 retain + // their global share (not renormalized to the top-3). + // Share is rounded to 2 decimals by RoundMetric (500/950 -> 0.53), so compare + // against the rounded value with a small tolerance. + if got, want := top[0].Share, RoundMetric(500.0/950.0); !approxEqual(got, want, 0.001) { + t.Fatalf("top[0] share = %v, want %v", got, want) + } +} + +func TestWriteTurnBenchJSONRoundTrip(t *testing.T) { + set := TaskSet{ID: "json-suite", Tasks: []BenchTask{{ID: "t1", Class: "nav", Prompt: "p1"}}} + canned := map[string]*trace.TurnTrace{"t1": cannedTrace(150, 20, 800)} + result, err := RunTurnBench(context.Background(), set, TurnBenchConfig{ + Model: "fake-model", + Runner: fakeTurnRunner(canned), + Now: func() time.Time { return time.Date(2026, 1, 2, 3, 4, 5, 0, time.UTC) }, + }) + if err != nil { + t.Fatalf("RunTurnBench: %v", err) + } + var buf bytes.Buffer + if err := WriteTurnBenchJSON(&buf, result); err != nil { + t.Fatalf("WriteTurnBenchJSON: %v", err) + } + var decoded TurnBenchResult + if err := json.Unmarshal(buf.Bytes(), &decoded); err != nil { + t.Fatalf("unmarshal: %v\n%s", err, buf.String()) + } + if decoded.SchemaVersion != TurnSchemaVersion || decoded.TasksPassed != 1 { + t.Fatalf("decoded = %+v", decoded) + } + if decoded.PerSpan[trace.SpanGeneration].TotalMs != 150 { + t.Fatalf("decoded generation totalMs = %v, want 150", decoded.PerSpan[trace.SpanGeneration].TotalMs) + } +} + +func TestFormatTurnBenchSummaryNamesTopSources(t *testing.T) { + set := TaskSet{ID: "fmt-suite", Tasks: []BenchTask{{ID: "t1", Class: "nav", Prompt: "p1"}}} + canned := map[string]*trace.TurnTrace{"t1": cannedTrace(150, 20, 800)} + result, err := RunTurnBench(context.Background(), set, TurnBenchConfig{ + Model: "fake-model", + Runner: fakeTurnRunner(canned), + Now: func() time.Time { return time.Date(2026, 1, 2, 3, 4, 5, 0, time.UTC) }, + }) + if err != nil { + t.Fatalf("RunTurnBench: %v", err) + } + summary := FormatTurnBenchSummary(result) + if !strings.Contains(summary, "top latency sources") { + t.Fatalf("summary missing top-latency header:\n%s", summary) + } + if !strings.Contains(summary, trace.SpanGeneration) { + t.Fatalf("summary missing top span name %q:\n%s", trace.SpanGeneration, summary) + } +} + +func TestLoadBaselineManifest(t *testing.T) { + path := filepath.Join("manifests", "baseline.json") + set, err := LoadTaskSet(path) + if err != nil { + t.Fatalf("LoadTaskSet: %v", err) + } + if set.ID == "" { + t.Fatal("manifest has no id") + } + // The baseline must clear the "do not proceed until ≥30 tasks" gate. + if len(set.Tasks) < 30 { + t.Fatalf("baseline has %d tasks, want >= 30", len(set.Tasks)) + } + // The six required classes must all be present and non-empty. + wantClasses := map[string]bool{ + "nav": false, "edit": false, "fix": false, + "refactor": false, "longproc": false, "longctx": false, "parallel": false, + } + counts := map[string]int{} + for _, task := range set.Tasks { + class := strings.TrimSpace(task.Class) + if class == "" { + t.Fatalf("task %q has no class", task.ID) + } + if _, ok := wantClasses[class]; !ok { + t.Fatalf("unexpected class %q on task %q", class, task.ID) + } + wantClasses[class] = true + counts[class]++ + } + for class, present := range wantClasses { + if !present { + t.Fatalf("manifest missing required class %q", class) + } + if counts[class] == 0 { + t.Fatalf("class %q has zero tasks", class) + } + } + // Every task must have a prompt and a workspace fixture pointing under testdata. + for _, task := range set.Tasks { + if strings.TrimSpace(task.Prompt) == "" { + t.Fatalf("task %q has empty prompt", task.ID) + } + if strings.TrimSpace(task.WorkspaceFixture) == "" { + t.Fatalf("task %q has no workspace fixture", task.ID) + } + if !strings.Contains(task.WorkspaceFixture, "testdata") { + t.Fatalf("task %q fixture %q not under testdata", task.ID, task.WorkspaceFixture) + } + } +} + +func approxEqual(a, b, tol float64) bool { + d := a - b + if d < 0 { + d = -d + } + return d < tol +} diff --git a/internal/providers/providerio/auth.go b/internal/providers/providerio/auth.go index e65949205..2ac5132db 100644 --- a/internal/providers/providerio/auth.go +++ b/internal/providers/providerio/auth.go @@ -4,6 +4,8 @@ import ( "context" "net/http" "strings" + + "github.com/Gitlawb/zero/internal/trace" ) // TokenResolver yields a fresh OAuth credential for one request, or ok=false to @@ -42,7 +44,12 @@ func SendWithAuthRetry( // request (leaking the path/body) before we return the error. headers := base if resolver != nil { + // ProviderQueue captures pre-send auth-wait (OAuth token resolve). No + // send-side semaphore exists today; a future request queue would also + // accumulate here. nil recorder (untraced) is a no-op. + queueSpan := trace.FromContext(ctx).Span(trace.SpanProviderQueue) header, value, ok, rerr := resolver(ctx, forceRefresh) + queueSpan.End() if rerr != nil { return nil, rerr } diff --git a/internal/providers/providerio/providerio.go b/internal/providers/providerio/providerio.go index 5f580a8d6..fe017c525 100644 --- a/internal/providers/providerio/providerio.go +++ b/internal/providers/providerio/providerio.go @@ -16,6 +16,7 @@ import ( "strings" "time" + "github.com/Gitlawb/zero/internal/trace" "github.com/Gitlawb/zero/internal/zeroruntime" ) @@ -366,6 +367,9 @@ func ScanSSEDataWithContext( // NOT output, so it must not reset the content watchdog. continue } + // First non-keepalive payload = first model output. Stamp once; later + // real payloads are no-ops. nil recorder (untraced run) is a no-op. + trace.FromContext(ctx).StampFirstToken() resetContent() if !handle(item.data) { // The provider asked to stop (e.g. it already emitted an error diff --git a/internal/providers/providerio/retry.go b/internal/providers/providerio/retry.go index 256ac2a17..59c53e1cc 100644 --- a/internal/providers/providerio/retry.go +++ b/internal/providers/providerio/retry.go @@ -7,6 +7,8 @@ import ( "strconv" "strings" "time" + + "github.com/Gitlawb/zero/internal/trace" ) // Transient-failure retry, shared by every provider. @@ -67,7 +69,9 @@ func SendWithRetry( setHeader(request) } + connectSpan := trace.FromContext(ctx).Span(trace.SpanProviderConnect) response, err := client.Do(request) + connectSpan.End() if err != nil { // A transport failure on a POST does NOT mean the server didn't receive // it — the request may have arrived and be generating a (billable, @@ -82,6 +86,9 @@ func SendWithRetry( } if ShouldRetryStatus(response.StatusCode) && attempt < maxAttempts { + if r := trace.FromContext(ctx); r != nil { + r.Counter(trace.CounterRetryCount, 1) + } wait := RetryAfter(response) _ = response.Body.Close() if Backoff(ctx, attempt, wait) { diff --git a/internal/trace/context.go b/internal/trace/context.go new file mode 100644 index 000000000..2006b3554 --- /dev/null +++ b/internal/trace/context.go @@ -0,0 +1,25 @@ +package trace + +import "context" + +type ctxKey struct{} + +// WithContext returns a copy of ctx that carries r, so the providerio seam +// and other lower layers can reach the recorder without changing their +// function signatures. Passing a nil recorder still injects a value (a nil +// *Recorder), but FromContext returns nil for it so downstream no-op guards +// see nil. +func WithContext(ctx context.Context, r *Recorder) context.Context { + return context.WithValue(ctx, ctxKey{}, r) +} + +// FromContext returns the recorder carried by ctx, or nil if none is present +// (or if the carried value is nil). Callers must guard all stamps with a nil +// check; the recorder methods are themselves nil-safe. +func FromContext(ctx context.Context) *Recorder { + if ctx == nil { + return nil + } + v, _ := ctx.Value(ctxKey{}).(*Recorder) + return v +} diff --git a/internal/trace/emit.go b/internal/trace/emit.go new file mode 100644 index 000000000..22ed94405 --- /dev/null +++ b/internal/trace/emit.go @@ -0,0 +1,153 @@ +package trace + +import ( + "encoding/json" + "fmt" + "io" + "sort" + "time" +) + +// Sink is the abstraction a finished TurnTrace is written to. The NDJSON and +// text sinks are implemented here; an OpenTelemetry sink is a documented +// future addition (see opentelemetrySink below) and is intentionally not +// pulled in as a dependency. +type Sink interface { + Emit(*TurnTrace) error +} + +// WriteNDJSON emits the trace as newline-delimited JSON compatible with the +// internal/agenteval trace contract: one object per line, each carrying a +// "type" and (for spans/counters) a "name" so ParseTraceEventKeys keys them. +// +// The first line is a "trace" summary (name "run"), followed by one "span" +// line per span and one "counter" line per counter. Spans and counters are +// emitted in stable (sorted) order for deterministic output. +func WriteNDJSON(w io.Writer, t *TurnTrace) error { + if w == nil { + return nil + } + if t == nil { + return nil + } + enc := json.NewEncoder(w) + enc.SetEscapeHTML(false) + + if err := enc.Encode(map[string]any{ + "type": "trace", + "name": "run", + "session_id": t.SessionID, + "run_id": t.RunID, + "profile": t.Profile, + "started_at": formatTime(t.StartedAt), + "first_visible_at": formatTime(t.FirstVisibleEventAt), + "first_useful_at": formatTime(t.FirstUsefulActionAt), + "first_token_at": formatTime(t.FirstTokenAt), + "completed_at": formatTime(t.CompletedAt), + "wall_ms": ms(t.WallDuration()), + "attributed_ms": ms(t.AttributedDuration()), + "attribution": round3(t.AttributionRatio()), + }); err != nil { + return err + } + + spans := append([]Span(nil), t.Spans...) + sort.Slice(spans, func(i, j int) bool { return spans[i].Name < spans[j].Name }) + for _, span := range spans { + if err := enc.Encode(map[string]any{ + "type": "span", + "name": span.Name, + "duration_ms": ms(span.Duration), + }); err != nil { + return err + } + } + + counters := append([]Counter(nil), t.Counters...) + sort.Slice(counters, func(i, j int) bool { return counters[i].Name < counters[j].Name }) + for _, c := range counters { + if err := enc.Encode(map[string]any{ + "type": "counter", + "name": c.Name, + "value": c.Value, + }); err != nil { + return err + } + } + return nil +} + +// WriteText emits a human-readable trace: a header, one line per span with its +// share of wall time, a totals line, then counters. +func WriteText(w io.Writer, t *TurnTrace) error { + if w == nil || t == nil { + return nil + } + wall := t.WallDuration() + fmt.Fprintf(w, "trace run=%s session=%s profile=%s\n", t.RunID, t.SessionID, t.Profile) + fmt.Fprintf(w, " started=%s completed=%s wall=%s\n", formatTime(t.StartedAt), formatTime(t.CompletedAt), wall) + if !t.FirstVisibleEventAt.IsZero() { + fmt.Fprintf(w, " first_visible_event=%s (+%s)\n", formatTime(t.FirstVisibleEventAt), t.FirstVisibleEventAt.Sub(t.StartedAt)) + } + if !t.FirstUsefulActionAt.IsZero() { + fmt.Fprintf(w, " first_useful_action=%s (+%s)\n", formatTime(t.FirstUsefulActionAt), t.FirstUsefulActionAt.Sub(t.StartedAt)) + } + if !t.FirstTokenAt.IsZero() { + fmt.Fprintf(w, " first_token=%s (+%s)\n", formatTime(t.FirstTokenAt), t.FirstTokenAt.Sub(t.StartedAt)) + } + + spans := append([]Span(nil), t.Spans...) + sort.Slice(spans, func(i, j int) bool { return spans[i].Name < spans[j].Name }) + fmt.Fprintln(w, "spans:") + for _, span := range spans { + share := 0.0 + if wall > 0 { + share = float64(span.Duration) / float64(wall) + } + fmt.Fprintf(w, " %-18s %10s %5.1f%%\n", span.Name, span.Duration, share*100) + } + fmt.Fprintf(w, " %-18s %10s %5.1f%%\n", "attributed", t.AttributedDuration(), t.AttributionRatio()*100) + + counters := append([]Counter(nil), t.Counters...) + sort.Slice(counters, func(i, j int) bool { return counters[i].Name < counters[j].Name }) + fmt.Fprintln(w, "counters:") + for _, c := range counters { + fmt.Fprintf(w, " %-22s %d\n", c.Name, c.Value) + } + return nil +} + +// NDJSONSink adapts an io.Writer as a Sink emitting NDJSON. +type NDJSONSink struct{ W io.Writer } + +func (s NDJSONSink) Emit(t *TurnTrace) error { return WriteNDJSON(s.W, t) } + +// TextSink adapts an io.Writer as a Sink emitting human-readable text. +type TextSink struct{ W io.Writer } + +func (s TextSink) Emit(t *TurnTrace) error { return WriteText(s.W, t) } + +// opentelemetrySink is a placeholder documenting the future OpenTelemetry +// export path. It is intentionally not implemented in the baseline: doing so +// would pull in the OTLP exporter dependency. When added, satisfy Sink by +// translating each Span into an OTLP span and each Counter into an attribute, +// parented under the run's trace: +// +// type opentelemetrySink struct{ exp someExporter } +// func (s opentelemetrySink) Emit(t *TurnTrace) error { ... } +// +// It is left as a comment to avoid an unused-type lint while signaling the +// intended extension seam to the next PR. + +func ms(d time.Duration) float64 { return round3(float64(d.Microseconds()) / 1000) } + +func round3(v float64) float64 { + return float64(int64(v*1000+0.5)) / 1000 +} + +func formatTime(t time.Time) string { + if t.IsZero() { + return "" + } + return t.UTC().Format(time.RFC3339Nano) +} diff --git a/internal/trace/parse.go b/internal/trace/parse.go new file mode 100644 index 000000000..08caf71f7 --- /dev/null +++ b/internal/trace/parse.go @@ -0,0 +1,91 @@ +package trace + +import ( + "bufio" + "encoding/json" + "io" + "strings" + "time" +) + +// ReadNDJSON parses an NDJSON trace emitted by WriteNDJSON back into a TurnTrace. +// It is the inverse of WriteNDJSON and is used by the benchmark harness to turn a +// captured trace file into structured per-span stats. Lines that are not valid +// JSON or lack a "type" field are skipped (the emitter is the only writer, so in +// practice every line is valid; the skip keeps a stray blank line from fataling a +// benchmark run). The first "trace" line sets the run/timing fields; "span" and +// "counter" lines populate Spans and Counters. +func ReadNDJSON(r io.Reader) (*TurnTrace, error) { + if r == nil { + return nil, nil + } + t := &TurnTrace{} + scanner := bufio.NewScanner(r) + scanner.Buffer(make([]byte, 0, 64*1024), 4*1024*1024) + for scanner.Scan() { + line := strings.TrimSpace(scanner.Text()) + if line == "" { + continue + } + var obj map[string]any + if err := json.Unmarshal([]byte(line), &obj); err != nil { + continue + } + typ, _ := obj["type"].(string) + switch typ { + case "trace": + t.RunID, _ = obj["run_id"].(string) + t.SessionID, _ = obj["session_id"].(string) + t.Profile, _ = obj["profile"].(string) + t.StartedAt = parseTime(obj["started_at"]) + t.FirstVisibleEventAt = parseTime(obj["first_visible_at"]) + t.FirstUsefulActionAt = parseTime(obj["first_useful_at"]) + t.FirstTokenAt = parseTime(obj["first_token_at"]) + t.CompletedAt = parseTime(obj["completed_at"]) + case "span": + name, _ := obj["name"].(string) + t.Spans = append(t.Spans, Span{Name: name, Duration: parseDurationMs(obj["duration_ms"])}) + case "counter": + name, _ := obj["name"].(string) + t.Counters = append(t.Counters, Counter{Name: name, Value: parseInt64(obj["value"])}) + } + } + if err := scanner.Err(); err != nil { + return nil, err + } + return t, nil +} + +func parseTime(v any) time.Time { + s, _ := v.(string) + if s == "" { + return time.Time{} + } + t, err := time.Parse(time.RFC3339Nano, s) + if err != nil { + return time.Time{} + } + return t +} + +func parseDurationMs(v any) time.Duration { + f := toFloat64(v) + return time.Duration(f * float64(time.Millisecond)) +} + +func parseInt64(v any) int64 { + return int64(toFloat64(v)) +} + +func toFloat64(v any) float64 { + switch n := v.(type) { + case float64: + return n + case int64: + return float64(n) + case int: + return float64(n) + default: + return 0 + } +} diff --git a/internal/trace/recorder.go b/internal/trace/recorder.go new file mode 100644 index 000000000..3a9fa0509 --- /dev/null +++ b/internal/trace/recorder.go @@ -0,0 +1,187 @@ +package trace + +import ( + "sync" + "time" +) + +// Recorder is the in-process handle one agent.Run stamps spans and counters +// into. It is concurrency-safe: parallel tool execution, provider reconnects, +// and async streaming stamp concurrently from different goroutines. +// +// A nil *Recorder is valid to call: the no-op helpers below route every +// stamp through a nil check so callers can write `options.Trace.Start()` +// unconditionally and pay nothing when tracing is off. +type Recorder struct { + mu sync.Mutex + tr TurnTrace + started bool + finished bool + firstTokenStamped bool + firstVisibleStamped bool + firstActionStamped bool +} + +// NewRecorder returns a ready recorder. sessionID correlates with the agent +// session (Options.SessionID); runID is a per-Run sequence; profile is an +// optional label (e.g. "cold", "warm") for benchmark runs. +func NewRecorder(sessionID, runID, profile string) *Recorder { + return &Recorder{tr: TurnTrace{ + SessionID: sessionID, + RunID: runID, + Profile: profile, + }} +} + +// Start stamps StartedAt. Safe to call at most once; idempotent on repeat. +func (r *Recorder) Start() { + if r == nil { + return + } + r.mu.Lock() + defer r.mu.Unlock() + if r.started { + return + } + r.started = true + r.tr.StartedAt = time.Now() +} + +// SpanHandle is a live timing span. Call End exactly once to commit it; a +// second End is a no-op. Not calling End leaks the span (it is dropped). +type SpanHandle struct { + recorder *Recorder + name string + start time.Time + once sync.Once +} + +// End commits the span's elapsed duration to the recorder. Durations +// accumulate by name so repeated stamps of the same span add together. +func (s *SpanHandle) End() { + if s == nil || s.recorder == nil { + return + } + s.once.Do(func() { + s.recorder.addSpan(s.name, time.Since(s.start)) + }) +} + +// Span begins a named span and returns a handle. Caller is responsible for +// calling End when the span completes. Example: +// +// span := r.Span(trace.SpanGeneration) +// defer span.End() +func (r *Recorder) Span(name string) *SpanHandle { + if r == nil { + return nil + } + return &SpanHandle{recorder: r, name: name, start: time.Now()} +} + +// RecordSpan commits an already-measured duration to name, accumulating with +// any prior value. Use this when the caller already holds a start time (for +// example, a span that began before the recorder existed). +func (r *Recorder) RecordSpan(name string, d time.Duration) { + if r == nil { + return + } + r.addSpan(name, d) +} + +// Counter adds n to the named counter, accumulating across calls. +func (r *Recorder) Counter(name string, n int64) { + if r == nil { + return + } + r.mu.Lock() + defer r.mu.Unlock() + r.addCounterLocked(name, n) +} + +// StampFirstToken records the time of the first output token. Only the first +// call wins; later calls are no-ops. +func (r *Recorder) StampFirstToken() { + if r == nil { + return + } + r.mu.Lock() + defer r.mu.Unlock() + if r.firstTokenStamped { + return + } + r.firstTokenStamped = true + r.tr.FirstTokenAt = time.Now() +} + +// StampFirstVisibleEvent records the first event visible to the user. First +// call wins. +func (r *Recorder) StampFirstVisibleEvent() { + if r == nil { + return + } + r.mu.Lock() + defer r.mu.Unlock() + if r.firstVisibleStamped { + return + } + r.firstVisibleStamped = true + r.tr.FirstVisibleEventAt = time.Now() +} + +// StampFirstUsefulAction records the first tool call or substantive action. +// First call wins. +func (r *Recorder) StampFirstUsefulAction() { + if r == nil { + return + } + r.mu.Lock() + defer r.mu.Unlock() + if r.firstActionStamped { + return + } + r.firstActionStamped = true + r.tr.FirstUsefulActionAt = time.Now() +} + +// Finish stamps CompletedAt and returns a snapshot of the trace. Calling +// Finish more than once returns the same snapshot. +func (r *Recorder) Finish() *TurnTrace { + if r == nil { + return nil + } + r.mu.Lock() + defer r.mu.Unlock() + if !r.finished { + r.finished = true + r.tr.CompletedAt = time.Now() + } + snap := r.tr + // Copy the slices so callers cannot mutate the recorder's state. + snap.Spans = append([]Span(nil), r.tr.Spans...) + snap.Counters = append([]Counter(nil), r.tr.Counters...) + return &snap +} + +// addSpan accumulates d into the named span, merging with an existing entry. +func (r *Recorder) addSpan(name string, d time.Duration) { + r.mu.Lock() + defer r.mu.Unlock() + for i := range r.tr.Spans { + if r.tr.Spans[i].Name == name { + r.tr.Spans[i].Duration += d + return + } + } + r.tr.Spans = append(r.tr.Spans, Span{Name: name, Duration: d}) +} + +func (r *Recorder) addCounterLocked(name string, n int64) { + for i := range r.tr.Counters { + if r.tr.Counters[i].Name == name { + r.tr.Counters[i].Value += n + return + } + } + r.tr.Counters = append(r.tr.Counters, Counter{Name: name, Value: n}) +} diff --git a/internal/trace/trace.go b/internal/trace/trace.go new file mode 100644 index 000000000..e46ab6ae9 --- /dev/null +++ b/internal/trace/trace.go @@ -0,0 +1,152 @@ +// Package trace records per-turn timing for a Zero agent run. +// +// Tracing is opt-in. A *Recorder is attached to agent.Options and threaded +// through the run via context (see FromContext / WithContext). When the +// recorder is nil, every stamp is a no-op and the agent loop, providers, and +// tools are byte-identical to an untraced run. +// +// The emitted NDJSON is compatible with internal/agenteval's trace contract: +// one JSON object per line carrying a "type" (and usually "name") field, so +// agenteval.ParseTraceEventKeys / MissingTraceEvents can validate a run. +package trace + +import "time" + +// Span names. These are the "name" keys emitted in the NDJSON event stream +// (e.g. {"type":"span","name":"generation","duration_ms":123.4}) and the +// single source of truth for what a run's wall time is attributed to. +const ( + SpanPromptBuild = "prompt_build" + SpanProviderConnect = "provider_connect" + SpanProviderQueue = "provider_queue" + SpanGeneration = "generation" + SpanToolQueue = "tool_queue" + SpanToolExecution = "tool_execution" + SpanPermissionWait = "permission_wait" + SpanProcessWait = "process_wait" + SpanVerification = "verification" + SpanCompaction = "compaction" + SpanPersistence = "persistence" +) + +// Counter names. Emitted as {"type":"counter","name":"tool_calls","value":7}. +const ( + CounterModelRequests = "model_requests" + CounterToolCalls = "tool_calls" + CounterRetryCount = "retry_count" + CounterReconnectCount = "reconnect_count" + CounterCompactionCount = "compaction_count" + CounterCompletionNudges = "completion_nudges" + CounterAcceptanceChecks = "acceptance_checks" + CounterPollingTurn = "polling_turn" + CounterModelSwitches = "model_switches" + CounterInputTokens = "input_tokens" + CounterCachedInputTokens = "cached_input_tokens" + CounterOutputTokens = "output_tokens" +) + +// Span is a named duration attributed to part of a run. Spans accumulate by +// name: stamping the same name twice (e.g. prompt_build across turns) adds to +// the existing entry rather than creating a duplicate. +type Span struct { + Name string `json:"name"` + Duration time.Duration `json:"duration"` +} + +// Counter is a named integer accumulated during a run (counts and token totals). +type Counter struct { + Name string `json:"name"` + Value int64 `json:"value"` +} + +// TurnTrace is the finished record for one agent.Run. It is the value +// emitters serialize; it is not mutated after Finish returns a snapshot. +type TurnTrace struct { + SessionID string `json:"session_id"` + RunID string `json:"run_id"` + Profile string `json:"profile,omitempty"` + StartedAt time.Time `json:"started_at"` + FirstVisibleEventAt time.Time `json:"first_visible_event_at,omitempty"` + FirstUsefulActionAt time.Time `json:"first_useful_action_at,omitempty"` + FirstTokenAt time.Time `json:"first_token_at,omitempty"` + CompletedAt time.Time `json:"completed_at"` + Spans []Span `json:"spans"` + Counters []Counter `json:"counters"` +} + +// WallDuration is the total traced wall time of the run. +func (t *TurnTrace) WallDuration() time.Duration { + if t == nil || t.CompletedAt.IsZero() || t.StartedAt.IsZero() { + return 0 + } + return t.CompletedAt.Sub(t.StartedAt) +} + +// AttributedDuration is the sum of all span durations. A run is considered +// well-attributed when this is >= 95% of WallDuration. +func (t *TurnTrace) AttributedDuration() time.Duration { + if t == nil { + return 0 + } + var total time.Duration + for _, span := range t.Spans { + total += span.Duration + } + return total +} + +// AttributionRatio is AttributedDuration / WallDuration, or 0 when unattributable. +func (t *TurnTrace) AttributionRatio() float64 { + wall := t.WallDuration() + if wall <= 0 { + return 0 + } + return float64(t.AttributedDuration()) / float64(wall) +} + +// Span returns the duration recorded for name, or zero if absent. +func (t *TurnTrace) Span(name string) time.Duration { + if t == nil { + return 0 + } + for _, span := range t.Spans { + if span.Name == name { + return span.Duration + } + } + return 0 +} + +// Counter returns the value recorded for name, or zero if absent. +func (t *TurnTrace) Counter(name string) int64 { + if t == nil { + return 0 + } + for _, c := range t.Counters { + if c.Name == name { + return c.Value + } + } + return 0 +} + +// RequiredEventKeys is the set of span/counter event keys a traced run is +// expected to emit. Tests assert via agenteval.MissingTraceEvents that a run +// produces all of these. Generation spans are only produced when the run +// reaches a model request, so callers may trim this list for short circuits. +func RequiredEventKeys() []string { + return []string{ + "span:" + SpanPromptBuild, + "span:" + SpanGeneration, + "span:" + SpanToolExecution, + "span:" + SpanPermissionWait, + "span:" + SpanCompaction, + "span:" + SpanPersistence, + "span:" + SpanProviderConnect, + "counter:" + CounterModelRequests, + "counter:" + CounterToolCalls, + "counter:" + CounterInputTokens, + "counter:" + CounterOutputTokens, + "trace:run", + } +} diff --git a/internal/trace/trace_test.go b/internal/trace/trace_test.go new file mode 100644 index 000000000..c81d27ef5 --- /dev/null +++ b/internal/trace/trace_test.go @@ -0,0 +1,268 @@ +package trace + +import ( + "bytes" + "context" + "encoding/json" + "strings" + "sync" + "testing" + "time" + + "github.com/Gitlawb/zero/internal/agenteval" +) + +func TestRecorderSpanAccumulates(t *testing.T) { + r := NewRecorder("s1", "r1", "") + r.Start() + s := r.Span(SpanGeneration) + time.Sleep(2 * time.Millisecond) + s.End() + s2 := r.Span(SpanGeneration) + time.Sleep(1 * time.Millisecond) + s2.End() + + tr := r.Finish() + got := tr.Span(SpanGeneration) + if got < 3*time.Millisecond { + t.Fatalf("generation span did not accumulate across stamps; got %v", got) + } + if len(tr.Spans) != 1 { + t.Fatalf("expected one generation span entry, got %d", len(tr.Spans)) + } +} + +func TestRecorderCounters(t *testing.T) { + r := NewRecorder("s1", "r1", "") + r.Counter(CounterToolCalls, 1) + r.Counter(CounterToolCalls, 2) + r.Counter(CounterModelRequests, 3) + + tr := r.Finish() + if got := tr.Counter(CounterToolCalls); got != 3 { + t.Fatalf("tool_calls = %d, want 3", got) + } + if got := tr.Counter(CounterModelRequests); got != 3 { + t.Fatalf("model_requests = %d, want 3", got) + } +} + +func TestRecorderFirstTokenOnce(t *testing.T) { + r := NewRecorder("s", "r", "") + r.Start() + r.StampFirstToken() + first := r.Finish().FirstTokenAt + r.StampFirstToken() // no-op after Finish; should not panic + if r.Finish().FirstTokenAt != first { + t.Fatal("StampFirstToken should not move the timestamp after the first stamp") + } +} + +func TestFinishSnapshotIsCopy(t *testing.T) { + r := NewRecorder("s", "r", "") + r.Counter(CounterToolCalls, 5) + tr := r.Finish() + tr.Counters[0].Value = 999 + if got := r.Finish().Counter(CounterToolCalls); got != 5 { + t.Fatalf("Finish snapshot must be a copy; mutating it changed recorder state to %d", got) + } +} + +func TestNilRecorderIsNoOp(t *testing.T) { + var r *Recorder + r.Start() + r.Counter(CounterToolCalls, 1) + r.StampFirstToken() + r.StampFirstVisibleEvent() + r.StampFirstUsefulAction() + r.RecordSpan(SpanGeneration, time.Millisecond) + s := r.Span(SpanGeneration) + s.End() + if tr := r.Finish(); tr != nil { + t.Fatalf("nil recorder Finish should return nil, got %+v", tr) + } +} + +func TestRecorderConcurrent(t *testing.T) { + r := NewRecorder("s", "r", "") + r.Start() + var wg sync.WaitGroup + for i := 0; i < 50; i++ { + wg.Add(1) + go func() { + defer wg.Done() + s := r.Span(SpanToolExecution) + time.Sleep(time.Millisecond) + s.End() + r.Counter(CounterToolCalls, 1) + r.StampFirstToken() + }() + } + wg.Wait() + tr := r.Finish() + if got := tr.Counter(CounterToolCalls); got != 50 { + t.Fatalf("tool_calls = %d, want 50", got) + } + if got := tr.Span(SpanToolExecution); got <= 0 { + t.Fatalf("tool_execution span empty after concurrent stamps; got %v", got) + } +} + +func TestContextRoundTrip(t *testing.T) { + r := NewRecorder("s", "r", "") + ctx := WithContext(context.Background(), r) + if got := FromContext(ctx); got != r { + t.Fatal("FromContext did not return the injected recorder") + } + if got := FromContext(context.Background()); got != nil { + t.Fatalf("FromContext on a bare context should return nil, got %v", got) + } +} + +func TestContextNilRecorder(t *testing.T) { + ctx := WithContext(context.Background(), nil) + if got := FromContext(ctx); got != nil { + t.Fatalf("FromContext should return nil for an injected nil recorder, got %v", got) + } +} + +func TestWriteNDJSONMatchesAgentevalContract(t *testing.T) { + r := NewRecorder("s1", "r1", "cold") + r.Start() + r.RecordSpan(SpanPromptBuild, 10*time.Millisecond) + r.RecordSpan(SpanGeneration, 50*time.Millisecond) + r.RecordSpan(SpanToolExecution, 5*time.Millisecond) + r.RecordSpan(SpanPermissionWait, 1*time.Millisecond) + r.RecordSpan(SpanCompaction, 2*time.Millisecond) + r.RecordSpan(SpanPersistence, 1*time.Millisecond) + r.RecordSpan(SpanProviderConnect, 8*time.Millisecond) + r.Counter(CounterModelRequests, 2) + r.Counter(CounterToolCalls, 3) + r.Counter(CounterInputTokens, 100) + r.Counter(CounterOutputTokens, 40) + tr := r.Finish() + + var buf bytes.Buffer + if err := WriteNDJSON(&buf, tr); err != nil { + t.Fatalf("WriteNDJSON: %v", err) + } + stdout := buf.String() + + missing := agenteval.MissingTraceEvents(RequiredEventKeys(), stdout) + if len(missing) > 0 { + t.Fatalf("NDJSON missing required event keys: %v\noutput:\n%s", missing, stdout) + } + + keys := agenteval.ParseTraceEventKeys(stdout) + want := map[string]bool{ + "trace:run": true, + "span:" + SpanPromptBuild: true, + "span:" + SpanGeneration: true, + "span:" + SpanToolExecution: true, + "span:" + SpanProviderConnect: true, + "counter:" + CounterModelRequests: true, + "counter:" + CounterToolCalls: true, + "counter:" + CounterInputTokens: true, + "counter:" + CounterOutputTokens: true, + } + for k := range want { + if !contains(keys, k) { + t.Fatalf("expected key %q in parsed keys %v", k, keys) + } + } + + // Each line must be valid JSON. + for _, line := range strings.Split(strings.TrimSpace(stdout), "\n") { + if strings.TrimSpace(line) == "" { + continue + } + var obj map[string]any + if err := json.Unmarshal([]byte(line), &obj); err != nil { + t.Fatalf("non-JSON NDJSON line: %q (%v)", line, err) + } + } +} + +func TestWriteTextIsReadable(t *testing.T) { + r := NewRecorder("s", "r", "") + r.Start() + r.RecordSpan(SpanGeneration, 42*time.Millisecond) + r.Counter(CounterToolCalls, 7) + tr := r.Finish() + var buf bytes.Buffer + if err := WriteText(&buf, tr); err != nil { + t.Fatalf("WriteText: %v", err) + } + out := buf.String() + for _, want := range []string{"trace run=", "spans:", "generation", "counters:", "tool_calls"} { + if !strings.Contains(out, want) { + t.Fatalf("text trace missing %q:\n%s", want, out) + } + } +} + +func TestAttributionRatio(t *testing.T) { + r := NewRecorder("s", "r", "") + r.Start() + // Attribute ~all wall time so the ratio is near 1.0. + r.RecordSpan(SpanGeneration, 10*time.Millisecond) + r.RecordSpan(SpanToolExecution, 10*time.Millisecond) + tr := r.Finish() + // Wall is at least 20ms and attributed is 20ms, so ratio should be <= 1 + // and the run is "well attributed" (>= 0.95 only if wall is close to 20ms; + // we assert the lower bound instead since wall includes scheduling jitter). + if ratio := tr.AttributionRatio(); ratio > 1.0 { + t.Fatalf("attribution ratio %v exceeds 1.0", ratio) + } + if tr.AttributedDuration() != 20*time.Millisecond { + t.Fatalf("attributed = %v, want 20ms", tr.AttributedDuration()) + } +} + +func contains(slice []string, s string) bool { + for _, v := range slice { + if v == s { + return true + } + } + return false +} + +func TestReadNDJSONRoundTrip(t *testing.T) { + r := NewRecorder("s1", "r1", "cold") + r.Start() + r.RecordSpan(SpanPromptBuild, 10*time.Millisecond) + r.RecordSpan(SpanGeneration, 50*time.Millisecond) + r.RecordSpan(SpanGeneration, 5*time.Millisecond) // accumulates to 55ms + r.Counter(CounterModelRequests, 3) + r.Counter(CounterToolCalls, 7) + r.StampFirstToken() + original := r.Finish() + + var buf bytes.Buffer + if err := WriteNDJSON(&buf, original); err != nil { + t.Fatalf("WriteNDJSON: %v", err) + } + parsed, err := ReadNDJSON(&buf) + if err != nil { + t.Fatalf("ReadNDJSON: %v", err) + } + if parsed == nil { + t.Fatal("ReadNDJSON returned nil") + } + if parsed.RunID != original.RunID || parsed.SessionID != original.SessionID || parsed.Profile != original.Profile { + t.Fatalf("identity mismatch: got %+v want %+v", parsed, original) + } + if got := parsed.Span(SpanGeneration); got != 55*time.Millisecond { + t.Fatalf("generation span after round-trip = %v, want 55ms", got) + } + if got := parsed.Counter(CounterModelRequests); got != 3 { + t.Fatalf("model_requests after round-trip = %d, want 3", got) + } + if got := parsed.Counter(CounterToolCalls); got != 7 { + t.Fatalf("tool_calls after round-trip = %d, want 7", got) + } + if parsed.FirstTokenAt.IsZero() { + t.Fatal("first_token_at lost in round-trip") + } +} From 6896fee475708806a2f2b53d4b781227cd6cd0ef Mon Sep 17 00:00:00 2001 From: Vasanthdev2004 Date: Thu, 16 Jul 2026 12:19:17 +0530 Subject: [PATCH 2/8] test(trace): make TestAttributionRatio clock-independent MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The test recorded two synthetic 10ms spans with no real delay and asserted the attribution ratio stayed <= 1.0. On a precise clock (Linux/macOS CI) the wall is microseconds while attributed is 20ms, so attributed/wall blows past 1.0 and the test failed — even though the ratio legitimately exceeds 1.0 when spans overlap (parallel tool execution). On Windows the coarse timer masked it, so the failure only surfaced in CI. Assert the contract instead: attributed is the deterministic sum of span durations, and the ratio equals attributed/wall (0 when wall is zero). Add a zero-wall case for the divide-by-zero guard. --- internal/trace/trace_test.go | 47 +++++++++++++++++++++++++++++------- 1 file changed, 38 insertions(+), 9 deletions(-) diff --git a/internal/trace/trace_test.go b/internal/trace/trace_test.go index c81d27ef5..be3156c30 100644 --- a/internal/trace/trace_test.go +++ b/internal/trace/trace_test.go @@ -204,18 +204,47 @@ func TestWriteTextIsReadable(t *testing.T) { func TestAttributionRatio(t *testing.T) { r := NewRecorder("s", "r", "") r.Start() - // Attribute ~all wall time so the ratio is near 1.0. r.RecordSpan(SpanGeneration, 10*time.Millisecond) r.RecordSpan(SpanToolExecution, 10*time.Millisecond) tr := r.Finish() - // Wall is at least 20ms and attributed is 20ms, so ratio should be <= 1 - // and the run is "well attributed" (>= 0.95 only if wall is close to 20ms; - // we assert the lower bound instead since wall includes scheduling jitter). - if ratio := tr.AttributionRatio(); ratio > 1.0 { - t.Fatalf("attribution ratio %v exceeds 1.0", ratio) - } - if tr.AttributedDuration() != 20*time.Millisecond { - t.Fatalf("attributed = %v, want 20ms", tr.AttributedDuration()) + + // Attributed time is the deterministic sum of recorded span durations; it + // does not depend on wall-clock timing. + if want := 20 * time.Millisecond; tr.AttributedDuration() != want { + t.Fatalf("attributed = %v, want %v", tr.AttributedDuration(), want) + } + + // AttributionRatio is attributed / wall. The spans are synthetic durations + // with no real delay, so wall is on the order of microseconds and the ratio + // can legitimately exceed 1.0 (overlapping parallel spans push it above 1.0 + // in real runs too). Assert the contract — ratio == attributed/wall — rather + // than a fixed bound, so the test is clock-independent. + wall := tr.WallDuration() + if wall <= 0 { + // Clock granularity collapsed the run to zero wall; the ratio is defined 0. + if got := tr.AttributionRatio(); got != 0 { + t.Fatalf("ratio with zero wall = %v, want 0", got) + } + return + } + wantRatio := float64(tr.AttributedDuration()) / float64(wall) + if got := tr.AttributionRatio(); got != wantRatio { + t.Fatalf("ratio = %v, want %v (attributed/wall)", got, wantRatio) + } +} + +func TestAttributionRatioZeroWall(t *testing.T) { + // A trace with no completed run has zero wall and a defined-zero ratio + // (covers the divide-by-zero guard). + tr := &TurnTrace{} + if got := tr.AttributionRatio(); got != 0 { + t.Fatalf("zero-wall ratio = %v, want 0", got) + } + if got := tr.AttributedDuration(); got != 0 { + t.Fatalf("empty attributed = %v, want 0", got) + } + if got := tr.WallDuration(); got != 0 { + t.Fatalf("empty wall = %v, want 0", got) } } From b3e6ef1f586b00023e1a947f0ce025a0fd7ec8f9 Mon Sep 17 00:00:00 2001 From: Vasanthdev2004 Date: Thu, 16 Jul 2026 12:45:15 +0530 Subject: [PATCH 3/8] Address review feedback on the per-turn tracer + benchmark harness MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Benchmark runner (internal/perfbench): - A nonzero agent exit code no longer counts as Passed. The runner set VerifyErr but then fell through to outcome.Passed = true, so a crashed run could be recorded as a pass. Return before the verification block when VerifyErr is already set. - A task now passes only when every iteration passes. The previous "any iteration passes" rule let a flaky fail hide behind one good run. - Each invocation copies its workspace fixture to a fresh temp dir and runs the agent + verifier there, so mutating tasks (edit/fix/refactor) can't dirty the checked-in fixtures or bleed into the next iteration. - Trace load failures (missing/malformed trace file) are surfaced as result warnings via a new TraceIssue field instead of being swallowed. Tracer (internal/trace): - Finish freezes the recorder: Counter, addSpan, and the first-event stamps are dropped after Finish returns, so a snapshot captures exactly one turn and late stamps can't mutate it. - WriteText propagates the first write error instead of silently swallowing sink failures. Provider seam (internal/providers/providerio): - FirstTokenAt is stamped only after a payload is accepted as real model output, not before handle() decides to drop it as an error payload. Agent loop (internal/agent): - The compaction counter increments only when the history actually shrinks, in both the proactive and reactive paths — paid no-ops no longer inflate the compaction total. - Document on Options.Trace that a fresh Recorder is required per Run. CLI (internal/cli/exec): - Finish the trace at the agent.Run boundary and defer only the serialization, so the snapshot covers exactly the turn. - Reject --trace / ZERO_TRACE for spec-draft runs with a clear error instead of silently accepting and writing nothing. Manifest + fixtures: - Strengthen the edit verifiers: rename and value-bump tasks now assert the old symbol is gone, and the getter task greps the method signature. - Add the missing testdata/edit fixture (10 edit tasks referenced a directory that was never committed, so the whole edit class errored out at run time). - The manifest test now stats each fixture so a missing dir fails at load time instead of at every run. - longproc benchmark keeps Process live across the loop; README code fence gets a language tag and documents the per-invocation fixture copy. - Add tests for the tracing wrapper (nil vs wired recorder, OnUsage forwarding, token aggregation) and the frozen-recorder contract. --- internal/agent/compaction.go | 18 ++-- internal/agent/loop_test.go | 64 ++++++++++++ internal/agent/types.go | 3 + internal/cli/exec.go | 41 +++++--- internal/perfbench/manifests/baseline.json | 8 +- internal/perfbench/reports/README.md | 7 +- internal/perfbench/testdata/edit/main.go | 42 ++++++++ internal/perfbench/testdata/edit/version.go | 4 + .../perfbench/testdata/longproc/main_test.go | 8 +- internal/perfbench/turn_bench.go | 99 +++++++++++++++++-- internal/perfbench/turn_bench_test.go | 18 +++- internal/providers/providerio/providerio.go | 9 +- internal/trace/emit.go | 45 ++++++--- internal/trace/recorder.go | 12 ++- internal/trace/trace_test.go | 57 +++++++++++ 15 files changed, 379 insertions(+), 56 deletions(-) create mode 100644 internal/perfbench/testdata/edit/main.go create mode 100644 internal/perfbench/testdata/edit/version.go diff --git a/internal/agent/compaction.go b/internal/agent/compaction.go index 7c87c16a4..a2896fcdb 100644 --- a/internal/agent/compaction.go +++ b/internal/agent/compaction.go @@ -419,9 +419,6 @@ func (state *compactionState) maybeCompact( PreserveLast: state.preserveLast, Summarize: summarizeClosure(ctx, provider, state.onUsage), }) - if r := trace.FromContext(ctx); r != nil && err == nil { - r.Counter(trace.CounterCompactionCount, 1) - } if err != nil { // Summarizer failed: keep the original history. The reactive path (or a // later turn) can try again; we never drop messages on failure here. @@ -434,6 +431,12 @@ func (state *compactionState) maybeCompact( state.lowWaterMark = size return messages } + // Only count a compaction when it actually shrank the history, so the + // compaction counter reflects real context reductions rather than paid + // no-ops that left the token budget untouched. + if r := trace.FromContext(ctx); r != nil { + r.Counter(trace.CounterCompactionCount, 1) + } state.lowWaterMark = newSize return compacted } @@ -466,9 +469,6 @@ func (state *compactionState) recover( PreserveLast: state.preserveLast, Summarize: summarizeClosure(ctx, provider, state.onUsage), }) - if r := trace.FromContext(ctx); r != nil && compactErr == nil { - r.Counter(trace.CounterCompactionCount, 1) - } if compactErr != nil { // A genuine compaction attempt was made (and failed): the budget is spent // so the loop gives up rather than retrying a failing summarizer forever. @@ -486,7 +486,11 @@ func (state *compactionState) recover( // one-shot budget now so a provider that keeps returning context-limit errors // after a successful compaction can't loop forever. Store the low-water mark in // the SAME combined (messages + tool-defs) domain maybeCompact uses, so the - // proactive shrink-guard compares like with like. + // proactive shrink-guard compares like with like. Count it now that the shrink + // is confirmed, so the counter mirrors maybeCompact's real-reduction policy. + if r := trace.FromContext(ctx); r != nil { + r.Counter(trace.CounterCompactionCount, 1) + } state.reactiveAttempted = true state.lowWaterMark = state.calibratedTokens(estimateTokens(result) + estimateToolDefTokens(tools)) return result, true, nil diff --git a/internal/agent/loop_test.go b/internal/agent/loop_test.go index 97647258b..1462078e2 100644 --- a/internal/agent/loop_test.go +++ b/internal/agent/loop_test.go @@ -15,6 +15,7 @@ import ( "github.com/Gitlawb/zero/internal/sandbox" "github.com/Gitlawb/zero/internal/specmode" "github.com/Gitlawb/zero/internal/tools" + "github.com/Gitlawb/zero/internal/trace" "github.com/Gitlawb/zero/internal/zeroruntime" ) @@ -3461,3 +3462,66 @@ func TestRunDoesNotFlagCleanToolOutput(t *testing.T) { t.Errorf("clean output should not get a reminder, got %q", captured.Output) } } + +// TestRunTracingWrapperStampsUsage verifies the per-turn tracing setup in Run: +// a wired recorder is Started, OnUsage is wrapped so it still forwards to the +// caller's callback AND stamps token counters, and the run completes. +func TestRunTracingWrapperStampsUsage(t *testing.T) { + provider := &mockProvider{turns: [][]zeroruntime.StreamEvent{{ + {Type: zeroruntime.StreamEventUsage, Usage: zeroruntime.Usage{InputTokens: 100, CachedInputTokens: 20, OutputTokens: 40}}, + {Type: zeroruntime.StreamEventText, Content: "done"}, + {Type: zeroruntime.StreamEventDone}, + }}} + onUsageCalls := 0 + rec := trace.NewRecorder("tracing-session", "run-1", "test") + if _, err := Run(context.Background(), "hi", provider, Options{ + SessionID: "tracing-session", + Cwd: t.TempDir(), + ProviderName: "test-provider", + Model: "test-model", + Trace: rec, + OnUsage: func(Usage) { onUsageCalls++ }, + }); err != nil { + t.Fatalf("Run: %v", err) + } + tr := rec.Finish() + if tr.StartedAt.IsZero() { + t.Fatal("tracing wrapper did not Start the recorder") + } + if got := tr.Counter(trace.CounterInputTokens); got != 100 { + t.Fatalf("input token counter = %d, want 100", got) + } + if got := tr.Counter(trace.CounterCachedInputTokens); got != 20 { + t.Fatalf("cached input token counter = %d, want 20", got) + } + if got := tr.Counter(trace.CounterOutputTokens); got != 40 { + t.Fatalf("output token counter = %d, want 40", got) + } + if onUsageCalls == 0 { + t.Fatal("wrapped OnUsage did not forward to the caller's callback") + } +} + +// TestRunNilTraceForwardsUsage verifies a nil recorder leaves the loop +// byte-identical: OnUsage is not wrapped, so the caller's callback still fires +// and nothing panics. +func TestRunNilTraceForwardsUsage(t *testing.T) { + provider := &mockProvider{turns: [][]zeroruntime.StreamEvent{{ + {Type: zeroruntime.StreamEventUsage, Usage: zeroruntime.Usage{InputTokens: 7}}, + {Type: zeroruntime.StreamEventText, Content: "done"}, + {Type: zeroruntime.StreamEventDone}, + }}} + onUsageCalls := 0 + if _, err := Run(context.Background(), "hi", provider, Options{ + SessionID: "nil-trace-session", + Cwd: t.TempDir(), + ProviderName: "test-provider", + Model: "test-model", + OnUsage: func(Usage) { onUsageCalls++ }, + }); err != nil { + t.Fatalf("Run: %v", err) + } + if onUsageCalls == 0 { + t.Fatal("OnUsage not forwarded when Trace is nil") + } +} diff --git a/internal/agent/types.go b/internal/agent/types.go index a65f01281..465d4a0fd 100644 --- a/internal/agent/types.go +++ b/internal/agent/types.go @@ -286,6 +286,9 @@ type Options struct { // retries, tokens) into it. nil DISABLES tracing entirely — every stamp is // nil-safe and the loop is byte-identical to an untraced run. The caller // owns the recorder: Run stamps into it but does not Finish or emit it. + // A fresh Recorder is required per Run — reusing one across runs merges + // their spans, counters, and first-event timestamps, and Finish freezes a + // recorder so no further stamps take. Trace *trace.Recorder // SelfCorrect, when set, runs a post-edit verify-and-correct cycle after a // mutating tool call: it verifies the changed files (LSP diagnostics + project diff --git a/internal/cli/exec.go b/internal/cli/exec.go index 99ef6306e..cddefadb5 100644 --- a/internal/cli/exec.go +++ b/internal/cli/exec.go @@ -429,6 +429,12 @@ func runExec(args []string, stdout io.Writer, stderr io.Writer, deps appDeps) in notify.MaybeAddWebhookSink(notifier, os.Getenv, func(format string, args ...any) { fmt.Fprintf(stderr, "[notify] "+format+"\n", args...) }) + // Spec-draft runs synthesize a prompt offline and never drive a model turn, so + // there is no per-turn trace to emit. Reject --trace / ZERO_TRACE up front with + // a clear error rather than silently accepting and writing nothing. + if options.useSpec && resolveTracePath(options) != "" { + return writeExecFormatUsageError(stdout, stderr, options.outputFormat, "--trace / ZERO_TRACE are not supported for spec-draft runs") + } if options.useSpec { return runExecSpecDraft(execSpecDraftRun{ options: options, @@ -483,15 +489,18 @@ func runExec(args []string, stdout io.Writer, stderr io.Writer, deps appDeps) in } // Per-turn tracing is opt-in (--trace or ZERO_TRACE=). The // recorder is stamped throughout agent.Run and the providerio seam; the run - // itself is byte-identical to an untraced run. We finish + emit on every exit - // path via the defer below. "-" writes NDJSON to stderr; otherwise the path - // is created/truncated. A failure to emit is logged to stderr, never fatal. + // itself is byte-identical to an untraced run. We finish the recorder at the + // agent.Run boundary (below) so the snapshot captures exactly one turn, then + // serialize the snapshot on every exit path via the defer. "-" writes NDJSON + // to stderr; otherwise the path is created/truncated. A failure to emit is + // logged to stderr, never fatal. tracePath := resolveTracePath(options) var traceRecorder *trace.Recorder + var traceSnapshot *trace.TurnTrace if tracePath != "" { traceRecorder = trace.NewRecorder(preparedSession.Session.SessionID, runID, "") defer func() { - if err := emitTrace(traceRecorder, tracePath, stderr); err != nil { + if err := writeTraceSnapshot(traceSnapshot, tracePath, stderr); err != nil { fmt.Fprintf(stderr, "[zero] failed to write trace: %s\n", err) } }() @@ -648,6 +657,12 @@ func runExec(args []string, stdout io.Writer, stderr io.Writer, deps appDeps) in sessionRecorder.append(sessions.EventUsage, payload) }, }) + // Finish the trace now that the turn is done, so the snapshot captures exactly + // agent.Run's work and nothing the post-run cleanup stamps. The deferred + // writer serializes the snapshot on every exit path. + if traceRecorder != nil { + traceSnapshot = traceRecorder.Finish() + } notifier.Notify(notify.Completion, notify.DefaultMessage(notify.Completion)) if writer.err != nil { return exitCrash @@ -1274,22 +1289,22 @@ func resolveTracePath(options execOptions) string { return "" } -// emitTrace finishes the recorder and writes the NDJSON trace to dest ("-" => -// stderr, otherwise a file path created/truncated). A nil recorder is a no-op -// (tracing off). The trace is best-effort: a write error is returned to the -// caller, which logs it but never fails the run. -func emitTrace(recorder *trace.Recorder, dest string, stderr io.Writer) error { - if recorder == nil || dest == "" { +// writeTraceSnapshot writes an already-finished trace snapshot to dest ("-" => +// stderr, otherwise a file path created/truncated). A nil snapshot is a no-op +// (tracing off, or the run exited before agent.Run produced a turn). The trace +// is best-effort: a write error is returned to the caller, which logs it but +// never fails the run. +func writeTraceSnapshot(snapshot *trace.TurnTrace, dest string, stderr io.Writer) error { + if snapshot == nil || dest == "" { return nil } - finished := recorder.Finish() if strings.TrimSpace(dest) == "-" { - return trace.WriteNDJSON(stderr, finished) + return trace.WriteNDJSON(stderr, snapshot) } file, err := os.Create(dest) if err != nil { return err } defer file.Close() - return trace.WriteNDJSON(file, finished) + return trace.WriteNDJSON(file, snapshot) } diff --git a/internal/perfbench/manifests/baseline.json b/internal/perfbench/manifests/baseline.json index 9848a698a..aa147a42f 100644 --- a/internal/perfbench/manifests/baseline.json +++ b/internal/perfbench/manifests/baseline.json @@ -13,14 +13,14 @@ {"id": "nav-09", "name": "report config", "class": "nav", "prompt": "Read config.json and report the keys it contains. Do not modify anything.", "workspaceFixture": "../testdata/nav"}, {"id": "nav-10", "name": "doc lookup", "class": "nav", "prompt": "Find the doc comment on the greet function and quote it. Do not modify anything.", "workspaceFixture": "../testdata/nav"}, - {"id": "edit-01", "name": "rename a constant", "class": "edit", "prompt": "Rename the constant MaxRetries to RetryLimit everywhere it appears.", "workspaceFixture": "../testdata/edit", "verificationCommand": ["grep", "-R", "RetryLimit", "."]}, + {"id": "edit-01", "name": "rename a constant", "class": "edit", "prompt": "Rename the constant MaxRetries to RetryLimit everywhere it appears.", "workspaceFixture": "../testdata/edit", "verificationCommand": ["bash", "-c", "grep -R RetryLimit . && ! grep -R MaxRetries ."]}, {"id": "edit-02", "name": "fix a typo", "class": "edit", "prompt": "Fix the typo in the comment above the greet function ('receieves' should be 'receives').", "workspaceFixture": "../testdata/edit", "verificationCommand": ["bash", "-c", "! grep -R receieves ."]}, {"id": "edit-03", "name": "add a field", "class": "edit", "prompt": "Add a string field named Label to the Config struct in main.go.", "workspaceFixture": "../testdata/edit", "verificationCommand": ["grep", "-R", "Label", "."]}, - {"id": "edit-04", "name": "bump a version", "class": "edit", "prompt": "Change the version string in version.go from 1.0.0 to 1.1.0.", "workspaceFixture": "../testdata/edit", "verificationCommand": ["grep", "-R", "1.1.0", "."]}, + {"id": "edit-04", "name": "bump a version", "class": "edit", "prompt": "Change the version string in version.go from 1.0.0 to 1.1.0.", "workspaceFixture": "../testdata/edit", "verificationCommand": ["bash", "-c", "grep -R 1.1.0 . && ! grep -R 1.0.0 ."]}, {"id": "edit-05", "name": "remove a log line", "class": "edit", "prompt": "Remove the line that prints 'debug: starting'.", "workspaceFixture": "../testdata/edit", "verificationCommand": ["bash", "-c", "! grep -R 'debug: starting' ."]}, {"id": "edit-06", "name": "add a license header", "class": "edit", "prompt": "Add a comment line '// SPDX-License-Identifier: MIT' at the top of main.go.", "workspaceFixture": "../testdata/edit", "verificationCommand": ["grep", "-R", "SPDX-License-Identifier", "."]}, - {"id": "edit-07", "name": "change a default", "class": "edit", "prompt": "Change the default value of the Port constant from 8080 to 9090.", "workspaceFixture": "../testdata/edit", "verificationCommand": ["grep", "-R", "9090", "."]}, - {"id": "edit-08", "name": "add a getter", "class": "edit", "prompt": "Add a method func (c *Config) GetLabel() string that returns c.Label.", "workspaceFixture": "../testdata/edit", "verificationCommand": ["grep", "-R", "GetLabel", "."]}, + {"id": "edit-07", "name": "change a default", "class": "edit", "prompt": "Change the default value of the Port constant from 8080 to 9090.", "workspaceFixture": "../testdata/edit", "verificationCommand": ["bash", "-c", "grep -R 9090 . && ! grep -R 8080 ."]}, + {"id": "edit-08", "name": "add a getter", "class": "edit", "prompt": "Add a method func (c *Config) GetLabel() string that returns c.Label.", "workspaceFixture": "../testdata/edit", "verificationCommand": ["bash", "-c", "grep -R 'func (c *Config) GetLabel' ."]}, {"id": "edit-09", "name": "wrap an error", "class": "edit", "prompt": "In the load function, wrap the returned error with fmt.Errorf so it includes 'load failed'.", "workspaceFixture": "../testdata/edit", "verificationCommand": ["grep", "-R", "load failed", "."]}, {"id": "edit-10", "name": "update a message", "class": "edit", "prompt": "Change the printed greeting from 'hello' to 'hello, world'.", "workspaceFixture": "../testdata/edit", "verificationCommand": ["grep", "-R", "hello, world", "."]}, diff --git a/internal/perfbench/reports/README.md b/internal/perfbench/reports/README.md index b33f491cf..88ef55744 100644 --- a/internal/perfbench/reports/README.md +++ b/internal/perfbench/reports/README.md @@ -8,7 +8,7 @@ model-specific, so a single snapshot here would mislead rather than inform. Run the harness over the checked-in manifest: -``` +```sh make baseline ZERO_BENCH_MODEL= # uses ./zero make baseline ZERO_BENCH_MODEL= ZERO_BENCH_BINARY=/path/to/zero ``` @@ -36,5 +36,6 @@ expectation. `.gitkeep` keeps the directory present between runs. - Each task is a fresh `zero exec` process, so iterations are **cold-start** samples. A warm path (reusing an in-process agent) is future work. -- Mutating tasks (edit/fix/refactor) modify their fixture in place; repeatable - runs reset the fixtures from a clean checkout first. \ No newline at end of file +- Mutating tasks (edit/fix/refactor) run against a per-invocation **copy** of + their fixture, so the checked-in fixtures stay clean and one task's edits + can't bleed into the next iteration. \ No newline at end of file diff --git a/internal/perfbench/testdata/edit/main.go b/internal/perfbench/testdata/edit/main.go new file mode 100644 index 000000000..f3c3d5684 --- /dev/null +++ b/internal/perfbench/testdata/edit/main.go @@ -0,0 +1,42 @@ +// Package edit is a small workspace for the edit-class benchmark tasks: each +// task asks the agent to make one targeted edit, verified by a grep/build +// command in the manifest. +package edit + +import ( + "fmt" + "os" +) + +// Port is the default listen port. +const Port = 8080 + +// MaxRetries is the maximum number of retries before giving up. +const MaxRetries = 3 + +// Config holds runtime configuration. +type Config struct { + Name string +} + +// greet returns a greeting for the named user. +// +// This receieves a name and formats a hello message. +func greet(name string) string { + return "hello" +} + +// load reads a config file and returns its bytes, or an error on failure. +func load(path string) ([]byte, error) { + data, err := os.ReadFile(path) + if err != nil { + return nil, err + } + return data, nil +} + +func main() { + fmt.Println("debug: starting") + cfg := Config{Name: "demo"} + fmt.Println(greet(cfg.Name)) +} diff --git a/internal/perfbench/testdata/edit/version.go b/internal/perfbench/testdata/edit/version.go new file mode 100644 index 000000000..f6bc60ed2 --- /dev/null +++ b/internal/perfbench/testdata/edit/version.go @@ -0,0 +1,4 @@ +package edit + +// Version is the build version string. +const Version = "1.0.0" diff --git a/internal/perfbench/testdata/longproc/main_test.go b/internal/perfbench/testdata/longproc/main_test.go index 1443d94a3..10f8697ec 100644 --- a/internal/perfbench/testdata/longproc/main_test.go +++ b/internal/perfbench/testdata/longproc/main_test.go @@ -2,6 +2,10 @@ package longproc import "testing" +// benchSink keeps Process(100) live across the benchmark loop so the compiler +// can't optimize the call away and report an unrealistically fast benchmark. +var benchSink int + func TestProcess(t *testing.T) { if got := Process(100); got != 4950 { t.Fatalf("Process(100) = %d, want 4950", got) @@ -9,7 +13,9 @@ func TestProcess(t *testing.T) { } func BenchmarkProcess(b *testing.B) { + var sink int for i := 0; i < b.N; i++ { - Process(100) + sink = Process(100) } + benchSink = sink } diff --git a/internal/perfbench/turn_bench.go b/internal/perfbench/turn_bench.go index c60d20056..4ece5cab6 100644 --- a/internal/perfbench/turn_bench.go +++ b/internal/perfbench/turn_bench.go @@ -7,6 +7,7 @@ import ( "errors" "fmt" "io" + "io/fs" "os" "os/exec" "path/filepath" @@ -33,7 +34,12 @@ type TurnTaskOutcome struct { VerifyErr string WallMs float64 Trace *trace.TurnTrace - Err error + // TraceIssue, when non-empty, explains why the per-turn trace could not be + // parsed (file missing or malformed). The run still has a pass/fail verdict, + // but an incomplete measurement is surfaced as a result warning so it can't + // masquerade as a clean attribution sample. + TraceIssue string + Err error } // TurnBenchConfig configures a turn-benchmark run. @@ -166,14 +172,24 @@ func RunTurnBench(ctx context.Context, set TaskSet, cfg TurnBenchConfig) (TurnBe class = "default" } classTasks[class]++ - passedForTask := false + // A task counts as passed only when every iteration passed. The per-process + // runner is cold-start, so a flaky pass on one iteration and a fail on + // another is a real regression signal, not noise to average away. + passedForTask := true for iter := 0; iter < iterations; iter++ { outcome := cfg.Runner(ctx, task, rc) + if outcome.TraceIssue != "" { + result.Warnings = append(result.Warnings, Warning{ + Metric: "trace", + Message: fmt.Sprintf("task %s: %s", task.ID, outcome.TraceIssue), + }) + } if outcome.Err != nil { + passedForTask = false continue } - if outcome.Passed { - passedForTask = true + if !outcome.Passed { + passedForTask = false } wall := outcome.WallMs if wall <= 0 && outcome.Trace != nil { @@ -334,6 +350,19 @@ func WriteTurnBenchJSON(w io.Writer, result TurnBenchResult) error { // VerificationCommand when present), exactly like NewExecRunner. func NewTurnExecRunner(binary string, extraArgs ...string) TurnRunner { return func(ctx context.Context, task BenchTask, rc RunContext) TurnTaskOutcome { + // Isolate the workspace: copy the fixture into a fresh temp dir so a + // mutating task (edit/fix/refactor) can't dirty the shared, checked-in + // fixture or bleed into a later iteration of the same task. When no + // fixture is configured the agent runs in the caller's cwd as before. + if fixture := strings.TrimSpace(task.WorkspaceFixture); fixture != "" { + copyDir, cerr := copyFixture(fixture) + if cerr != nil { + return TurnTaskOutcome{Err: fmt.Errorf("isolate fixture: %w", cerr)} + } + defer os.RemoveAll(copyDir) + task.WorkspaceFixture = copyDir + } + traceFile, err := os.CreateTemp("", "zero-turn-trace-*.ndjson") if err != nil { return TurnTaskOutcome{Err: fmt.Errorf("create trace file: %w", err)} @@ -369,15 +398,26 @@ func NewTurnExecRunner(binary string, extraArgs ...string) TurnRunner { return outcome } - // Parse the captured trace (best-effort: a missing/empty file is not fatal — - // the run still produced a pass/fail; the trace is the attribution layer). - if f, ferr := os.Open(tracePath); ferr == nil { - if tr, perr := trace.ReadNDJSON(f); perr == nil { + // Parse the captured trace. The trace is the attribution layer, so a + // missing/malformed file is not fatal — but it IS surfaced as a warning + // (via outcome.TraceIssue) so an incomplete measurement can't look valid. + if f, ferr := os.Open(tracePath); ferr != nil { + outcome.TraceIssue = fmt.Sprintf("trace open failed: %v", ferr) + } else { + tr, perr := trace.ReadNDJSON(f) + _ = f.Close() + if perr != nil { + outcome.TraceIssue = fmt.Sprintf("trace parse failed: %v", perr) + } else { outcome.Trace = tr } - _ = f.Close() } + // A nonzero agent exit already decided failure; don't run verification or + // mark the task passed. + if outcome.VerifyErr != "" { + return outcome + } if len(task.VerificationCommand) > 0 { if vOutcome := runVerification(ctx, task); !vOutcome.Passed { outcome.VerifyErr = strings.TrimSpace(vOutcome.Detail) @@ -389,6 +429,47 @@ func NewTurnExecRunner(binary string, extraArgs ...string) TurnRunner { } } +// copyFixture copies the fixture directory at src into a fresh temp dir and +// returns the copy's path. Used to give each benchmark invocation an isolated +// workspace so mutating tasks (edit/fix/refactor) can't dirty the checked-in +// fixture or a later iteration. +func copyFixture(src string) (string, error) { + info, err := os.Stat(src) + if err != nil { + return "", err + } + if !info.IsDir() { + return "", fmt.Errorf("fixture %q is not a directory", src) + } + dst, err := os.MkdirTemp("", "zero-turn-fixture-*") + if err != nil { + return "", err + } + err = filepath.WalkDir(src, func(path string, d fs.DirEntry, werr error) error { + if werr != nil { + return werr + } + rel, rerr := filepath.Rel(src, path) + if rerr != nil { + return rerr + } + target := filepath.Join(dst, rel) + if d.IsDir() { + return os.MkdirAll(target, 0o755) + } + data, rerr := os.ReadFile(path) + if rerr != nil { + return rerr + } + return os.WriteFile(target, data, 0o644) + }) + if err != nil { + os.RemoveAll(dst) + return "", err + } + return dst, nil +} + func buildTurnExecArgs(task BenchTask, rc RunContext, tracePath string, extraArgs []string) []string { args := []string{"exec", "--output-format", "stream-json", "--trace", tracePath} if model := strings.TrimSpace(rc.Model); model != "" { diff --git a/internal/perfbench/turn_bench_test.go b/internal/perfbench/turn_bench_test.go index 6afb7a548..53275fce7 100644 --- a/internal/perfbench/turn_bench_test.go +++ b/internal/perfbench/turn_bench_test.go @@ -4,6 +4,7 @@ import ( "bytes" "context" "encoding/json" + "os" "path/filepath" "strings" "testing" @@ -279,7 +280,11 @@ func TestLoadBaselineManifest(t *testing.T) { t.Fatalf("class %q has zero tasks", class) } } - // Every task must have a prompt and a workspace fixture pointing under testdata. + // Every task must have a prompt and a workspace fixture pointing under testdata, + // and that fixture must actually exist on disk — a manifest referencing a + // missing fixture would make every task in its class error out at run time, so + // catch it at load time instead. + seen := map[string]bool{} for _, task := range set.Tasks { if strings.TrimSpace(task.Prompt) == "" { t.Fatalf("task %q has empty prompt", task.ID) @@ -290,6 +295,17 @@ func TestLoadBaselineManifest(t *testing.T) { if !strings.Contains(task.WorkspaceFixture, "testdata") { t.Fatalf("task %q fixture %q not under testdata", task.ID, task.WorkspaceFixture) } + if seen[task.WorkspaceFixture] { + continue + } + seen[task.WorkspaceFixture] = true + info, err := os.Stat(task.WorkspaceFixture) + if err != nil { + t.Fatalf("task %q fixture %q does not exist: %v", task.ID, task.WorkspaceFixture, err) + } + if !info.IsDir() { + t.Fatalf("task %q fixture %q is not a directory", task.ID, task.WorkspaceFixture) + } } } diff --git a/internal/providers/providerio/providerio.go b/internal/providers/providerio/providerio.go index fe017c525..374269f65 100644 --- a/internal/providers/providerio/providerio.go +++ b/internal/providers/providerio/providerio.go @@ -367,17 +367,20 @@ func ScanSSEDataWithContext( // NOT output, so it must not reset the content watchdog. continue } - // First non-keepalive payload = first model output. Stamp once; later - // real payloads are no-ops. nil recorder (untraced run) is a no-op. - trace.FromContext(ctx).StampFirstToken() resetContent() if !handle(item.data) { // The provider asked to stop (e.g. it already emitted an error // for this payload). Abort the read and end like ScanSSEData: // return nil so callers fall through to their post-scan checks. + // Do not stamp FirstToken — this payload was not accepted model + // output, so counting it as first-token time would be misleading. cancel() return nil } + // First accepted non-keepalive payload = first real model output. Stamp + // once; later real payloads are no-ops. nil recorder (untraced run) is a + // no-op. + trace.FromContext(ctx).StampFirstToken() } } } diff --git a/internal/trace/emit.go b/internal/trace/emit.go index 22ed94405..8b6c7beef 100644 --- a/internal/trace/emit.go +++ b/internal/trace/emit.go @@ -78,43 +78,64 @@ func WriteNDJSON(w io.Writer, t *TurnTrace) error { } // WriteText emits a human-readable trace: a header, one line per span with its -// share of wall time, a totals line, then counters. +// share of wall time, a totals line, then counters. The first write error is +// returned; remaining writes are skipped so a failing sink surfaces promptly +// instead of being silently dropped. func WriteText(w io.Writer, t *TurnTrace) error { if w == nil || t == nil { return nil } wall := t.WallDuration() - fmt.Fprintf(w, "trace run=%s session=%s profile=%s\n", t.RunID, t.SessionID, t.Profile) - fmt.Fprintf(w, " started=%s completed=%s wall=%s\n", formatTime(t.StartedAt), formatTime(t.CompletedAt), wall) + var p textPrinter + p.printf(w, "trace run=%s session=%s profile=%s\n", t.RunID, t.SessionID, t.Profile) + p.printf(w, " started=%s completed=%s wall=%s\n", formatTime(t.StartedAt), formatTime(t.CompletedAt), wall) if !t.FirstVisibleEventAt.IsZero() { - fmt.Fprintf(w, " first_visible_event=%s (+%s)\n", formatTime(t.FirstVisibleEventAt), t.FirstVisibleEventAt.Sub(t.StartedAt)) + p.printf(w, " first_visible_event=%s (+%s)\n", formatTime(t.FirstVisibleEventAt), t.FirstVisibleEventAt.Sub(t.StartedAt)) } if !t.FirstUsefulActionAt.IsZero() { - fmt.Fprintf(w, " first_useful_action=%s (+%s)\n", formatTime(t.FirstUsefulActionAt), t.FirstUsefulActionAt.Sub(t.StartedAt)) + p.printf(w, " first_useful_action=%s (+%s)\n", formatTime(t.FirstUsefulActionAt), t.FirstUsefulActionAt.Sub(t.StartedAt)) } if !t.FirstTokenAt.IsZero() { - fmt.Fprintf(w, " first_token=%s (+%s)\n", formatTime(t.FirstTokenAt), t.FirstTokenAt.Sub(t.StartedAt)) + p.printf(w, " first_token=%s (+%s)\n", formatTime(t.FirstTokenAt), t.FirstTokenAt.Sub(t.StartedAt)) } spans := append([]Span(nil), t.Spans...) sort.Slice(spans, func(i, j int) bool { return spans[i].Name < spans[j].Name }) - fmt.Fprintln(w, "spans:") + p.println(w, "spans:") for _, span := range spans { share := 0.0 if wall > 0 { share = float64(span.Duration) / float64(wall) } - fmt.Fprintf(w, " %-18s %10s %5.1f%%\n", span.Name, span.Duration, share*100) + p.printf(w, " %-18s %10s %5.1f%%\n", span.Name, span.Duration, share*100) } - fmt.Fprintf(w, " %-18s %10s %5.1f%%\n", "attributed", t.AttributedDuration(), t.AttributionRatio()*100) + p.printf(w, " %-18s %10s %5.1f%%\n", "attributed", t.AttributedDuration(), t.AttributionRatio()*100) counters := append([]Counter(nil), t.Counters...) sort.Slice(counters, func(i, j int) bool { return counters[i].Name < counters[j].Name }) - fmt.Fprintln(w, "counters:") + p.println(w, "counters:") for _, c := range counters { - fmt.Fprintf(w, " %-22s %d\n", c.Name, c.Value) + p.printf(w, " %-22s %d\n", c.Name, c.Value) } - return nil + return p.err +} + +// textPrinter remembers the first write error so a stream of fprintf/fprintln +// calls can short-circuit after the sink fails, then report it once. +type textPrinter struct{ err error } + +func (p *textPrinter) printf(w io.Writer, format string, args ...any) { + if p.err != nil { + return + } + _, p.err = fmt.Fprintf(w, format, args...) +} + +func (p *textPrinter) println(w io.Writer, s string) { + if p.err != nil { + return + } + _, p.err = fmt.Fprintln(w, s) } // NDJSONSink adapts an io.Writer as a Sink emitting NDJSON. diff --git a/internal/trace/recorder.go b/internal/trace/recorder.go index 3a9fa0509..25c33889c 100644 --- a/internal/trace/recorder.go +++ b/internal/trace/recorder.go @@ -96,6 +96,9 @@ func (r *Recorder) Counter(name string, n int64) { } r.mu.Lock() defer r.mu.Unlock() + if r.finished { + return + } r.addCounterLocked(name, n) } @@ -107,7 +110,7 @@ func (r *Recorder) StampFirstToken() { } r.mu.Lock() defer r.mu.Unlock() - if r.firstTokenStamped { + if r.finished || r.firstTokenStamped { return } r.firstTokenStamped = true @@ -122,7 +125,7 @@ func (r *Recorder) StampFirstVisibleEvent() { } r.mu.Lock() defer r.mu.Unlock() - if r.firstVisibleStamped { + if r.finished || r.firstVisibleStamped { return } r.firstVisibleStamped = true @@ -137,7 +140,7 @@ func (r *Recorder) StampFirstUsefulAction() { } r.mu.Lock() defer r.mu.Unlock() - if r.firstActionStamped { + if r.finished || r.firstActionStamped { return } r.firstActionStamped = true @@ -167,6 +170,9 @@ func (r *Recorder) Finish() *TurnTrace { func (r *Recorder) addSpan(name string, d time.Duration) { r.mu.Lock() defer r.mu.Unlock() + if r.finished { + return + } for i := range r.tr.Spans { if r.tr.Spans[i].Name == name { r.tr.Spans[i].Duration += d diff --git a/internal/trace/trace_test.go b/internal/trace/trace_test.go index be3156c30..88f30bced 100644 --- a/internal/trace/trace_test.go +++ b/internal/trace/trace_test.go @@ -4,6 +4,7 @@ import ( "bytes" "context" "encoding/json" + "errors" "strings" "sync" "testing" @@ -68,6 +69,47 @@ func TestFinishSnapshotIsCopy(t *testing.T) { } } +func TestFinishFreezesState(t *testing.T) { + // Once Finish returns a snapshot, the recorder is frozen: later stamps must + // not mutate its state, so a second Finish yields the same trace. + r := NewRecorder("s", "r", "") + r.Start() + r.Counter(CounterToolCalls, 2) + r.RecordSpan(SpanGeneration, 5*time.Millisecond) + r.StampFirstToken() + first := r.Finish() + + // Post-finish stamps of every kind must be dropped. + r.Counter(CounterToolCalls, 100) + r.RecordSpan(SpanGeneration, 100*time.Millisecond) + r.StampFirstToken() + r.StampFirstVisibleEvent() + r.StampFirstUsefulAction() + s := r.Span(SpanToolExecution) + time.Sleep(time.Millisecond) + s.End() + + second := r.Finish() + if got := second.Counter(CounterToolCalls); got != 2 { + t.Fatalf("post-finish Counter leaked into snapshot: got %d, want 2", got) + } + if got := second.Span(SpanGeneration); got != 5*time.Millisecond { + t.Fatalf("post-finish RecordSpan leaked into snapshot: got %v, want 5ms", got) + } + if got := second.Span(SpanToolExecution); got != 0 { + t.Fatalf("post-finish Span leaked into snapshot: got %v, want 0", got) + } + if second.FirstTokenAt != first.FirstTokenAt { + t.Fatalf("post-finish StampFirstToken moved timestamp") + } + if !second.FirstVisibleEventAt.IsZero() { + t.Fatalf("post-finish StampFirstVisibleEvent leaked into snapshot") + } + if !second.FirstUsefulActionAt.IsZero() { + t.Fatalf("post-finish StampFirstUsefulAction leaked into snapshot") + } +} + func TestNilRecorderIsNoOp(t *testing.T) { var r *Recorder r.Start() @@ -201,6 +243,21 @@ func TestWriteTextIsReadable(t *testing.T) { } } +func TestWriteTextPropagatesWriteError(t *testing.T) { + r := NewRecorder("s", "r", "") + r.Start() + r.RecordSpan(SpanGeneration, 42*time.Millisecond) + r.Counter(CounterToolCalls, 7) + tr := r.Finish() + if err := WriteText(errWriter{}, tr); err == nil { + t.Fatal("WriteText to a failing sink returned nil; want the write error") + } +} + +type errWriter struct{} + +func (errWriter) Write(p []byte) (int, error) { return 0, errors.New("write failed") } + func TestAttributionRatio(t *testing.T) { r := NewRecorder("s", "r", "") r.Start() From 0f372f38446954dcf159455d5a5cc04470e9e8e0 Mon Sep 17 00:00:00 2001 From: Vasanthdev2004 Date: Thu, 16 Jul 2026 13:36:32 +0530 Subject: [PATCH 4/8] Address review feedback: exclusive-time attribution + wired spans + fix-suite compile Rewrite the trace attribution model so concurrent/nested spans no longer double-count. Spans record wall intervals; the recorder derives a parent for each by interval containment and computes exclusive time (duration minus the union of its children). AttributedDuration sums only top-level spans; Coverage is the union of intervals over wall, capped at 1, the honest ">=95%" metric. Top-latency ranking uses exclusive time so shares sum to ~1 instead of being inflated by overlapping provider_connect/generation and nested permission_wait/tool_execution. Wire the spans that were named but never stamped: verification around the self-correct verify pass, and StampFirstVisibleEvent on the first forwarded text event. Drop the tool_queue/process_wait/persistence constants that had no stamps, and rename the misnamed near-noise prompt_build span to tool_partition. Trim RequiredEventKeys to events a healthy short run actually emits; move conditional phases (tools, permission, compaction, verification) to OptionalEventKeys so a short trace does not false-fail. Make ReadNDJSON fail loudly on a corrupt file: require a type:trace header, error on span/counter lines that appear before it, and error when a header yields no spans or counters. Fix the blocking fix-suite compile error: Label's %d format verb on a string tripped go test's vet before any fix task could verify. Make it a runtime wrong-prefix bug ("admin-" vs "user-") that still type-checks, so each fix task is independent again. Manifest: correct refactor-04's stats.go to main.go, reword fix-07 to the wrong-prefix bug, add a latency-only description (read-only tasks carry no verification oracle by design), and frame the report README on exclusive time and coverage. Tests updated for the occurrence/exclusive/coverage model; trace, perfbench, and agent green under -race. --- internal/agent/loop.go | 16 ++- internal/agent/selfcorrect.go | 3 + internal/perfbench/manifests/baseline.json | 5 +- internal/perfbench/reports/README.md | 20 ++- internal/perfbench/taskbench.go | 7 +- internal/perfbench/testdata/fix/bugs.go | 6 +- internal/perfbench/turn_bench.go | 16 ++- internal/trace/emit.go | 109 +++++++++------ internal/trace/parse.go | 59 +++++++- internal/trace/recorder.go | 151 +++++++++++++++++--- internal/trace/trace.go | 153 ++++++++++++++++----- internal/trace/trace_test.go | 107 +++++++++++--- 12 files changed, 512 insertions(+), 140 deletions(-) diff --git a/internal/agent/loop.go b/internal/agent/loop.go index 8310a72ca..cc411c2cb 100644 --- a/internal/agent/loop.go +++ b/internal/agent/loop.go @@ -209,9 +209,9 @@ func Run(ctx context.Context, prompt string, provider Provider, options Options) // the tool-definition tokens (they ride on every request) in its estimate. // partitionTools depends only on registry/permissions/options/loaded, not on // the messages, so computing it before compaction is safe. - promptBuildSpan := options.Trace.Span(trace.SpanPromptBuild) + toolPartitionSpan := options.Trace.Span(trace.SpanToolPartition) exposed, _ := partitionToolsCached(registry, permissionMode, options, loaded, toolDefCache) - promptBuildSpan.End() + toolPartitionSpan.End() // PROACTIVE compaction: if the history is approaching the model's // context window, summarize the oldest middle before building the @@ -285,10 +285,18 @@ func Run(ctx context.Context, prompt string, provider Provider, options Options) forwardedVisibleText := false forwardingOpts := zeroruntime.CollectOptions{OnUsage: options.OnUsage} if options.OnText != nil { - forwardingOpts.OnText = func(s string) { forwardedVisibleText = true; options.OnText(s) } + forwardingOpts.OnText = func(s string) { + forwardedVisibleText = true + options.Trace.StampFirstVisibleEvent() + options.Trace.StampFirstToken() + options.OnText(s) + } } if options.OnReasoning != nil { - forwardingOpts.OnReasoning = func(s string) { options.OnReasoning(s) } + forwardingOpts.OnReasoning = func(s string) { + options.Trace.StampFirstToken() + options.OnReasoning(s) + } } if options.OnToolCallStart != nil { forwardingOpts.OnToolCallStart = func(id, name string) { options.OnToolCallStart(id, name) } diff --git a/internal/agent/selfcorrect.go b/internal/agent/selfcorrect.go index 662076ca1..ed151b07f 100644 --- a/internal/agent/selfcorrect.go +++ b/internal/agent/selfcorrect.go @@ -9,6 +9,7 @@ import ( "github.com/Gitlawb/zero/internal/lsp" "github.com/Gitlawb/zero/internal/redaction" + "github.com/Gitlawb/zero/internal/trace" "github.com/Gitlawb/zero/internal/verify" ) @@ -133,7 +134,9 @@ func (sc *SelfCorrector) inspect(ctx context.Context, changedFiles []string) Cor } if sc.cfg.IncludeTests && sc.verifier != nil { + verifySpan := trace.FromContext(ctx).Span(trace.SpanVerification) vr, err := sc.verifier.Verify(ctx) + verifySpan.End() if err != nil { // "No plan / no tests" is not an error (DetectPlan returns an empty // plan), so a non-nil error means verification could not run at all — diff --git a/internal/perfbench/manifests/baseline.json b/internal/perfbench/manifests/baseline.json index aa147a42f..b9e051466 100644 --- a/internal/perfbench/manifests/baseline.json +++ b/internal/perfbench/manifests/baseline.json @@ -1,6 +1,7 @@ { "id": "zero-baseline-turn", "name": "Zero per-turn baseline (Phase 0)", + "description": "Latency-only baseline: measures where a turn spends wall time, not task correctness. Read-only tasks (nav, longproc, longctx, parallel) carry no verification oracle by design — a zero-exit does not prove the answer was right, only that the turn ran. Edit/fix/refactor oracles are intentionally lightweight (substring grep or `go build`) so the suite stays a latency probe; do not read pass/fail as a correctness verdict.", "tasks": [ {"id": "nav-01", "name": "list repo files", "class": "nav", "prompt": "List the files in this repository and report their count. Do not modify anything.", "workspaceFixture": "../testdata/nav"}, {"id": "nav-02", "name": "find a function", "class": "nav", "prompt": "Find the function named 'greet' and report the file and line it is defined on. Do not modify anything.", "workspaceFixture": "../testdata/nav"}, @@ -30,13 +31,13 @@ {"id": "fix-04", "name": "truncated read", "class": "fix", "prompt": "In bugs.go ReadFirst returns only a single character instead of the full content; fix it to return the whole string.", "workspaceFixture": "../testdata/fix", "verificationCommand": ["go", "test", "-run", "TestReadFirstReturnsFullContent", "./..."]}, {"id": "fix-05", "name": "swapped args", "class": "fix", "prompt": "In bugs.go Divide swaps its operands; fix the order so Divide(10,2) returns 5.", "workspaceFixture": "../testdata/fix", "verificationCommand": ["go", "test", "-run", "TestDivideOrder", "./..."]}, {"id": "fix-06", "name": "missing return", "class": "fix", "prompt": "In bugs.go Classify is missing a return for the high case; add it so Classify(500) returns \"high\".", "workspaceFixture": "../testdata/fix", "verificationCommand": ["go", "test", "-run", "TestClassifyHigh", "./..."]}, - {"id": "fix-07", "name": "wrong format verb", "class": "fix", "prompt": "In bugs.go Label uses the %d format verb for a string; fix it to use %s.", "workspaceFixture": "../testdata/fix", "verificationCommand": ["go", "test", "-run", "TestLabelUsesString", "./..."]}, + {"id": "fix-07", "name": "wrong label prefix", "class": "fix", "prompt": "In bugs.go Label returns 'admin-' but the test expects 'user-'; change the prefix from 'admin-' to 'user-'.", "workspaceFixture": "../testdata/fix", "verificationCommand": ["go", "test", "-run", "TestLabelUsesString", "./..."]}, {"id": "fix-08", "name": "race on counter", "class": "fix", "prompt": "In bugs.go the global counter is incremented without synchronization; guard it with a mutex.", "workspaceFixture": "../testdata/fix", "verificationCommand": ["go", "test", "-race", "-run", "TestCounterRace", "./..."]}, {"id": "refactor-01", "name": "extract helper", "class": "refactor", "prompt": "Extract the duplicated greeting logic into a single helper function and call it from both sites.", "workspaceFixture": "../testdata/refactor", "verificationCommand": ["go", "build", "./..."]}, {"id": "refactor-02", "name": "split a file", "class": "refactor", "prompt": "Split main.go into two files: one for Config, one for the rest, keeping the package building.", "workspaceFixture": "../testdata/refactor", "verificationCommand": ["go", "build", "./..."]}, {"id": "refactor-03", "name": "rename package", "class": "refactor", "prompt": "Rename the package from app to zeroapp everywhere and keep it building.", "workspaceFixture": "../testdata/refactor", "verificationCommand": ["go", "build", "./..."]}, - {"id": "refactor-04", "name": "introduce a type", "class": "refactor", "prompt": "Introduce a named type for the map[string]int used in stats.go and update its users.", "workspaceFixture": "../testdata/refactor", "verificationCommand": ["go", "build", "./..."]}, + {"id": "refactor-04", "name": "introduce a type", "class": "refactor", "prompt": "Introduce a named type for the map[string]int used in main.go and update its users.", "workspaceFixture": "../testdata/refactor", "verificationCommand": ["go", "build", "./..."]}, {"id": "refactor-05", "name": "inline a wrapper", "class": "refactor", "prompt": "Inline the thin wrapper function into its single caller and remove it.", "workspaceFixture": "../testdata/refactor", "verificationCommand": ["go", "build", "./..."]}, {"id": "refactor-06", "name": "consolidate errors", "class": "refactor", "prompt": "Consolidate the repeated error-construction blocks into a single helper.", "workspaceFixture": "../testdata/refactor", "verificationCommand": ["go", "build", "./..."]}, diff --git a/internal/perfbench/reports/README.md b/internal/perfbench/reports/README.md index 88ef55744..432ea10cd 100644 --- a/internal/perfbench/reports/README.md +++ b/internal/perfbench/reports/README.md @@ -20,11 +20,29 @@ This builds `zero`, then runs `zero-perf-bench turn` over The JSON report is self-describing: model, mode, self-correct flag, version, commit, date, per-span median/P95, the **top three controllable latency sources** -ranked by share of attributed time, per-class roll-ups, and token/count totals. +ranked by **exclusive** time, per-class roll-ups, and token/count totals. That top-three list is the Phase 0 baseline's "do not proceed until" criterion — it names where a turn actually spends time so later optimization work is targeted, not guessed. +### Attribution model (honest by construction) + +Spans record wall intervals and are **not** summed into each other. Each span's +**exclusive** time is its own duration minus the union of its nested children's +intervals, derived at finish by interval containment. So a `provider_connect` +that runs concurrently inside `generation`, or a `permission_wait` nested inside +`tool_execution`, each contributes only its own exclusive time — they no longer +double-count the same wall. The top-latency shares therefore sum to ~1 for a +well-instrumented run, and the ranking reflects where wall time is actually +spent. + +**Coverage** is the fraction of wall covered by the union of all span +intervals (capped at 1.0) — the honest "≥95% of wall accounted for" metric. A +run with `coverage < 0.95` has uninstrumented gaps, not an inflated attribution. +Note that the suite is **latency-only** (see the manifest `description`): the +top-three ranking is about latency, and pass/fail oracles are intentionally +lightweight; do not read them as a correctness verdict. + ## What to commit Commit the manifest and fixtures (`manifests/`, `../testdata/`), not a generated diff --git a/internal/perfbench/taskbench.go b/internal/perfbench/taskbench.go index c23342a97..8ffcb3703 100644 --- a/internal/perfbench/taskbench.go +++ b/internal/perfbench/taskbench.go @@ -25,9 +25,10 @@ const TaskSchemaVersion = 1 // ZERO must satisfy. The set is recorded by ID with every result so a published // number is traceable to the exact tasks that produced it. type TaskSet struct { - ID string `json:"id"` - Name string `json:"name,omitempty"` - Tasks []BenchTask `json:"tasks"` + ID string `json:"id"` + Name string `json:"name,omitempty"` + Description string `json:"description,omitempty"` + Tasks []BenchTask `json:"tasks"` } // BenchTask is one benchmark task. WorkspaceFixture is the relative path of the diff --git a/internal/perfbench/testdata/fix/bugs.go b/internal/perfbench/testdata/fix/bugs.go index 3395a4752..81a4830a2 100644 --- a/internal/perfbench/testdata/fix/bugs.go +++ b/internal/perfbench/testdata/fix/bugs.go @@ -69,10 +69,10 @@ func Classify(n int) string { return "" } -// Label returns a display label for the given name. BUG: uses the %d format -// verb for a string, producing the wrong text. +// Label returns a display label for the given name. BUG: uses the wrong prefix +// ("admin-" instead of "user-"), producing the wrong text. func Label(name string) string { - return fmt.Sprintf("user-%d", name) + return fmt.Sprintf("admin-%s", name) } // counter is a shared, unsynchronized counter. BUG: Inc is not goroutine-safe. diff --git a/internal/perfbench/turn_bench.go b/internal/perfbench/turn_bench.go index 4ece5cab6..c132355f9 100644 --- a/internal/perfbench/turn_bench.go +++ b/internal/perfbench/turn_bench.go @@ -69,8 +69,10 @@ type SpanStats struct { } // LatencySource is one of the top controllable latency sources, ranked by total -// attributed time across the whole run. Share is its fraction of total attributed -// span time (not wall time — spans overlap, so shares need not sum to 1). +// exclusive time across the whole run. Share is its fraction of total exclusive +// span time. Because exclusive time subtracts nested children, concurrent and +// nested spans no longer double-count, so shares of the top sources sum to ~1 +// for a well-instrumented run. type LatencySource struct { Span string `json:"span"` TotalMs float64 `json:"totalMs"` @@ -201,7 +203,15 @@ func RunTurnBench(ctx context.Context, set TaskSet, cfg TurnBenchConfig) (TurnBe if outcome.Trace != nil { aggregateTotals(&totals, outcome.Trace) for _, span := range outcome.Trace.Spans { - ms := float64(span.Duration.Microseconds()) / 1000 + // Rank by exclusive time (duration minus nested children) so + // concurrent/nested spans do not double-count: provider_connect + // inside generation and permission_wait inside tool_execution + // each contribute their own exclusive time, not their parent's. + d := span.Exclusive + if d <= 0 { + d = span.Duration + } + ms := float64(d.Microseconds()) / 1000 perSpanSamples[span.Name] = append(perSpanSamples[span.Name], ms) if classSpanTotals[class] == nil { classSpanTotals[class] = map[string]float64{} diff --git a/internal/trace/emit.go b/internal/trace/emit.go index 8b6c7beef..a1e1a70ed 100644 --- a/internal/trace/emit.go +++ b/internal/trace/emit.go @@ -17,12 +17,15 @@ type Sink interface { } // WriteNDJSON emits the trace as newline-delimited JSON compatible with the -// internal/agenteval trace contract: one object per line, each carrying a -// "type" and (for spans/counters) a "name" so ParseTraceEventKeys keys them. +// internal/agenteval trace contract: one object per line carrying a "type" +// and (for spans/counters) a "name" so ParseTraceEventKeys keys them. // // The first line is a "trace" summary (name "run"), followed by one "span" -// line per span and one "counter" line per counter. Spans and counters are -// emitted in stable (sorted) order for deterministic output. +// line per span occurrence and one "counter" line per counter. Span lines +// carry the wall interval (start/end), inclusive duration, exclusive +// duration, and parent — the data the harness needs to rank latency sources +// without double-counting nested/concurrent work. Spans are emitted in stable +// (name, then start) order for deterministic output; counters are sorted. func WriteNDJSON(w io.Writer, t *TurnTrace) error { if w == nil { return nil @@ -46,19 +49,36 @@ func WriteNDJSON(w io.Writer, t *TurnTrace) error { "completed_at": formatTime(t.CompletedAt), "wall_ms": ms(t.WallDuration()), "attributed_ms": ms(t.AttributedDuration()), + "coverage": round3(t.Coverage()), "attribution": round3(t.AttributionRatio()), }); err != nil { return err } spans := append([]Span(nil), t.Spans...) - sort.Slice(spans, func(i, j int) bool { return spans[i].Name < spans[j].Name }) + sort.SliceStable(spans, func(i, j int) bool { + if spans[i].Name != spans[j].Name { + return spans[i].Name < spans[j].Name + } + return spans[i].Start.Before(spans[j].Start) + }) for _, span := range spans { - if err := enc.Encode(map[string]any{ - "type": "span", - "name": span.Name, - "duration_ms": ms(span.Duration), - }); err != nil { + obj := map[string]any{ + "type": "span", + "name": span.Name, + "duration_ms": ms(span.Duration), + "exclusive_ms": ms(span.Exclusive), + } + if !span.Start.IsZero() { + obj["start"] = formatTime(span.Start) + } + if !span.End.IsZero() { + obj["end"] = formatTime(span.End) + } + if span.Parent != "" { + obj["parent"] = span.Parent + } + if err := enc.Encode(obj); err != nil { return err } } @@ -78,64 +98,63 @@ func WriteNDJSON(w io.Writer, t *TurnTrace) error { } // WriteText emits a human-readable trace: a header, one line per span with its -// share of wall time, a totals line, then counters. The first write error is -// returned; remaining writes are skipped so a failing sink surfaces promptly -// instead of being silently dropped. +// exclusive time and share of wall, a coverage line, then counters. It returns +// the first write error encountered so a failing sink (e.g. a full disk) is not +// silently swallowed. func WriteText(w io.Writer, t *TurnTrace) error { if w == nil || t == nil { return nil } wall := t.WallDuration() - var p textPrinter - p.printf(w, "trace run=%s session=%s profile=%s\n", t.RunID, t.SessionID, t.Profile) - p.printf(w, " started=%s completed=%s wall=%s\n", formatTime(t.StartedAt), formatTime(t.CompletedAt), wall) + var firstErr error + write := func(format string, args ...any) { + if firstErr != nil { + return + } + if _, err := fmt.Fprintf(w, format, args...); err != nil { + firstErr = err + } + } + write("trace run=%s session=%s profile=%s\n", t.RunID, t.SessionID, t.Profile) + write(" started=%s completed=%s wall=%s\n", formatTime(t.StartedAt), formatTime(t.CompletedAt), wall) + write(" attributed=%s coverage=%.1f%%\n", t.AttributedDuration(), t.Coverage()*100) if !t.FirstVisibleEventAt.IsZero() { - p.printf(w, " first_visible_event=%s (+%s)\n", formatTime(t.FirstVisibleEventAt), t.FirstVisibleEventAt.Sub(t.StartedAt)) + write(" first_visible_event=%s (+%s)\n", formatTime(t.FirstVisibleEventAt), t.FirstVisibleEventAt.Sub(t.StartedAt)) } if !t.FirstUsefulActionAt.IsZero() { - p.printf(w, " first_useful_action=%s (+%s)\n", formatTime(t.FirstUsefulActionAt), t.FirstUsefulActionAt.Sub(t.StartedAt)) + write(" first_useful_action=%s (+%s)\n", formatTime(t.FirstUsefulActionAt), t.FirstUsefulActionAt.Sub(t.StartedAt)) } if !t.FirstTokenAt.IsZero() { - p.printf(w, " first_token=%s (+%s)\n", formatTime(t.FirstTokenAt), t.FirstTokenAt.Sub(t.StartedAt)) + write(" first_token=%s (+%s)\n", formatTime(t.FirstTokenAt), t.FirstTokenAt.Sub(t.StartedAt)) } spans := append([]Span(nil), t.Spans...) - sort.Slice(spans, func(i, j int) bool { return spans[i].Name < spans[j].Name }) - p.println(w, "spans:") + sort.SliceStable(spans, func(i, j int) bool { + if spans[i].Name != spans[j].Name { + return spans[i].Name < spans[j].Name + } + return spans[i].Start.Before(spans[j].Start) + }) + write("spans:\n") for _, span := range spans { share := 0.0 if wall > 0 { - share = float64(span.Duration) / float64(wall) + share = float64(span.Exclusive) / float64(wall) + } + parent := "" + if span.Parent != "" { + parent = " [" + span.Parent + "]" } - p.printf(w, " %-18s %10s %5.1f%%\n", span.Name, span.Duration, share*100) + write(" %-18s %10s excl=%-10s %5.1f%%%s\n", span.Name, span.Duration, span.Exclusive, share*100, parent) } - p.printf(w, " %-18s %10s %5.1f%%\n", "attributed", t.AttributedDuration(), t.AttributionRatio()*100) counters := append([]Counter(nil), t.Counters...) sort.Slice(counters, func(i, j int) bool { return counters[i].Name < counters[j].Name }) - p.println(w, "counters:") + write("counters:\n") for _, c := range counters { - p.printf(w, " %-22s %d\n", c.Name, c.Value) - } - return p.err -} - -// textPrinter remembers the first write error so a stream of fprintf/fprintln -// calls can short-circuit after the sink fails, then report it once. -type textPrinter struct{ err error } - -func (p *textPrinter) printf(w io.Writer, format string, args ...any) { - if p.err != nil { - return - } - _, p.err = fmt.Fprintf(w, format, args...) -} - -func (p *textPrinter) println(w io.Writer, s string) { - if p.err != nil { - return + write(" %-22s %d\n", c.Name, c.Value) } - _, p.err = fmt.Fprintln(w, s) + return firstErr } // NDJSONSink adapts an io.Writer as a Sink emitting NDJSON. diff --git a/internal/trace/parse.go b/internal/trace/parse.go index 08caf71f7..71b8d149c 100644 --- a/internal/trace/parse.go +++ b/internal/trace/parse.go @@ -3,6 +3,7 @@ package trace import ( "bufio" "encoding/json" + "errors" "io" "strings" "time" @@ -10,11 +11,15 @@ import ( // ReadNDJSON parses an NDJSON trace emitted by WriteNDJSON back into a TurnTrace. // It is the inverse of WriteNDJSON and is used by the benchmark harness to turn a -// captured trace file into structured per-span stats. Lines that are not valid -// JSON or lack a "type" field are skipped (the emitter is the only writer, so in -// practice every line is valid; the skip keeps a stray blank line from fataling a -// benchmark run). The first "trace" line sets the run/timing fields; "span" and -// "counter" lines populate Spans and Counters. +// captured trace file into structured per-span stats. +// +// It fails loudly on a corrupt file rather than silently returning an empty +// trace: a non-empty input must contain a "type":"trace" header line, and a +// non-empty input that yields no spans and no counters is treated as corrupt. +// Individual span/counter lines with bad JSON are skipped only when a valid +// "trace" header has already been seen — a truncated middle of a real trace +// should not fatal a run, but a file with no header at all is never parsed as +// a valid empty trace. func ReadNDJSON(r io.Reader) (*TurnTrace, error) { if r == nil { return nil, nil @@ -22,18 +27,26 @@ func ReadNDJSON(r io.Reader) (*TurnTrace, error) { t := &TurnTrace{} scanner := bufio.NewScanner(r) scanner.Buffer(make([]byte, 0, 64*1024), 4*1024*1024) + sawInput := false + sawTraceHeader := false for scanner.Scan() { line := strings.TrimSpace(scanner.Text()) if line == "" { continue } + sawInput = true var obj map[string]any if err := json.Unmarshal([]byte(line), &obj); err != nil { + // A non-JSON line before any header means the file is not a trace. + if !sawTraceHeader { + return nil, errors.New("parse trace: not a valid NDJSON trace (no type:trace header)") + } continue } typ, _ := obj["type"].(string) switch typ { case "trace": + sawTraceHeader = true t.RunID, _ = obj["run_id"].(string) t.SessionID, _ = obj["session_id"].(string) t.Profile, _ = obj["profile"].(string) @@ -43,16 +56,50 @@ func ReadNDJSON(r io.Reader) (*TurnTrace, error) { t.FirstTokenAt = parseTime(obj["first_token_at"]) t.CompletedAt = parseTime(obj["completed_at"]) case "span": + if !sawTraceHeader { + return nil, errors.New("parse trace: not a valid NDJSON trace (no type:trace header)") + } name, _ := obj["name"].(string) - t.Spans = append(t.Spans, Span{Name: name, Duration: parseDurationMs(obj["duration_ms"])}) + s := Span{ + Name: name, + Start: parseTime(obj["start"]), + End: parseTime(obj["end"]), + Duration: parseDurationMs(obj["duration_ms"]), + } + if s.End.IsZero() && !s.Start.IsZero() { + s.End = s.Start.Add(s.Duration) + } + s.Exclusive = parseDurationMs(obj["exclusive_ms"]) + if s.Exclusive <= 0 { + s.Exclusive = s.Duration + } + if v, ok := obj["parent"].(string); ok { + s.Parent = v + } + t.Spans = append(t.Spans, s) case "counter": + if !sawTraceHeader { + return nil, errors.New("parse trace: not a valid NDJSON trace (no type:trace header)") + } name, _ := obj["name"].(string) t.Counters = append(t.Counters, Counter{Name: name, Value: parseInt64(obj["value"])}) + default: + // Unknown event type: tolerate (forward-compat) but only after a + // header has been seen. + if !sawTraceHeader { + return nil, errors.New("parse trace: not a valid NDJSON trace (no type:trace header)") + } } } if err := scanner.Err(); err != nil { return nil, err } + if sawInput && !sawTraceHeader { + return nil, errors.New("parse trace: non-empty input had no type:trace header") + } + if sawTraceHeader && len(t.Spans) == 0 && len(t.Counters) == 0 { + return nil, errors.New("parse trace: header present but no spans or counters recovered (corrupt or truncated)") + } return t, nil } diff --git a/internal/trace/recorder.go b/internal/trace/recorder.go index 25c33889c..38d056d38 100644 --- a/internal/trace/recorder.go +++ b/internal/trace/recorder.go @@ -1,6 +1,7 @@ package trace import ( + "sort" "sync" "time" ) @@ -12,9 +13,15 @@ import ( // A nil *Recorder is valid to call: the no-op helpers below route every // stamp through a nil check so callers can write `options.Trace.Start()` // unconditionally and pay nothing when tracing is off. +// +// Spans are stored as occurrences (one entry per stamp) with their wall +// interval. Parent/child nesting and exclusive time are derived at Finish by +// interval containment, so concurrent (provider_connect inside generation) and +// nested (permission_wait inside tool_execution) spans are not double-counted. type Recorder struct { mu sync.Mutex tr TurnTrace + cursor time.Time // synthesis cursor for RecordSpan (no real interval) started bool finished bool firstTokenStamped bool @@ -56,14 +63,15 @@ type SpanHandle struct { once sync.Once } -// End commits the span's elapsed duration to the recorder. Durations -// accumulate by name so repeated stamps of the same span add together. +// End commits the span's wall interval to the recorder. Each stamp is its own +// occurrence (spans are not merged by name); exclusive time is derived at +// Finish from the recorded intervals. func (s *SpanHandle) End() { if s == nil || s.recorder == nil { return } s.once.Do(func() { - s.recorder.addSpan(s.name, time.Since(s.start)) + s.recorder.addOccurrence(s.name, s.start, time.Now()) }) } @@ -79,14 +87,31 @@ func (r *Recorder) Span(name string) *SpanHandle { return &SpanHandle{recorder: r, name: name, start: time.Now()} } -// RecordSpan commits an already-measured duration to name, accumulating with -// any prior value. Use this when the caller already holds a start time (for -// example, a span that began before the recorder existed). +// RecordSpan commits an already-measured duration to name as a synthesized +// sequential occurrence. Use this when the caller already holds a duration +// (for example, in tests) rather than a live interval; production code uses +// Span/End, which record the real wall interval. Synthesized occurrences +// chain from the recorder's StartedAt (or a moving cursor) so coverage and +// exclusive math remain consistent. Each stamp is its own entry. func (r *Recorder) RecordSpan(name string, d time.Duration) { if r == nil { return } - r.addSpan(name, d) + r.mu.Lock() + defer r.mu.Unlock() + if r.finished { + return + } + start := r.cursor + if start.IsZero() { + start = r.tr.StartedAt + } + if start.IsZero() { + start = time.Now() + } + end := start.Add(d) + r.cursor = end + r.tr.Spans = append(r.tr.Spans, Span{Name: name, Start: start, End: end, Duration: d}) } // Counter adds n to the named counter, accumulating across calls. @@ -147,7 +172,8 @@ func (r *Recorder) StampFirstUsefulAction() { r.tr.FirstUsefulActionAt = time.Now() } -// Finish stamps CompletedAt and returns a snapshot of the trace. Calling +// Finish stamps CompletedAt, derives each span's parent (by interval +// containment) and exclusive time, and returns a snapshot of the trace. Calling // Finish more than once returns the same snapshot. func (r *Recorder) Finish() *TurnTrace { if r == nil { @@ -158,6 +184,7 @@ func (r *Recorder) Finish() *TurnTrace { if !r.finished { r.finished = true r.tr.CompletedAt = time.Now() + deriveNesting(r.tr.Spans) } snap := r.tr // Copy the slices so callers cannot mutate the recorder's state. @@ -166,20 +193,18 @@ func (r *Recorder) Finish() *TurnTrace { return &snap } -// addSpan accumulates d into the named span, merging with an existing entry. -func (r *Recorder) addSpan(name string, d time.Duration) { +// addOccurrence appends a span occurrence with its wall interval. +func (r *Recorder) addOccurrence(name string, start, end time.Time) { r.mu.Lock() defer r.mu.Unlock() if r.finished { return } - for i := range r.tr.Spans { - if r.tr.Spans[i].Name == name { - r.tr.Spans[i].Duration += d - return - } + d := end.Sub(start) + if d < 0 { + d = 0 } - r.tr.Spans = append(r.tr.Spans, Span{Name: name, Duration: d}) + r.tr.Spans = append(r.tr.Spans, Span{Name: name, Start: start, End: end, Duration: d}) } func (r *Recorder) addCounterLocked(name string, n int64) { @@ -191,3 +216,97 @@ func (r *Recorder) addCounterLocked(name string, n int64) { } r.tr.Counters = append(r.tr.Counters, Counter{Name: name, Value: n}) } + +// interval is a half-open [start, end) wall window used for containment and +// coverage math. +type interval struct{ start, end time.Time } + +// deriveNesting computes each span's parent (the tightest span whose interval +// contains it) and its exclusive time (duration minus the union of its direct +// children's intervals). Spans without a usable interval are left top-level +// with exclusive = duration. This is O(n²) in the span count, which is tiny +// (a handful to a few dozen per run), and runs once at Finish. +func deriveNesting(spans []Span) { + parent := make([]int, len(spans)) + for i := range parent { + parent[i] = -1 + } + for i, a := range spans { + if a.Start.IsZero() || a.End.IsZero() { + continue + } + bestIdx := -1 + bestDur := time.Duration(0) + for j, b := range spans { + if i == j || b.Start.IsZero() || b.End.IsZero() { + continue + } + // b contains a when a starts at/after b and ends at/before b. + if !a.Start.Before(b.Start) && !a.End.After(b.End) { + bd := b.End.Sub(b.Start) + if bestIdx == -1 || bd < bestDur { + bestIdx = j + bestDur = bd + } + } + } + parent[i] = bestIdx + } + for i := range spans { + if spans[i].Start.IsZero() || spans[i].End.IsZero() { + spans[i].Exclusive = spans[i].Duration + continue + } + var children []interval + for j := range spans { + if parent[j] == i { + children = append(children, interval{spans[j].Start, spans[j].End}) + } + } + exclusive := spans[i].Duration - unionOf(children) + if exclusive < 0 { + exclusive = 0 + } + spans[i].Exclusive = exclusive + if parent[i] != -1 { + spans[i].Parent = spans[parent[i]].Name + } + } +} + +// unionIntervalDuration returns the total wall time covered by the union of +// all span intervals (used for Coverage). Spans without a usable interval are +// skipped. +func unionIntervalDuration(spans []Span) time.Duration { + var intervals []interval + for _, s := range spans { + if s.Start.IsZero() || s.End.IsZero() || s.End.Before(s.Start) { + continue + } + intervals = append(intervals, interval{s.Start, s.End}) + } + return unionOf(intervals) +} + +// unionOf returns the total duration covered by the union of the intervals. +func unionOf(intervals []interval) time.Duration { + if len(intervals) == 0 { + return 0 + } + sort.Slice(intervals, func(i, j int) bool { return intervals[i].start.Before(intervals[j].start) }) + var total time.Duration + cur := intervals[0] + for _, iv := range intervals[1:] { + if !iv.start.After(cur.end) { + // overlap or touch: extend the current window. + if iv.end.After(cur.end) { + cur.end = iv.end + } + continue + } + total += cur.end.Sub(cur.start) + cur = iv + } + total += cur.end.Sub(cur.start) + return total +} diff --git a/internal/trace/trace.go b/internal/trace/trace.go index e46ab6ae9..3c86fedf9 100644 --- a/internal/trace/trace.go +++ b/internal/trace/trace.go @@ -8,25 +8,35 @@ // The emitted NDJSON is compatible with internal/agenteval's trace contract: // one JSON object per line carrying a "type" (and usually "name") field, so // agenteval.ParseTraceEventKeys / MissingTraceEvents can validate a run. +// +// Attribution model. Each stamp records a wall interval [start, end]. Spans +// that run concurrently or are nested (e.g. provider_connect inside generation, +// permission_wait inside tool_execution) are NOT summed into each other. The +// recorder derives a parent for each span by interval containment and computes +// per-span exclusive time (duration minus the union of its children's +// intervals). AttributedDuration is the sum of top-level (non-nested) spans — +// the time accounted for without double-counting. Coverage is the fraction of +// wall covered by the union of all span intervals; it is the honest "≥95% of +// wall accounted for" metric and never exceeds 1. package trace import "time" // Span names. These are the "name" keys emitted in the NDJSON event stream // (e.g. {"type":"span","name":"generation","duration_ms":123.4}) and the -// single source of truth for what a run's wall time is attributed to. +// vocabulary a run's wall time is attributed to. Only names that are actually +// stamped appear here: phases without a real stamp are omitted so readers do +// not trust empty categories. RequiredEventKeys lists the subset guaranteed in +// any successful model turn; OptionalEventKeys lists the rest. const ( - SpanPromptBuild = "prompt_build" - SpanProviderConnect = "provider_connect" - SpanProviderQueue = "provider_queue" - SpanGeneration = "generation" - SpanToolQueue = "tool_queue" - SpanToolExecution = "tool_execution" - SpanPermissionWait = "permission_wait" - SpanProcessWait = "process_wait" - SpanVerification = "verification" - SpanCompaction = "compaction" - SpanPersistence = "persistence" + SpanToolPartition = "tool_partition" // partitioning the tool set for the prompt + SpanProviderConnect = "provider_connect" // client.Do in the provider seam + SpanProviderQueue = "provider_queue" // pre-send OAuth/token resolve + SpanGeneration = "generation" // streaming a model completion + SpanToolExecution = "tool_execution" // executing tool calls + SpanPermissionWait = "permission_wait" // waiting on a permission prompt + SpanVerification = "verification" // self-correct verify pass + SpanCompaction = "compaction" // context compaction ) // Counter names. Emitted as {"type":"counter","name":"tool_calls","value":7}. @@ -45,12 +55,22 @@ const ( CounterOutputTokens = "output_tokens" ) -// Span is a named duration attributed to part of a run. Spans accumulate by -// name: stamping the same name twice (e.g. prompt_build across turns) adds to -// the existing entry rather than creating a duplicate. +// Span is one named wall interval attributed to part of a run. Each stamp is +// its own entry (spans are not merged by name): a run that streams two model +// completions has two generation entries, which lets the recorder derive +// parent/child nesting by interval containment and compute exclusive time. +// +// Duration is the inclusive wall time (End - Start). Exclusive is Duration +// minus the union of this span's children's intervals — the time uniquely +// attributable to this phase rather than to a nested sub-phase. Parent is the +// name of the tightest containing span, or "" for a top-level span. type Span struct { - Name string `json:"name"` - Duration time.Duration `json:"duration"` + Name string `json:"name"` + Start time.Time `json:"start,omitempty"` + End time.Time `json:"end,omitempty"` + Duration time.Duration `json:"duration"` + Parent string `json:"parent,omitempty"` + Exclusive time.Duration `json:"exclusive,omitempty"` } // Counter is a named integer accumulated during a run (counts and token totals). @@ -82,39 +102,81 @@ func (t *TurnTrace) WallDuration() time.Duration { return t.CompletedAt.Sub(t.StartedAt) } -// AttributedDuration is the sum of all span durations. A run is considered -// well-attributed when this is >= 95% of WallDuration. +// AttributedDuration is the sum of top-level (non-nested) span durations — the +// wall time accounted for without double-counting nested or concurrent sub- +// phases. For a well-instrumented sequential run this is close to WallDuration +// (gaps are uninstrumented regions); it does not inflate from nested children. func (t *TurnTrace) AttributedDuration() time.Duration { if t == nil { return 0 } var total time.Duration for _, span := range t.Spans { - total += span.Duration + if span.Parent == "" { + total += span.Duration + } } return total } -// AttributionRatio is AttributedDuration / WallDuration, or 0 when unattributable. -func (t *TurnTrace) AttributionRatio() float64 { +// Coverage is the fraction of WallDuration covered by the union of all span +// intervals, capped at 1.0. This is the honest "what fraction of wall time did +// we account for" metric: overlapping or nested spans do not push it above 1. +// Returns 0 when wall is zero or no span has a usable interval. +func (t *TurnTrace) Coverage() float64 { + if t == nil { + return 0 + } wall := t.WallDuration() if wall <= 0 { return 0 } - return float64(t.AttributedDuration()) / float64(wall) + union := unionIntervalDuration(t.Spans) + if union <= 0 { + return 0 + } + ratio := float64(union) / float64(wall) + if ratio > 1 { + ratio = 1 + } + return ratio } -// Span returns the duration recorded for name, or zero if absent. +// AttributionRatio is Coverage — the fraction of wall covered by span +// intervals. A run is considered well-attributed when this is >= 0.95. It +// never exceeds 1, so it is a sound denominator for "share of attributed time". +func (t *TurnTrace) AttributionRatio() float64 { + return t.Coverage() +} + +// Span returns the total inclusive duration recorded for name across all its +// occurrences, or zero if absent. func (t *TurnTrace) Span(name string) time.Duration { if t == nil { return 0 } + var total time.Duration for _, span := range t.Spans { if span.Name == name { - return span.Duration + total += span.Duration } } - return 0 + return total +} + +// Exclusive returns the total exclusive duration recorded for name across all +// its occurrences (each occurrence's Duration minus its children), or zero. +func (t *TurnTrace) Exclusive(name string) time.Duration { + if t == nil { + return 0 + } + var total time.Duration + for _, span := range t.Spans { + if span.Name == name { + total += span.Exclusive + } + } + return total } // Counter returns the value recorded for name, or zero if absent. @@ -130,23 +192,42 @@ func (t *TurnTrace) Counter(name string) int64 { return 0 } -// RequiredEventKeys is the set of span/counter event keys a traced run is -// expected to emit. Tests assert via agenteval.MissingTraceEvents that a run -// produces all of these. Generation spans are only produced when the run -// reaches a model request, so callers may trim this list for short circuits. +// RequiredEventKeys is the set of span/counter event keys guaranteed in any +// successful single-turn traced run, regardless of provider or auth path. +// Tests assert via agenteval.MissingTraceEvents that a run produces all of +// these. Phases that are conditional (tools, permission, compaction, +// verification) are in OptionalEventKeys, not here, so a healthy short trace +// does not false-fail. func RequiredEventKeys() []string { return []string{ - "span:" + SpanPromptBuild, + "span:" + SpanToolPartition, "span:" + SpanGeneration, - "span:" + SpanToolExecution, - "span:" + SpanPermissionWait, - "span:" + SpanCompaction, - "span:" + SpanPersistence, "span:" + SpanProviderConnect, "counter:" + CounterModelRequests, - "counter:" + CounterToolCalls, "counter:" + CounterInputTokens, "counter:" + CounterOutputTokens, "trace:run", } } + +// OptionalEventKeys are event keys a traced run MAY emit depending on what the +// run does (it may call no tools, need no permission, never compact, etc.). +// Callers must not treat their absence as a failure. +func OptionalEventKeys() []string { + return []string{ + "span:" + SpanProviderQueue, + "span:" + SpanToolExecution, + "span:" + SpanPermissionWait, + "span:" + SpanCompaction, + "span:" + SpanVerification, + "counter:" + CounterToolCalls, + "counter:" + CounterCachedInputTokens, + "counter:" + CounterRetryCount, + "counter:" + CounterReconnectCount, + "counter:" + CounterCompactionCount, + "counter:" + CounterCompletionNudges, + "counter:" + CounterAcceptanceChecks, + "counter:" + CounterPollingTurn, + "counter:" + CounterModelSwitches, + } +} diff --git a/internal/trace/trace_test.go b/internal/trace/trace_test.go index 88f30bced..bac453b7e 100644 --- a/internal/trace/trace_test.go +++ b/internal/trace/trace_test.go @@ -28,8 +28,10 @@ func TestRecorderSpanAccumulates(t *testing.T) { if got < 3*time.Millisecond { t.Fatalf("generation span did not accumulate across stamps; got %v", got) } - if len(tr.Spans) != 1 { - t.Fatalf("expected one generation span entry, got %d", len(tr.Spans)) + // Spans are stored as occurrences (one entry per stamp), not merged by name, + // so the recorder can derive parent/child nesting by interval containment. + if len(tr.Spans) != 2 { + t.Fatalf("expected two generation span occurrences, got %d", len(tr.Spans)) } } @@ -171,12 +173,11 @@ func TestContextNilRecorder(t *testing.T) { func TestWriteNDJSONMatchesAgentevalContract(t *testing.T) { r := NewRecorder("s1", "r1", "cold") r.Start() - r.RecordSpan(SpanPromptBuild, 10*time.Millisecond) + r.RecordSpan(SpanToolPartition, 10*time.Millisecond) r.RecordSpan(SpanGeneration, 50*time.Millisecond) r.RecordSpan(SpanToolExecution, 5*time.Millisecond) r.RecordSpan(SpanPermissionWait, 1*time.Millisecond) r.RecordSpan(SpanCompaction, 2*time.Millisecond) - r.RecordSpan(SpanPersistence, 1*time.Millisecond) r.RecordSpan(SpanProviderConnect, 8*time.Millisecond) r.Counter(CounterModelRequests, 2) r.Counter(CounterToolCalls, 3) @@ -198,7 +199,7 @@ func TestWriteNDJSONMatchesAgentevalContract(t *testing.T) { keys := agenteval.ParseTraceEventKeys(stdout) want := map[string]bool{ "trace:run": true, - "span:" + SpanPromptBuild: true, + "span:" + SpanToolPartition: true, "span:" + SpanGeneration: true, "span:" + SpanToolExecution: true, "span:" + SpanProviderConnect: true, @@ -261,32 +262,78 @@ func (errWriter) Write(p []byte) (int, error) { return 0, errors.New("write fail func TestAttributionRatio(t *testing.T) { r := NewRecorder("s", "r", "") r.Start() + // Two sequential, non-overlapping spans (RecordSpan synthesizes them + // back-to-back from the cursor) so neither contains the other: both are + // top-level and AttributedDuration is their sum with no double-counting. r.RecordSpan(SpanGeneration, 10*time.Millisecond) r.RecordSpan(SpanToolExecution, 10*time.Millisecond) tr := r.Finish() - // Attributed time is the deterministic sum of recorded span durations; it + // Attributed time is the deterministic sum of top-level span durations; it // does not depend on wall-clock timing. if want := 20 * time.Millisecond; tr.AttributedDuration() != want { t.Fatalf("attributed = %v, want %v", tr.AttributedDuration(), want) } - // AttributionRatio is attributed / wall. The spans are synthetic durations - // with no real delay, so wall is on the order of microseconds and the ratio - // can legitimately exceed 1.0 (overlapping parallel spans push it above 1.0 - // in real runs too). Assert the contract — ratio == attributed/wall — rather - // than a fixed bound, so the test is clock-independent. - wall := tr.WallDuration() - if wall <= 0 { - // Clock granularity collapsed the run to zero wall; the ratio is defined 0. - if got := tr.AttributionRatio(); got != 0 { - t.Fatalf("ratio with zero wall = %v, want 0", got) + // AttributionRatio is Coverage — the fraction of wall covered by the union + // of span intervals, capped at 1.0. It never exceeds 1 (no double-counting + // of overlapping/nested spans), and equals Coverage by definition. + if got := tr.AttributionRatio(); got > 1 { + t.Fatalf("attribution ratio = %v, must never exceed 1", got) + } + if got := tr.AttributionRatio(); got != tr.Coverage() { + t.Fatalf("attribution ratio = %v, want Coverage() = %v", got, tr.Coverage()) + } +} + +func TestCoverageExcludesDoubleCountAndCaps(t *testing.T) { + // A nested span (provider_connect inside generation) must NOT push coverage + // above 1, and the parent's exclusive time must subtract the child's interval. + r := NewRecorder("s", "r", "") + r.Start() + // Synthesize a containing generation interval of 100ms, then a provider_connect + // recorded after it so its interval sits fully inside generation's. + gen := r.Span(SpanGeneration) + time.Sleep(2 * time.Millisecond) + // Record a provider_connect that starts after generation started and ends + // before generation ends: nested, so it is the child of generation. + pc := r.Span(SpanProviderConnect) + time.Sleep(1 * time.Millisecond) + pc.End() + gen.End() + tr := r.Finish() + + var genExclusive, pcExclusive time.Duration + var genParent, pcParent string + for _, s := range tr.Spans { + switch s.Name { + case SpanGeneration: + genExclusive = s.Exclusive + genParent = s.Parent + case SpanProviderConnect: + pcExclusive = s.Exclusive + pcParent = s.Parent } - return } - wantRatio := float64(tr.AttributedDuration()) / float64(wall) - if got := tr.AttributionRatio(); got != wantRatio { - t.Fatalf("ratio = %v, want %v (attributed/wall)", got, wantRatio) + // provider_connect has no children, so its exclusive time equals its own + // duration and is positive. + if pcExclusive <= 0 { + t.Fatalf("provider_connect exclusive = %v, want > 0", pcExclusive) + } + if pcParent != SpanGeneration { + t.Fatalf("provider_connect parent = %q, want %q (nested by interval containment)", pcParent, SpanGeneration) + } + if genParent != "" { + t.Fatalf("generation should be top-level, got parent %q", genParent) + } + // generation's exclusive time must be its duration minus provider_connect's + // interval, not its full duration. + if genExclusive >= tr.Span(SpanGeneration) { + t.Fatalf("generation exclusive = %v should be less than its inclusive %v (child subtracted)", + genExclusive, tr.Span(SpanGeneration)) + } + if tr.Coverage() > 1 { + t.Fatalf("coverage = %v, must never exceed 1 even with nested spans", tr.Coverage()) } } @@ -317,7 +364,7 @@ func contains(slice []string, s string) bool { func TestReadNDJSONRoundTrip(t *testing.T) { r := NewRecorder("s1", "r1", "cold") r.Start() - r.RecordSpan(SpanPromptBuild, 10*time.Millisecond) + r.RecordSpan(SpanToolPartition, 10*time.Millisecond) r.RecordSpan(SpanGeneration, 50*time.Millisecond) r.RecordSpan(SpanGeneration, 5*time.Millisecond) // accumulates to 55ms r.Counter(CounterModelRequests, 3) @@ -352,3 +399,21 @@ func TestReadNDJSONRoundTrip(t *testing.T) { t.Fatal("first_token_at lost in round-trip") } } + +func TestReadNDJSONRejectsNonTrace(t *testing.T) { + // A file with content but no type:trace header is never a valid empty trace. + if _, err := ReadNDJSON(strings.NewReader("not json at all\n")); err == nil { + t.Fatal("expected error for non-JSON input with no trace header") + } + if _, err := ReadNDJSON(strings.NewReader(`{"type":"span","name":"generation","duration_ms":5}` + "\n")); err == nil { + t.Fatal("expected error for span lines with no preceding trace header") + } +} + +func TestReadNDJSONRejectsHeaderOnly(t *testing.T) { + // A header with no recoverable spans/counters is corrupt/truncated, not empty. + header := `{"type":"trace","name":"run","session_id":"s","run_id":"r"}` + "\n" + if _, err := ReadNDJSON(strings.NewReader(header)); err == nil { + t.Fatal("expected error for a trace header with no spans or counters") + } +} From 40806aa4b1c640da3038244b59763ae9388537ae Mon Sep 17 00:00:00 2001 From: Vasanthdev2004 Date: Thu, 16 Jul 2026 13:56:46 +0530 Subject: [PATCH 5/8] Fix exclusive-time round-trip, identical-interval nesting, and empty-trace parse MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Three correctness bugs in the attribution model found by an adversarial review of the prior commit, all undermining the no-double-count guarantee: 1. exclusive_ms:0 was overwritten with the inclusive Duration on re-parse. A parent whose children tile its interval legitimately has exclusive time 0; WriteNDJSON emits exclusive_ms:0, but ReadNDJSON's "<= 0 means missing" fallback turned that back into the full duration, so every re-parsed trace re-introduced the double-counting the model exists to prevent (the benchmark harness, which ranks re-parsed traces, inherits it). Gate the fallback on key ABSENCE, so a written 0 is preserved. 2. deriveNesting formed a 2-cycle for two spans with identical [start, end] intervals: the symmetric containment check made each parent the other, dropping both from top-level and zeroing AttributedDuration. Break the tie deterministically — strict containment is an unambiguous parent; for identical intervals, only the lower-indexed span may parent the other, so one stays top-level. 3. ReadNDJSON returned a valid empty TurnTrace for empty/blank-only input, so a run that crashed before emitting a trace (or where --trace was not honored) masqueraded as a clean zero-attribution sample. Empty input now errors, so the harness records a TraceIssue. Also: decode counters via json.Number so int64 values above 2^53 round-trip exactly instead of losing precision through float64; and drop the harness's own "exclusive <= 0 -> Duration" ranking fallback, which was the same double-count on the re-parsed path. Added regression tests covering the zero-exclusive round-trip, the identical-interval nesting, empty-input rejection, and counter precision. --- internal/perfbench/turn_bench.go | 12 +-- internal/trace/parse.go | 69 ++++++++++++++--- internal/trace/recorder.go | 25 +++++-- internal/trace/trace_test.go | 123 +++++++++++++++++++++++++++++++ 4 files changed, 206 insertions(+), 23 deletions(-) diff --git a/internal/perfbench/turn_bench.go b/internal/perfbench/turn_bench.go index c132355f9..df674ff55 100644 --- a/internal/perfbench/turn_bench.go +++ b/internal/perfbench/turn_bench.go @@ -207,11 +207,13 @@ func RunTurnBench(ctx context.Context, set TaskSet, cfg TurnBenchConfig) (TurnBe // concurrent/nested spans do not double-count: provider_connect // inside generation and permission_wait inside tool_execution // each contribute their own exclusive time, not their parent's. - d := span.Exclusive - if d <= 0 { - d = span.Duration - } - ms := float64(d.Microseconds()) / 1000 + // A span whose exclusive is legitimately zero (a parent fully + // covered by its children) contributes zero on purpose — do + // NOT fall back to Duration, which would re-introduce the + // double-count. ReadNDJSON preserves a written exclusive_ms:0 + // as 0 and only falls back to Duration when the key is absent, + // so span.Exclusive is always populated here. + ms := float64(span.Exclusive.Microseconds()) / 1000 perSpanSamples[span.Name] = append(perSpanSamples[span.Name], ms) if classSpanTotals[class] == nil { classSpanTotals[class] = map[string]float64{} diff --git a/internal/trace/parse.go b/internal/trace/parse.go index 71b8d149c..490918c14 100644 --- a/internal/trace/parse.go +++ b/internal/trace/parse.go @@ -14,12 +14,17 @@ import ( // captured trace file into structured per-span stats. // // It fails loudly on a corrupt file rather than silently returning an empty -// trace: a non-empty input must contain a "type":"trace" header line, and a -// non-empty input that yields no spans and no counters is treated as corrupt. -// Individual span/counter lines with bad JSON are skipped only when a valid -// "trace" header has already been seen — a truncated middle of a real trace -// should not fatal a run, but a file with no header at all is never parsed as -// a valid empty trace. +// trace. Empty or blank-only input is an error (an empty trace file means +// emission never happened — e.g. the agent crashed before writing the header +// or --trace was not honored — and must not masquerade as a valid zero- +// attribution sample). A non-empty input must contain a "type":"trace" header +// line; span/counter lines before it are an error; and a header that yields no +// spans and no counters is treated as corrupt. Individual span/counter lines +// with bad JSON are skipped only when a valid "trace" header has already been +// seen — a truncated middle of a real trace should not fatal a run. +// +// Numbers are decoded with UseNumber so counter values round-trip as exact +// int64s rather than going through float64 (which loses precision above 2^53). func ReadNDJSON(r io.Reader) (*TurnTrace, error) { if r == nil { return nil, nil @@ -36,7 +41,9 @@ func ReadNDJSON(r io.Reader) (*TurnTrace, error) { } sawInput = true var obj map[string]any - if err := json.Unmarshal([]byte(line), &obj); err != nil { + dec := json.NewDecoder(strings.NewReader(line)) + dec.UseNumber() + if err := dec.Decode(&obj); err != nil { // A non-JSON line before any header means the file is not a trace. if !sawTraceHeader { return nil, errors.New("parse trace: not a valid NDJSON trace (no type:trace header)") @@ -69,8 +76,15 @@ func ReadNDJSON(r io.Reader) (*TurnTrace, error) { if s.End.IsZero() && !s.Start.IsZero() { s.End = s.Start.Add(s.Duration) } - s.Exclusive = parseDurationMs(obj["exclusive_ms"]) - if s.Exclusive <= 0 { + // Preserve exclusive time exactly as written. A legitimately-zero + // exclusive (a parent whose children cover its whole interval) is + // emitted as exclusive_ms: 0 and MUST round-trip as 0 — falling back + // to Duration here would re-introduce the double-counting the + // exclusive-time model exists to prevent. Only fall back to Duration + // when the key is genuinely absent (an older/duration-only emitter). + if ev, ok := obj["exclusive_ms"]; ok { + s.Exclusive = parseDurationMs(ev) + } else { s.Exclusive = s.Duration } if v, ok := obj["parent"].(string); ok { @@ -94,10 +108,16 @@ func ReadNDJSON(r io.Reader) (*TurnTrace, error) { if err := scanner.Err(); err != nil { return nil, err } - if sawInput && !sawTraceHeader { + if !sawInput { + // Empty or blank-only input: emission never produced a trace line, so + // this is not a valid trace. Surface it so the harness records a + // TraceIssue rather than treating a crashed run as clean zero-attribution. + return nil, errors.New("parse trace: empty input (no trace emitted)") + } + if !sawTraceHeader { return nil, errors.New("parse trace: non-empty input had no type:trace header") } - if sawTraceHeader && len(t.Spans) == 0 && len(t.Counters) == 0 { + if len(t.Spans) == 0 && len(t.Counters) == 0 { return nil, errors.New("parse trace: header present but no spans or counters recovered (corrupt or truncated)") } return t, nil @@ -120,12 +140,37 @@ func parseDurationMs(v any) time.Duration { return time.Duration(f * float64(time.Millisecond)) } +// parseInt64 parses a counter value. json.Number (from UseNumber) is parsed +// directly to int64 so large counters round-trip without float64 precision +// loss; other numeric kinds fall back to a float conversion. func parseInt64(v any) int64 { - return int64(toFloat64(v)) + switch n := v.(type) { + case json.Number: + if i, err := n.Int64(); err == nil { + return i + } + if f, err := n.Float64(); err == nil { + return int64(f) + } + return 0 + case float64: + return int64(n) + case int64: + return n + case int: + return int64(n) + default: + return int64(toFloat64(v)) + } } func toFloat64(v any) float64 { switch n := v.(type) { + case json.Number: + if f, err := n.Float64(); err == nil { + return f + } + return 0 case float64: return n case int64: diff --git a/internal/trace/recorder.go b/internal/trace/recorder.go index 38d056d38..1327f97fd 100644 --- a/internal/trace/recorder.go +++ b/internal/trace/recorder.go @@ -242,12 +242,25 @@ func deriveNesting(spans []Span) { continue } // b contains a when a starts at/after b and ends at/before b. - if !a.Start.Before(b.Start) && !a.End.After(b.End) { - bd := b.End.Sub(b.Start) - if bestIdx == -1 || bd < bestDur { - bestIdx = j - bestDur = bd - } + contained := !a.Start.Before(b.Start) && !a.End.After(b.End) + if !contained { + continue + } + // Strict containment makes b an unambiguous parent of a. When the + // two intervals are identical (contained but not strictly — equality + // satisfies the check symmetrically), they would otherwise pick + // each other as parent and form a 2-cycle that drops both from + // top-level. Break that tie deterministically: only the + // lower-indexed span may parent a co-extensive higher-indexed one, + // so one stays top-level and the other nests under it. + strict := a.Start.After(b.Start) || a.End.Before(b.End) + if !strict && j >= i { + continue + } + bd := b.End.Sub(b.Start) + if bestIdx == -1 || bd < bestDur { + bestIdx = j + bestDur = bd } } parent[i] = bestIdx diff --git a/internal/trace/trace_test.go b/internal/trace/trace_test.go index bac453b7e..08507cc4d 100644 --- a/internal/trace/trace_test.go +++ b/internal/trace/trace_test.go @@ -417,3 +417,126 @@ func TestReadNDJSONRejectsHeaderOnly(t *testing.T) { t.Fatal("expected error for a trace header with no spans or counters") } } + +func TestReadNDJSONRejectsEmpty(t *testing.T) { + // Empty or blank-only input means emission never produced a trace line + // (e.g. the agent crashed before writing the header, or --trace was not + // honored). That must surface as an error so the harness records a + // TraceIssue rather than treating a crashed run as clean zero-attribution. + if _, err := ReadNDJSON(strings.NewReader("")); err == nil { + t.Fatal("expected error for empty input") + } + if _, err := ReadNDJSON(strings.NewReader("\n \n\n")); err == nil { + t.Fatal("expected error for blank-only input") + } +} + +func TestExclusiveZeroRoundTrips(t *testing.T) { + // A parent whose children exactly tile its interval has exclusive time 0. + // That 0 must survive a write-then-read round-trip — overwriting it with the + // inclusive Duration on re-parse re-introduces the double-counting the + // exclusive-time model exists to prevent. + base := time.Date(2024, 1, 1, 0, 0, 0, 0, time.UTC) + spans := []Span{ + {Name: SpanGeneration, Start: base, End: base.Add(100 * time.Millisecond), Duration: 100 * time.Millisecond}, + {Name: SpanProviderConnect, Start: base, End: base.Add(60 * time.Millisecond), Duration: 60 * time.Millisecond}, + {Name: SpanToolExecution, Start: base.Add(60 * time.Millisecond), End: base.Add(100 * time.Millisecond), Duration: 40 * time.Millisecond}, + } + deriveNesting(spans) + if spans[0].Exclusive != 0 { + t.Fatalf("setup invariant: generation exclusive = %v, want 0 (children tile it)", spans[0].Exclusive) + } + original := &TurnTrace{ + SessionID: "s", + RunID: "r", + StartedAt: base, + CompletedAt: base.Add(100 * time.Millisecond), + Spans: spans, + } + + var buf bytes.Buffer + if err := WriteNDJSON(&buf, original); err != nil { + t.Fatalf("WriteNDJSON: %v", err) + } + parsed, err := ReadNDJSON(&buf) + if err != nil { + t.Fatalf("ReadNDJSON: %v", err) + } + var parsedGenExclusive time.Duration + for _, s := range parsed.Spans { + if s.Name == SpanGeneration { + parsedGenExclusive = s.Exclusive + } + } + if parsedGenExclusive != 0 { + t.Fatalf("generation exclusive after round-trip = %v, want 0 (a written exclusive_ms:0 must be preserved, not overwritten with Duration)", parsedGenExclusive) + } + // The harness ranks by exclusive; the sum of exclusive across the run must + // equal the wall (children carry the time, the parent contributes 0), with + // no double-count. + var exclusiveSum time.Duration + for _, s := range parsed.Spans { + exclusiveSum += s.Exclusive + } + if exclusiveSum != original.WallDuration() { + t.Fatalf("exclusive sum = %v, want wall %v (double-count or gap on re-parse)", exclusiveSum, original.WallDuration()) + } +} + +func TestIdenticalIntervalsNoCycle(t *testing.T) { + // Two spans stamped at the exact same [start, end] would, under a symmetric + // containment check, pick each other as parent and form a 2-cycle, dropping + // both from top-level and zeroing AttributedDuration. The tie-break must + // keep one top-level so AttributedDuration stays correct (no cycle, no + // double-count). + base := time.Date(2024, 1, 1, 0, 0, 0, 0, time.UTC) + spans := []Span{ + {Name: SpanGeneration, Start: base, End: base.Add(100 * time.Millisecond), Duration: 100 * time.Millisecond}, + {Name: SpanProviderConnect, Start: base, End: base.Add(100 * time.Millisecond), Duration: 100 * time.Millisecond}, + } + deriveNesting(spans) + + var topLevel int + var parents []string + for _, s := range spans { + if s.Parent == "" { + topLevel++ + } else { + parents = append(parents, s.Name+"->"+s.Parent) + } + } + if topLevel == 0 { + t.Fatalf("identical intervals formed a parent cycle; no top-level spans (parents=%v)", parents) + } + if topLevel != 1 { + t.Fatalf("expected exactly one top-level span for co-extensive pair, got %d (parents=%v)", topLevel, parents) + } + // AttributedDuration is the single top-level span's duration — not 0 (cycle) + // and not 2x (siblings double-count). + tr := &TurnTrace{StartedAt: base, CompletedAt: base.Add(100 * time.Millisecond), Spans: spans} + if got := tr.AttributedDuration(); got != 100*time.Millisecond { + t.Fatalf("AttributedDuration = %v, want 100ms (one top-level span, no cycle)", got) + } +} + +func TestCounterPrecisionRoundTrip(t *testing.T) { + // Counter values decode through json.Number so an int64 above 2^53 + // round-trips exactly instead of losing precision via float64. + r := NewRecorder("s", "r", "") + r.Start() + const big = int64(1<<53 + 1) // 9007199254740993 — not representable exactly as float64 + r.Counter(CounterInputTokens, big) + tr := r.Finish() + + var buf bytes.Buffer + if err := WriteNDJSON(&buf, tr); err != nil { + t.Fatalf("WriteNDJSON: %v", err) + } + parsed, err := ReadNDJSON(&buf) + if err != nil { + t.Fatalf("ReadNDJSON: %v", err) + } + if got := parsed.Counter(CounterInputTokens); got != big { + t.Fatalf("counter round-trip = %d, want %d (float64 precision loss)", got, big) + } +} From 2bfb340668320f7d03ca20e2560f0980edf16cf7 Mon Sep 17 00:00:00 2001 From: Vasanthdev2004 Date: Thu, 16 Jul 2026 14:32:13 +0530 Subject: [PATCH 6/8] perf(turn-bench): split pass/fail into oracle tiers so the pass rate can't be misread as correctness MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The turn benchmark counted any exit-0 task as passed, including the 24 read-only tasks (nav/longproc/longctx/parallel) that carry no verification oracle — so the JSON tasksPassed / "N/M passed" headline could read as a correctness verdict it never was. Split pass/fail into three oracle tiers: - correctness (edit grep + fix go test): the only pass rate that can move with model quality (tasksVerified / tasksPassed / correctnessPassRate) - build-only (refactor go build): a non-positive oracle, reported as buildPassRate and excluded from correctnessPassRate; the manifest declares buildOnlyClasses: ["refactor"] - latency-only (no oracle): counted in latencyOnlyTasks, never in any pass rate NewTurnExecRunner no longer sets Passed=true for tasks with no verificationCommand, and the summary headline names each tier explicitly so an exit-0 read-only run cannot inflate a correctness number. Bumps TurnSchemaVersion to 2. Class breakdown and tier contract documented in internal/perfbench/MANIFEST.md and reports/README.md. Also install the trace first-token/visible-event forwarding handlers in agent.Run whenever options.Trace is set, not only when a UI OnText / OnReasoning callback is set, so a headless traced run (zero exec --trace) still captures FirstTokenAt. forwardedVisibleText stays tied to the user callback so stall-retry semantics are unchanged. Adds a regression assertion to the existing traced-run test. --- internal/agent/loop.go | 36 +++- internal/agent/loop_test.go | 7 + internal/perfbench/MANIFEST.md | 71 ++++++++ internal/perfbench/manifests/baseline.json | 3 +- internal/perfbench/reports/README.md | 23 ++- internal/perfbench/taskbench.go | 8 + internal/perfbench/turn_bench.go | 202 +++++++++++++++++---- internal/perfbench/turn_bench_test.go | 136 +++++++++++--- 8 files changed, 414 insertions(+), 72 deletions(-) create mode 100644 internal/perfbench/MANIFEST.md diff --git a/internal/agent/loop.go b/internal/agent/loop.go index cc411c2cb..69c87ecfc 100644 --- a/internal/agent/loop.go +++ b/internal/agent/loop.go @@ -284,18 +284,38 @@ func Run(ctx context.Context, prompt string, provider Provider, options Options) // conversation-state duplication. forwardedVisibleText := false forwardingOpts := zeroruntime.CollectOptions{OnUsage: options.OnUsage} - if options.OnText != nil { + // Install text/reasoning forwarding handlers whenever EITHER a user + // callback OR a trace recorder is set. A headless traced run (e.g. `zero + // exec --trace`) sets Trace but no OnText/OnReasoning; without these + // handlers the stream is still collected, but FirstTokenAt would never + // stamp and the trace would lose its TTFT signal. The trace recorder's + // stamp methods are nil-safe, but we guard on `trace != nil` so a run with + // a user callback but no recorder still works. forwardedVisibleText stays + // tied to the USER callback only, preserving the stall-retry semantics + // (a trace-only handler forwards nothing the user would see duplicated). + rec := options.Trace + onText := options.OnText + if onText != nil || rec != nil { forwardingOpts.OnText = func(s string) { - forwardedVisibleText = true - options.Trace.StampFirstVisibleEvent() - options.Trace.StampFirstToken() - options.OnText(s) + if rec != nil { + rec.StampFirstVisibleEvent() + rec.StampFirstToken() + } + if onText != nil { + forwardedVisibleText = true + onText(s) + } } } - if options.OnReasoning != nil { + onReasoning := options.OnReasoning + if onReasoning != nil || rec != nil { forwardingOpts.OnReasoning = func(s string) { - options.Trace.StampFirstToken() - options.OnReasoning(s) + if rec != nil { + rec.StampFirstToken() + } + if onReasoning != nil { + onReasoning(s) + } } } if options.OnToolCallStart != nil { diff --git a/internal/agent/loop_test.go b/internal/agent/loop_test.go index 1462078e2..dabea25c9 100644 --- a/internal/agent/loop_test.go +++ b/internal/agent/loop_test.go @@ -3488,6 +3488,13 @@ func TestRunTracingWrapperStampsUsage(t *testing.T) { if tr.StartedAt.IsZero() { t.Fatal("tracing wrapper did not Start the recorder") } + // FirstTokenAt must stamp even though no OnText/OnReasoning user callback is + // set: a headless traced run (e.g. `zero exec --trace`) sets Trace but no UI + // callbacks, so the loop installs trace-only forwarding handlers to capture + // TTFT. Without them FirstTokenAt stays zero and the trace loses its signal. + if tr.FirstTokenAt.IsZero() { + t.Fatal("FirstTokenAt not stamped for a traced run with no OnText/OnReasoning callbacks") + } if got := tr.Counter(trace.CounterInputTokens); got != 100 { t.Fatalf("input token counter = %d, want 100", got) } diff --git a/internal/perfbench/MANIFEST.md b/internal/perfbench/MANIFEST.md new file mode 100644 index 000000000..0ef90f3e7 --- /dev/null +++ b/internal/perfbench/MANIFEST.md @@ -0,0 +1,71 @@ +# Turn benchmark manifest + +The baseline manifest (`manifests/baseline.json`) is the per-turn benchmark's +program keystone: it defines the tasks the harness runs, the workspace each +starts in, and — critically — what "pass" means for each task. Because `make +baseline` is re-run on every perf change, the manifest's pass/fail contract +matters for months, so the contract is written down here. + +## Task count + +48 tasks across seven classes: + +| class | count | oracle | tier | +|-----------|-------|-----------------------------|-------------| +| nav | 10 | none | latency | +| edit | 10 | substring grep | correctness | +| fix | 8 | scoped `go test -run ` | correctness | +| refactor | 6 | `go build ./...` | build | +| longproc | 4 | none | latency | +| longctx | 4 | none | latency | +| parallel | 6 | none | latency | +| **total** | **48**| | | + +## Oracle tiers + +Pass/fail is reported per tier so the report cannot be misread as a blanket +correctness verdict. The tier is decided per task from oracle presence and the +manifest's `buildOnlyClasses` list: + +- **Correctness** (18 tasks: 10 edit + 8 fix) — a positive oracle (substring + grep that the requested change landed, or a scoped `go test -run` that the + bug fix passes). This is the only pass rate that can move with model quality: + `tasksVerified` / `tasksPassed` / `correctnessPassRate`. +- **Build-only** (6 tasks: refactor) — `go build ./...` proves the edit + compiles, not that the refactor achieved its goal (a no-op refactor passes). + The manifest declares `buildOnlyClasses: ["refactor"]`. Reported as + `buildCheckedTasks` / `buildPassedTasks` / `buildPassRate`, never in + `correctnessPassRate`. +- **Latency-only** (24 tasks: nav, longproc, longctx, parallel) — no + `verificationCommand`. An exit 0 only proves the turn ran, not that the answer + was right. They contribute to latency and span attribution only and are + counted in `latencyOnlyTasks`, never in any pass rate. + +A task's tier is driven by oracle **presence** first: a task with no +`verificationCommand` is latency-only even if its class is listed in +`buildOnlyClasses`, so a missing oracle can never silently pass on exit 0. + +## Known limitations (deferred) + +These are accepted for the Phase 0 baseline and tracked in a follow-up issue; +they do not block the baseline because the tier split keeps the report honest: + +- The edit grep oracles are substring checks. A rename oracle asserts the new + name is present AND the old name is gone (compound `bash -c`), but an + add-field oracle (`grep -R Label .`) only proves the string appears, not that + it landed on the right struct. Strengthening these to `go vet`/`go build` + + structural assertions is follow-up work. +- The refactor build oracle is non-positive (a no-op refactor passes). A + structural verifier that proves the refactor happened is follow-up work; + until then refactor is `buildPassRate`, not `correctnessPassRate`. +- The 24 read-only tasks have no oracle. Adding deterministic oracles for nav + (diff against an expected answer) and documenting longproc/longctx/parallel + as permanently latency-only is follow-up work. + +## Fixtures + +Each task's `workspaceFixture` points at a small self-contained workspace under +`testdata/` so the suite runs offline and repeatably. Mutating tasks (edit, +fix, refactor) run against a per-invocation **copy** of their fixture, so the +checked-in fixtures stay clean and one task's edits can't bleed into the next +iteration or a later task. \ No newline at end of file diff --git a/internal/perfbench/manifests/baseline.json b/internal/perfbench/manifests/baseline.json index b9e051466..3d78176fb 100644 --- a/internal/perfbench/manifests/baseline.json +++ b/internal/perfbench/manifests/baseline.json @@ -1,7 +1,8 @@ { "id": "zero-baseline-turn", "name": "Zero per-turn baseline (Phase 0)", - "description": "Latency-only baseline: measures where a turn spends wall time, not task correctness. Read-only tasks (nav, longproc, longctx, parallel) carry no verification oracle by design — a zero-exit does not prove the answer was right, only that the turn ran. Edit/fix/refactor oracles are intentionally lightweight (substring grep or `go build`) so the suite stays a latency probe; do not read pass/fail as a correctness verdict.", + "description": "Latency-first baseline: measures where a turn spends wall time, with pass/fail reported per oracle tier so it cannot be misread as a blanket correctness verdict. Read-only classes (nav, longproc, longctx, parallel) carry no verification oracle — a zero-exit only proves the turn ran, so they count as latency-only and never in any pass rate. Correctness classes (edit, fix) carry a positive oracle (substring grep or a scoped `go test`) and are the only tasks in correctnessPassRate. Build-only classes (refactor) carry `go build ./...`, which proves the edit compiles but not that the refactor achieved its goal, so they are reported as buildPassRate and excluded from correctnessPassRate.", + "buildOnlyClasses": ["refactor"], "tasks": [ {"id": "nav-01", "name": "list repo files", "class": "nav", "prompt": "List the files in this repository and report their count. Do not modify anything.", "workspaceFixture": "../testdata/nav"}, {"id": "nav-02", "name": "find a function", "class": "nav", "prompt": "Find the function named 'greet' and report the file and line it is defined on. Do not modify anything.", "workspaceFixture": "../testdata/nav"}, diff --git a/internal/perfbench/reports/README.md b/internal/perfbench/reports/README.md index 432ea10cd..8fd0a7263 100644 --- a/internal/perfbench/reports/README.md +++ b/internal/perfbench/reports/README.md @@ -39,9 +39,26 @@ spent. **Coverage** is the fraction of wall covered by the union of all span intervals (capped at 1.0) — the honest "≥95% of wall accounted for" metric. A run with `coverage < 0.95` has uninstrumented gaps, not an inflated attribution. -Note that the suite is **latency-only** (see the manifest `description`): the -top-three ranking is about latency, and pass/fail oracles are intentionally -lightweight; do not read them as a correctness verdict. + +### Pass/fail is reported per oracle tier + +Pass/fail is split into three tiers so it cannot be misread as a blanket +correctness verdict (see `MANIFEST.md` for the class breakdown): + +- **Correctness** (`tasksVerified` / `tasksPassed` / `correctnessPassRate`): + tasks with a positive oracle — edit's substring grep, fix's scoped `go test`. + This is the only pass rate that can move with model quality. +- **Build-only** (`buildCheckedTasks` / `buildPassedTasks` / `buildPassRate`): + refactor's `go build ./...`, which proves the edit compiles but not that the + refactor achieved its goal. Reported separately, never in `correctnessPassRate`. +- **Latency-only** (`latencyOnlyTasks`): the read-only classes (nav, longproc, + longctx, parallel) carry no oracle — an exit 0 only proves the turn ran. They + contribute to latency and span attribution and are excluded from every pass + rate. + +`tasksAttempted` is still the total across all three tiers. The tier class lists +are echoed in the report so a consumer can see exactly which classes each rate +is computed over. ## What to commit diff --git a/internal/perfbench/taskbench.go b/internal/perfbench/taskbench.go index 8ffcb3703..c7d32e65c 100644 --- a/internal/perfbench/taskbench.go +++ b/internal/perfbench/taskbench.go @@ -29,6 +29,14 @@ type TaskSet struct { Name string `json:"name,omitempty"` Description string `json:"description,omitempty"` Tasks []BenchTask `json:"tasks"` + // BuildOnlyClasses lists task classes whose verificationCommand is a + // non-positive build check (e.g. refactor's `go build ./...`): it proves the + // edit compiles, not that the refactor achieved its goal. The turn benchmark + // reports these separately from correctness oracles so a build-pass cannot be + // misread as a correctness pass. Classes with a verificationCommand that are + // NOT listed here are treated as correctness classes; classes whose tasks + // carry no verificationCommand are latency-only regardless of this list. + BuildOnlyClasses []string `json:"buildOnlyClasses,omitempty"` } // BenchTask is one benchmark task. WorkspaceFixture is the relative path of the diff --git a/internal/perfbench/turn_bench.go b/internal/perfbench/turn_bench.go index df674ff55..4937d0ac3 100644 --- a/internal/perfbench/turn_bench.go +++ b/internal/perfbench/turn_bench.go @@ -20,7 +20,14 @@ import ( // TurnSchemaVersion is the schema version of a published turn-benchmark result. // Bump when the TurnBenchResult shape changes so consumers can detect drift. -const TurnSchemaVersion = 1 +// +// v2 splits pass/fail into three oracle tiers so the report cannot be misread as +// a blanket correctness verdict: tasksVerified/tasksPassed/correctnessPassRate +// cover only the positive-oracle classes (edit/fix); buildCheckedTasks/ +// buildPassedTasks/buildPassRate cover the non-positive build-check classes +// (refactor); latencyOnlyTasks covers the no-oracle classes (nav/longproc/ +// longctx/parallel). tasksAttempted is still every task run. +const TurnSchemaVersion = 2 // TurnRunner runs one benchmark task and reports its outcome plus the captured // per-turn trace. A non-nil Err means the run failed to execute (process crash); @@ -80,31 +87,64 @@ type LatencySource struct { } // ClassSummary is the per-class (task group) roll-up. +// +// Passed is the count that passed THIS class's oracle: a correctness pass for +// edit/fix, a build pass for refactor, and always 0 for the no-oracle classes +// (nav/longproc/longctx/parallel). Verified is how many tasks in the class +// carry an oracle (correctness or build); LatencyOnly is how many carry none. +// A latency-only class therefore reports Passed=0, Verified=0, LatencyOnly=Tasks. type ClassSummary struct { - Tasks int `json:"tasks"` - Passed int `json:"passed"` - WallMs NumericStats `json:"wallMs"` - SpanTotals map[string]float64 `json:"spanTotals"` + Tasks int `json:"tasks"` + Verified int `json:"verified"` + Passed int `json:"passed"` + LatencyOnly int `json:"latencyOnly"` + WallMs NumericStats `json:"wallMs"` + SpanTotals map[string]float64 `json:"spanTotals"` } // TurnBenchResult is the publishable turn-benchmark record. +// +// Pass/fail is split into three oracle tiers so it cannot be misread as a +// blanket correctness verdict: +// - Correctness (tasksVerified / tasksPassed / correctnessPassRate): tasks +// with a positive oracle (edit/fix). This is the only pass rate that can +// move with model quality. +// - Build-only (buildCheckedTasks / buildPassedTasks / buildPassRate): tasks +// whose oracle is a non-positive build check (refactor `go build`). A pass +// means it compiles, not that the refactor is correct. +// - Latency-only (latencyOnlyTasks): tasks with no oracle (nav/longproc/ +// longctx/parallel). They ran for latency and span attribution only and are +// excluded from every pass rate. +// +// tasksAttempted is still the total number of tasks run across all three tiers. +// The tier class lists are echoed so a consumer can see exactly which classes +// each rate is computed over. type TurnBenchResult struct { - SchemaVersion int `json:"schemaVersion"` - Suite string `json:"suite"` - Model string `json:"model"` - Mode string `json:"mode,omitempty"` - SelfCorrect bool `json:"selfCorrect"` - Version string `json:"version,omitempty"` - Commit string `json:"commit,omitempty"` - Date string `json:"date"` - TasksAttempted int `json:"tasksAttempted"` - TasksPassed int `json:"tasksPassed"` - Iterations int `json:"iterations"` - PerSpan map[string]SpanStats `json:"perSpan"` - TopLatency []LatencySource `json:"topLatency"` - PerClass map[string]ClassSummary `json:"perClass"` - Totals TurnBenchTotals `json:"totals"` - Warnings []Warning `json:"warnings,omitempty"` + SchemaVersion int `json:"schemaVersion"` + Suite string `json:"suite"` + Model string `json:"model"` + Mode string `json:"mode,omitempty"` + SelfCorrect bool `json:"selfCorrect"` + Version string `json:"version,omitempty"` + Commit string `json:"commit,omitempty"` + Date string `json:"date"` + TasksAttempted int `json:"tasksAttempted"` + TasksVerified int `json:"tasksVerified"` + TasksPassed int `json:"tasksPassed"` + LatencyOnlyTasks int `json:"latencyOnlyTasks"` + BuildCheckedTasks int `json:"buildCheckedTasks"` + BuildPassedTasks int `json:"buildPassedTasks"` + CorrectnessPassRate float64 `json:"correctnessPassRate"` + BuildPassRate float64 `json:"buildPassRate,omitempty"` + CorrectnessClasses []string `json:"correctnessClasses,omitempty"` + BuildOnlyClasses []string `json:"buildOnlyClasses,omitempty"` + LatencyOnlyClasses []string `json:"latencyOnlyClasses,omitempty"` + Iterations int `json:"iterations"` + PerSpan map[string]SpanStats `json:"perSpan"` + TopLatency []LatencySource `json:"topLatency"` + PerClass map[string]ClassSummary `json:"perClass"` + Totals TurnBenchTotals `json:"totals"` + Warnings []Warning `json:"warnings,omitempty"` } // TurnBenchTotals aggregates token and count totals across the whole run. @@ -148,9 +188,25 @@ func RunTurnBench(ctx context.Context, set TaskSet, cfg TurnBenchConfig) (TurnBe classWalls := map[string][]float64{} classSpanTotals := map[string]map[string]float64{} classTasks := map[string]int{} + classVerified := map[string]int{} classPassed := map[string]int{} + classLatencyOnly := map[string]int{} + correctnessClasses := map[string]bool{} + buildOnlyClasses := map[string]bool{} + latencyOnlyClasses := map[string]bool{} var totals TurnBenchTotals + // A class is build-only when the manifest declares it in BuildOnlyClasses. + // A task's tier is then decided per-task: no verificationCommand => latency- + // only; otherwise build-only if its class is declared, else correctness. The + // latency-only tier is always driven by oracle presence, never by the + // declared list, so a declared build-only class with a missing oracle still + // counts as latency-only rather than silently passing on exit 0. + buildOnly := map[string]bool{} + for _, c := range set.BuildOnlyClasses { + buildOnly[strings.TrimSpace(c)] = true + } + result := TurnBenchResult{ SchemaVersion: TurnSchemaVersion, Suite: strings.TrimSpace(set.ID), @@ -223,9 +279,33 @@ func RunTurnBench(ctx context.Context, set TaskSet, cfg TurnBenchConfig) (TurnBe } } result.TasksAttempted++ - if passedForTask { - result.TasksPassed++ - classPassed[class]++ + + // Classify the task into an oracle tier and update only that tier's + // counters. A latency-only task (no verificationCommand) is never counted + // in any pass rate even when the runner reports Passed — an exit-0 + // read-only run proves the turn ran, not that the answer was right. + hasOracle := len(task.VerificationCommand) > 0 + switch { + case !hasOracle: + result.LatencyOnlyTasks++ + classLatencyOnly[class]++ + latencyOnlyClasses[class] = true + case buildOnly[class]: + result.BuildCheckedTasks++ + classVerified[class]++ + buildOnlyClasses[class] = true + if passedForTask { + result.BuildPassedTasks++ + classPassed[class]++ + } + default: + result.TasksVerified++ + classVerified[class]++ + correctnessClasses[class] = true + if passedForTask { + result.TasksPassed++ + classPassed[class]++ + } } } @@ -240,16 +320,44 @@ func RunTurnBench(ctx context.Context, set TaskSet, cfg TurnBenchConfig) (TurnBe wallStats = SummarizeSamples(walls) } result.PerClass[class] = ClassSummary{ - Tasks: classTasks[class], - Passed: classPassed[class], - WallMs: wallStats, - SpanTotals: classSpanTotals[class], + Tasks: classTasks[class], + Verified: classVerified[class], + Passed: classPassed[class], + LatencyOnly: classLatencyOnly[class], + WallMs: wallStats, + SpanTotals: classSpanTotals[class], } } + result.CorrectnessClasses = sortedSetKeys(correctnessClasses) + result.BuildOnlyClasses = sortedSetKeys(buildOnlyClasses) + result.LatencyOnlyClasses = sortedSetKeys(latencyOnlyClasses) + result.CorrectnessPassRate = passRate(result.TasksPassed, result.TasksVerified) + result.BuildPassRate = passRate(result.BuildPassedTasks, result.BuildCheckedTasks) result.Totals = totals return result, nil } +// passRate is passed/total rounded to the benchmark's metric precision, or 0 +// when the denominator is zero (no tasks in that tier were run). +func passRate(passed, total int) float64 { + if total <= 0 { + return 0 + } + return RoundMetric(float64(passed) / float64(total)) +} + +func sortedSetKeys(set map[string]bool) []string { + if len(set) == 0 { + return nil + } + keys := make([]string, 0, len(set)) + for k := range set { + keys = append(keys, k) + } + sort.Strings(keys) + return keys +} + func summarizeSpan(samples []float64) SpanStats { if len(samples) == 0 { return SpanStats{} @@ -315,7 +423,15 @@ func FormatTurnBenchSummary(result TurnBenchResult) string { lines := []string{ "Zero turn benchmark: " + displayOrUnknown(result.Suite), "model: " + displayOrUnknown(result.Model), - fmt.Sprintf("tasks: %d/%d passed across %d iteration(s)", result.TasksPassed, result.TasksAttempted, result.Iterations), + // The headline separates the three oracle tiers so an exit-0 read-only + // task can never inflate a "pass rate" that reads as correctness: + // correctness (positive oracle, edit/fix), build (non-positive `go build`, + // refactor), and latency-only (no oracle, nav/longproc/longctx/parallel). + fmt.Sprintf("tasks: %d total | correctness %d/%d (%.0f%%) | build %d/%d (%.0f%%) | latency-only %d | %d iter", + result.TasksAttempted, + result.TasksPassed, result.TasksVerified, result.CorrectnessPassRate*100, + result.BuildPassedTasks, result.BuildCheckedTasks, result.BuildPassRate*100, + result.LatencyOnlyTasks, result.Iterations), } if result.Mode != "" { lines = append(lines, "mode: "+result.Mode) @@ -333,11 +449,30 @@ func FormatTurnBenchSummary(result TurnBenchResult) string { for _, class := range sortedClasses(result.PerClass) { summary := result.PerClass[class] median := FormatMetric(summary.WallMs.Median, "ms") - lines = append(lines, fmt.Sprintf(" [%s] %d/%d passed, wall median %s", class, summary.Passed, summary.Tasks, median)) + tier := classTier(result, class) + lines = append(lines, fmt.Sprintf(" [%s/%s] %d/%d passed, %d latency-only, wall median %s", + class, tier, summary.Passed, summary.Verified, summary.LatencyOnly, median)) } return strings.Join(lines, "\n") } +// classTier returns the oracle tier label a class was classified into, so the +// per-class roll-up states explicitly which oracle (if any) its "passed" count +// is measured against. +func classTier(result TurnBenchResult, class string) string { + for _, c := range result.BuildOnlyClasses { + if c == class { + return "build" + } + } + for _, c := range result.LatencyOnlyClasses { + if c == class { + return "latency" + } + } + return "correctness" +} + func sortedClasses(perClass map[string]ClassSummary) []string { classes := make([]string, 0, len(perClass)) for c := range perClass { @@ -435,8 +570,13 @@ func NewTurnExecRunner(binary string, extraArgs ...string) TurnRunner { outcome.VerifyErr = strings.TrimSpace(vOutcome.Detail) return outcome } + // A positive oracle (grep/test/build) passed: this is the only path + // that sets Passed. A task with no verificationCommand is latency-only + // (read-only nav/longproc/longctx/parallel): its exit 0 proves the turn + // ran, not that the answer was right, so it never reports Passed and the + // harness counts it in latencyOnlyTasks rather than any pass rate. + outcome.Passed = true } - outcome.Passed = true return outcome } } diff --git a/internal/perfbench/turn_bench_test.go b/internal/perfbench/turn_bench_test.go index 53275fce7..2c364fcd2 100644 --- a/internal/perfbench/turn_bench_test.go +++ b/internal/perfbench/turn_bench_test.go @@ -54,15 +54,18 @@ func TestRunTurnBenchAggregation(t *testing.T) { set := TaskSet{ ID: "fake-suite", Tasks: []BenchTask{ - {ID: "t1", Class: "nav", Prompt: "p1"}, - {ID: "t2", Class: "nav", Prompt: "p2"}, - {ID: "t3", Class: "edit", Prompt: "p3"}, + {ID: "t1", Class: "nav", Prompt: "p1"}, // latency-only + {ID: "t2", Class: "nav", Prompt: "p2"}, // latency-only + {ID: "t3", Class: "edit", Prompt: "p3", VerificationCommand: []string{"true"}}, // correctness + {ID: "t4", Class: "refactor", Prompt: "p4", VerificationCommand: []string{"true"}}, // build-only }, + BuildOnlyClasses: []string{"refactor"}, } canned := map[string]*trace.TurnTrace{ "t1": cannedTrace(100, 10, 1000), "t2": cannedTrace(300, 10, 1000), "t3": cannedTrace(200, 50, 2000), + "t4": cannedTrace(150, 20, 1500), } cfg := TurnBenchConfig{ Model: "fake-model", @@ -74,8 +77,33 @@ func TestRunTurnBenchAggregation(t *testing.T) { if err != nil { t.Fatalf("RunTurnBench: %v", err) } - if result.TasksAttempted != 3 || result.TasksPassed != 3 { - t.Fatalf("attempted=%d passed=%d, want 3/3", result.TasksAttempted, result.TasksPassed) + // 4 tasks attempted; the tier split is 2 latency-only, 1 correctness, 1 build. + if result.TasksAttempted != 4 { + t.Fatalf("attempted=%d, want 4", result.TasksAttempted) + } + if result.TasksVerified != 1 || result.TasksPassed != 1 { + t.Fatalf("correctness verified=%d passed=%d, want 1/1", result.TasksVerified, result.TasksPassed) + } + if result.LatencyOnlyTasks != 2 { + t.Fatalf("latencyOnly=%d, want 2", result.LatencyOnlyTasks) + } + if result.BuildCheckedTasks != 1 || result.BuildPassedTasks != 1 { + t.Fatalf("build checked=%d passed=%d, want 1/1", result.BuildCheckedTasks, result.BuildPassedTasks) + } + if result.CorrectnessPassRate != 1.0 { + t.Fatalf("correctnessPassRate=%v, want 1.0", result.CorrectnessPassRate) + } + if result.BuildPassRate != 1.0 { + t.Fatalf("buildPassRate=%v, want 1.0", result.BuildPassRate) + } + if len(result.CorrectnessClasses) != 1 || result.CorrectnessClasses[0] != "edit" { + t.Fatalf("correctnessClasses=%v, want [edit]", result.CorrectnessClasses) + } + if len(result.BuildOnlyClasses) != 1 || result.BuildOnlyClasses[0] != "refactor" { + t.Fatalf("buildOnlyClasses=%v, want [refactor]", result.BuildOnlyClasses) + } + if len(result.LatencyOnlyClasses) != 1 || result.LatencyOnlyClasses[0] != "nav" { + t.Fatalf("latencyOnlyClasses=%v, want [nav]", result.LatencyOnlyClasses) } if result.SchemaVersion != TurnSchemaVersion { t.Fatalf("schemaVersion = %d, want %d", result.SchemaVersion, TurnSchemaVersion) @@ -84,21 +112,21 @@ func TestRunTurnBenchAggregation(t *testing.T) { t.Fatalf("date = %q", result.Date) } - // Per-span: generation appears in all three (100+300+200=600ms), tool in all - // three (10+10+50=70ms). Count must equal the number of tasks * iterations. + // Per-span: generation appears in all four (100+300+200+150=750ms), tool in + // all four (10+10+50+20=90ms). Count must equal the number of tasks * iterations. gen := result.PerSpan[trace.SpanGeneration] - if gen.Count != 3 { - t.Fatalf("generation count = %d, want 3", gen.Count) + if gen.Count != 4 { + t.Fatalf("generation count = %d, want 4", gen.Count) } - if gen.TotalMs != 600 { - t.Fatalf("generation totalMs = %v, want 600", gen.TotalMs) + if gen.TotalMs != 750 { + t.Fatalf("generation totalMs = %v, want 750", gen.TotalMs) } tool := result.PerSpan[trace.SpanToolExecution] - if tool.TotalMs != 70 { - t.Fatalf("tool totalMs = %v, want 70", tool.TotalMs) + if tool.TotalMs != 90 { + t.Fatalf("tool totalMs = %v, want 90", tool.TotalMs) } - // Top latency: generation (600) ranks above tool (70). Exactly two spans + // Top latency: generation (750) ranks above tool (90). Exactly two spans // here, so both appear and generation is first. if len(result.TopLatency) != 2 || result.TopLatency[0].Span != trace.SpanGeneration { t.Fatalf("topLatency = %+v", result.TopLatency) @@ -107,29 +135,70 @@ func TestRunTurnBenchAggregation(t *testing.T) { t.Fatalf("top latency not ranked by share: %+v", result.TopLatency) } - // Totals: 3 model requests, 3 tool calls, input tokens 1000+1000+2000=4000. - if result.Totals.ModelRequests != 3 { - t.Fatalf("modelRequests = %d, want 3", result.Totals.ModelRequests) + // Totals: 4 model requests, 4 tool calls, input tokens 1000+1000+2000+1500=5500. + if result.Totals.ModelRequests != 4 { + t.Fatalf("modelRequests = %d, want 4", result.Totals.ModelRequests) } - if result.Totals.ToolCalls != 3 { - t.Fatalf("toolCalls = %d, want 3", result.Totals.ToolCalls) + if result.Totals.ToolCalls != 4 { + t.Fatalf("toolCalls = %d, want 4", result.Totals.ToolCalls) } - if result.Totals.InputTokens != 4000 { - t.Fatalf("inputTokens = %d, want 4000", result.Totals.InputTokens) + if result.Totals.InputTokens != 5500 { + t.Fatalf("inputTokens = %d, want 5500", result.Totals.InputTokens) } - if result.Totals.OutputTokens != 2000 { - t.Fatalf("outputTokens = %d, want 2000", result.Totals.OutputTokens) + if result.Totals.OutputTokens != 2750 { + t.Fatalf("outputTokens = %d, want 2750", result.Totals.OutputTokens) } - // Per-class: nav has two tasks, edit has one; both fully passed. + // Per-class tier roll-up: nav is latency-only (0 verified, 2 latency-only), + // edit is correctness (1/1 verified passed), refactor is build (1/1 passed). nav := result.PerClass["nav"] - if nav.Tasks != 2 || nav.Passed != 2 { + if nav.Tasks != 2 || nav.Verified != 0 || nav.Passed != 0 || nav.LatencyOnly != 2 { t.Fatalf("nav class = %+v", nav) } edit := result.PerClass["edit"] - if edit.Tasks != 1 || edit.Passed != 1 { + if edit.Tasks != 1 || edit.Verified != 1 || edit.Passed != 1 || edit.LatencyOnly != 0 { t.Fatalf("edit class = %+v", edit) } + refactor := result.PerClass["refactor"] + if refactor.Tasks != 1 || refactor.Verified != 1 || refactor.Passed != 1 || refactor.LatencyOnly != 0 { + t.Fatalf("refactor class = %+v", refactor) + } +} + +// TestRunTurnBenchLatencyOnlyNeverPassed asserts the honesty gate: a task with +// no verificationCommand reports Passed=true from the (stub) runner, yet the +// harness counts it ONLY in latencyOnlyTasks — never in tasksPassed or any pass +// rate — so an exit-0 read-only run cannot inflate a correctness number. +func TestRunTurnBenchLatencyOnlyNeverPassed(t *testing.T) { + set := TaskSet{ + ID: "lo-suite", + Tasks: []BenchTask{ + {ID: "n1", Class: "nav", Prompt: "p"}, // no oracle — runner still says Passed=true + }, + } + cfg := TurnBenchConfig{ + Model: "fake-model", + Runner: fakeTurnRunner(map[string]*trace.TurnTrace{"n1": cannedTrace(50, 5, 100)}), + Now: func() time.Time { return time.Date(2026, 1, 2, 3, 4, 5, 0, time.UTC) }, + } + result, err := RunTurnBench(context.Background(), set, cfg) + if err != nil { + t.Fatalf("RunTurnBench: %v", err) + } + if result.TasksPassed != 0 || result.TasksVerified != 0 { + t.Fatalf("latency-only leaked into pass: passed=%d verified=%d, want 0/0", + result.TasksPassed, result.TasksVerified) + } + if result.CorrectnessPassRate != 0 || result.BuildPassRate != 0 { + t.Fatalf("pass rates should be 0 with no oracle tasks: c=%v b=%v", + result.CorrectnessPassRate, result.BuildPassRate) + } + if result.LatencyOnlyTasks != 1 { + t.Fatalf("latencyOnlyTasks=%d, want 1", result.LatencyOnlyTasks) + } + if result.PerClass["nav"].Passed != 0 || result.PerClass["nav"].LatencyOnly != 1 { + t.Fatalf("nav class = %+v, want passed=0 latencyOnly=1", result.PerClass["nav"]) + } } func TestRunTurnBenchIterationsAggregates(t *testing.T) { @@ -196,7 +265,9 @@ func TestTopLatencySourcesRanksByTotalAndCapsTopN(t *testing.T) { } func TestWriteTurnBenchJSONRoundTrip(t *testing.T) { - set := TaskSet{ID: "json-suite", Tasks: []BenchTask{{ID: "t1", Class: "nav", Prompt: "p1"}}} + set := TaskSet{ID: "json-suite", Tasks: []BenchTask{ + {ID: "t1", Class: "edit", Prompt: "p1", VerificationCommand: []string{"true"}}, + }} canned := map[string]*trace.TurnTrace{"t1": cannedTrace(150, 20, 800)} result, err := RunTurnBench(context.Background(), set, TurnBenchConfig{ Model: "fake-model", @@ -214,8 +285,15 @@ func TestWriteTurnBenchJSONRoundTrip(t *testing.T) { if err := json.Unmarshal(buf.Bytes(), &decoded); err != nil { t.Fatalf("unmarshal: %v\n%s", err, buf.String()) } - if decoded.SchemaVersion != TurnSchemaVersion || decoded.TasksPassed != 1 { - t.Fatalf("decoded = %+v", decoded) + if decoded.SchemaVersion != TurnSchemaVersion { + t.Fatalf("schemaVersion = %d, want %d", decoded.SchemaVersion, TurnSchemaVersion) + } + if decoded.TasksVerified != 1 || decoded.TasksPassed != 1 || decoded.LatencyOnlyTasks != 0 { + t.Fatalf("decoded tier counts = verified=%d passed=%d latency=%d, want 1/1/0", + decoded.TasksVerified, decoded.TasksPassed, decoded.LatencyOnlyTasks) + } + if decoded.CorrectnessPassRate != 1.0 { + t.Fatalf("decoded correctnessPassRate = %v, want 1.0", decoded.CorrectnessPassRate) } if decoded.PerSpan[trace.SpanGeneration].TotalMs != 150 { t.Fatalf("decoded generation totalMs = %v, want 150", decoded.PerSpan[trace.SpanGeneration].TotalMs) From d061524989509d5732a9daba470de4066126b60a Mon Sep 17 00:00:00 2001 From: Vasanthdev2004 Date: Thu, 16 Jul 2026 14:46:42 +0530 Subject: [PATCH 7/8] Address CodeRabbit review on 2bfb3406: omitempty + crash visibility Three findings from CodeRabbit's review of the 3-tier pass-rate fix: - BuildPassRate dropped its omitempty so an explicit 0.0 (all refactor tasks fail to compile) is no longer indistinguishable from 'no build tasks ran' in the JSON. Matches CorrectnessPassRate's always-serialize behavior, which is the whole point of the tier split: the report cannot be misread. - A crashed sample (outcome.Err) now emits a Warning mirroring the TraceIssue path, so a run that died every iteration can't look like a normal benchmark with fewer measurements instead of a failure. - cmd.Run()'s returned error is preserved on the no-run_end path: when stderr is empty and Run failed (binary missing, exec permission denied), the actual OS error is reported instead of collapsing to the generic 'missing terminal run_end event'. go build/vet/gofmt clean; go test -race green for perfbench/agent/trace. --- internal/perfbench/turn_bench.go | 16 ++++++++++++++-- 1 file changed, 14 insertions(+), 2 deletions(-) diff --git a/internal/perfbench/turn_bench.go b/internal/perfbench/turn_bench.go index 4937d0ac3..a506dfe81 100644 --- a/internal/perfbench/turn_bench.go +++ b/internal/perfbench/turn_bench.go @@ -135,7 +135,7 @@ type TurnBenchResult struct { BuildCheckedTasks int `json:"buildCheckedTasks"` BuildPassedTasks int `json:"buildPassedTasks"` CorrectnessPassRate float64 `json:"correctnessPassRate"` - BuildPassRate float64 `json:"buildPassRate,omitempty"` + BuildPassRate float64 `json:"buildPassRate"` CorrectnessClasses []string `json:"correctnessClasses,omitempty"` BuildOnlyClasses []string `json:"buildOnlyClasses,omitempty"` LatencyOnlyClasses []string `json:"latencyOnlyClasses,omitempty"` @@ -243,6 +243,13 @@ func RunTurnBench(ctx context.Context, set TaskSet, cfg TurnBenchConfig) (TurnBe }) } if outcome.Err != nil { + // A crashed run must not look like a normal sample that's merely + // absent — surface it as a warning so a run that died every + // iteration can't pass as "fewer measurements." + result.Warnings = append(result.Warnings, Warning{ + Metric: "run", + Message: fmt.Sprintf("task %s: %v", task.ID, outcome.Err), + }) passedForTask = false continue } @@ -530,7 +537,6 @@ func NewTurnExecRunner(binary string, extraArgs ...string) TurnRunner { start := time.Now() runErr := cmd.Run() wallMs := float64(time.Since(start).Microseconds()) / 1000 - _ = runErr exitCode, haveExit := streamJSONExitCode(outBuf.Bytes()) outcome := TurnTaskOutcome{WallMs: wallMs} @@ -538,6 +544,12 @@ func NewTurnExecRunner(binary string, extraArgs ...string) TurnRunner { outcome.VerifyErr = fmt.Sprintf("agent run_end exit code %d", exitCode) } else if !haveExit { detail := strings.TrimSpace(errBuf.String()) + // If the process never produced a run_end event, the actual failure + // is in runErr (binary missing, exec permission denied, etc.) — + // prefer it over the generic fallback so the real reason survives. + if detail == "" && runErr != nil { + detail = runErr.Error() + } if detail == "" { detail = "missing terminal run_end event" } From c4de52a5c505cc41238893c6bf368e852fd50283 Mon Sep 17 00:00:00 2001 From: Vasanthdev2004 Date: Thu, 16 Jul 2026 14:52:24 +0530 Subject: [PATCH 8/8] Address CodeRabbit re-review: anti-averaging README + fixture-isolation test Re-review at d0615249 asked for the pass-rate contract to be loud to downstream consumers and for the fixture-isolation property to be asserted, not just read from code. - reports/README.md gains a prominent 'do not average the tier pass rates / do not report a single pass rate' warning. The schema offers no headline pass rate on purpose; a consumer must name the tier it is reporting. This is the durability fix for the misread the tier split exists to prevent. - turn_bench_test.go gains TestCopyFixtureIsolatesSourceFromMutation: copies a fixture, mutates the copy, and asserts the source is byte-identical (and that a file added to the copy never appears in the source). Proves the 'fixtures stay clean across runs' property without needing the binary. Items the re-review also raised that were already satisfied: the oracle-presence-over-declared-list precedence is documented on the BuildOnlyClasses field (taskbench.go), and the PR body already says '48-task manifest'. The Share->exclusiveShare rename is tracked in #701. go build/vet/gofmt clean; go test -race green for perfbench. --- internal/perfbench/reports/README.md | 8 ++++ internal/perfbench/turn_bench_test.go | 59 +++++++++++++++++++++++++++ 2 files changed, 67 insertions(+) diff --git a/internal/perfbench/reports/README.md b/internal/perfbench/reports/README.md index 8fd0a7263..13f2dea5e 100644 --- a/internal/perfbench/reports/README.md +++ b/internal/perfbench/reports/README.md @@ -60,6 +60,14 @@ correctness verdict (see `MANIFEST.md` for the class breakdown): are echoed in the report so a consumer can see exactly which classes each rate is computed over. +> **Do not average the tier pass rates. Do not report a single "pass rate".** +> `correctnessPassRate` and `buildPassRate` measure different things over +> different task sets and must never be combined — a weighted or arithmetic +> mean of the two is a number that means nothing. The schema offers no +> headline pass rate on purpose: a consumer must name the tier it is reporting +> (`correctness`, `build`, or `latency-only`) and quote that tier's fields. A +> read-only run that exits 0 is a latency sample, not a pass. + ## What to commit Commit the manifest and fixtures (`manifests/`, `../testdata/`), not a generated diff --git a/internal/perfbench/turn_bench_test.go b/internal/perfbench/turn_bench_test.go index 2c364fcd2..bd5250ddb 100644 --- a/internal/perfbench/turn_bench_test.go +++ b/internal/perfbench/turn_bench_test.go @@ -394,3 +394,62 @@ func approxEqual(a, b, tol float64) bool { } return d < tol } + +// TestCopyFixtureIsolatesSourceFromMutation asserts the property that lets a +// mutating task run twice (or across iterations) without poisoning the next +// sample: the runner operates on a per-invocation copy, so mutating the copy +// leaves the checked-in source fixture byte-identical. This is verified by +// reading the code today; a test makes it durable against future refactors of +// the runner's isolation path. +func TestCopyFixtureIsolatesSourceFromMutation(t *testing.T) { + src, err := os.MkdirTemp("", "zero-fixture-src-*") + if err != nil { + t.Fatalf("mkdtemp src: %v", err) + } + defer os.RemoveAll(src) + orig := "package main\n\nfunc main() {}\n" + if err := os.WriteFile(filepath.Join(src, "main.go"), []byte(orig), 0o644); err != nil { + t.Fatalf("write fixture: %v", err) + } + if err := os.MkdirAll(filepath.Join(src, "sub"), 0o755); err != nil { + t.Fatalf("mkdir sub: %v", err) + } + if err := os.WriteFile(filepath.Join(src, "sub", "a.go"), []byte("package sub\n"), 0o644); err != nil { + t.Fatalf("write sub: %v", err) + } + + // Snapshot the source tree before any mutation of the copy. + wantMain, err := os.ReadFile(filepath.Join(src, "main.go")) + if err != nil { + t.Fatalf("read source main.go: %v", err) + } + + copyDir, err := copyFixture(src) + if err != nil { + t.Fatalf("copyFixture: %v", err) + } + defer os.RemoveAll(copyDir) + + // The copy must be a real copy, not a symlink/alias of the source, and + // mutating it must not touch the source. + if copyDir == src { + t.Fatalf("copyFixture returned the source dir, not a copy: %s", copyDir) + } + if err := os.WriteFile(filepath.Join(copyDir, "main.go"), []byte("package main\n\n// mutated\nfunc main() {}\n"), 0o644); err != nil { + t.Fatalf("mutate copy: %v", err) + } + if err := os.WriteFile(filepath.Join(copyDir, "new.go"), []byte("package main\n"), 0o644); err != nil { + t.Fatalf("add file to copy: %v", err) + } + + gotMain, err := os.ReadFile(filepath.Join(src, "main.go")) + if err != nil { + t.Fatalf("re-read source main.go: %v", err) + } + if string(gotMain) != string(wantMain) { + t.Fatalf("source fixture mutated by copy: got %q, want %q", gotMain, wantMain) + } + if _, err := os.Stat(filepath.Join(src, "new.go")); !os.IsNotExist(err) { + t.Fatalf("file added to copy appeared in source: %v", err) + } +}