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..a2896fcdb 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" ) @@ -430,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 } @@ -479,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.go b/internal/agent/loop.go index 2ea4ac0bd..69c87ecfc 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. + toolPartitionSpan := options.Trace.Span(trace.SpanToolPartition) exposed, _ := partitionToolsCached(registry, permissionMode, options, loaded, toolDefCache) + toolPartitionSpan.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, @@ -255,11 +284,39 @@ 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 { - forwardingOpts.OnText = func(s string) { forwardedVisibleText = true; options.OnText(s) } + // 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) { + if rec != nil { + rec.StampFirstVisibleEvent() + rec.StampFirstToken() + } + if onText != nil { + forwardedVisibleText = true + onText(s) + } + } } - if options.OnReasoning != nil { - forwardingOpts.OnReasoning = func(s string) { options.OnReasoning(s) } + onReasoning := options.OnReasoning + if onReasoning != nil || rec != nil { + forwardingOpts.OnReasoning = func(s string) { + if rec != nil { + rec.StampFirstToken() + } + if onReasoning != nil { + onReasoning(s) + } + } } if options.OnToolCallStart != nil { forwardingOpts.OnToolCallStart = func(id, name string) { options.OnToolCallStart(id, name) } @@ -297,14 +354,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 +418,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 +522,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 +552,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 +613,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 +737,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 +836,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 +844,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 +1948,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/loop_test.go b/internal/agent/loop_test.go index 97647258b..dabea25c9 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,73 @@ 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") + } + // 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) + } + 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/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/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/agent/types.go b/internal/agent/types.go index 1b12e0c78..465d4a0fd 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,16 @@ 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. + // 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 // 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..cddefadb5 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 { @@ -422,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, @@ -474,6 +487,24 @@ 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 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 := writeTraceSnapshot(traceSnapshot, tracePath, stderr); err != nil { + fmt.Fprintf(stderr, "[zero] failed to write trace: %s\n", err) + } + }() + } writer := execEventWriter{ stdout: stdout, stderr: stderr, @@ -556,6 +587,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, @@ -625,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 @@ -1237,3 +1275,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 "" +} + +// 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 + } + if strings.TrimSpace(dest) == "-" { + return trace.WriteNDJSON(stderr, snapshot) + } + file, err := os.Create(dest) + if err != nil { + return err + } + defer file.Close() + return trace.WriteNDJSON(file, snapshot) +} 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/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 new file mode 100644 index 000000000..3d78176fb --- /dev/null +++ b/internal/perfbench/manifests/baseline.json @@ -0,0 +1,62 @@ +{ + "id": "zero-baseline-turn", + "name": "Zero per-turn baseline (Phase 0)", + "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"}, + {"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": ["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": ["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": ["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", "."]}, + + {"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 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 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", "./..."]}, + + {"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..13f2dea5e --- /dev/null +++ b/internal/perfbench/reports/README.md @@ -0,0 +1,84 @@ +# 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: + +```sh +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 **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. + +### 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. + +> **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 +`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) 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/taskbench.go b/internal/perfbench/taskbench.go index 19bb8a347..c7d32e65c 100644 --- a/internal/perfbench/taskbench.go +++ b/internal/perfbench/taskbench.go @@ -25,17 +25,29 @@ 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"` + // 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 // 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/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/fix/bugs.go b/internal/perfbench/testdata/fix/bugs.go new file mode 100644 index 000000000..81a4830a2 --- /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 wrong prefix +// ("admin-" instead of "user-"), producing the wrong text. +func Label(name string) string { + return fmt.Sprintf("admin-%s", 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..10f8697ec --- /dev/null +++ b/internal/perfbench/testdata/longproc/main_test.go @@ -0,0 +1,21 @@ +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) + } +} + +func BenchmarkProcess(b *testing.B) { + var sink int + for i := 0; i < b.N; i++ { + sink = Process(100) + } + benchSink = sink +} 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..a506dfe81 --- /dev/null +++ b/internal/perfbench/turn_bench.go @@ -0,0 +1,679 @@ +package perfbench + +import ( + "bytes" + "context" + "encoding/json" + "errors" + "fmt" + "io" + "io/fs" + "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. +// +// 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); +// 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 + // 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. +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 +// 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"` + Share float64 `json:"share"` +} + +// 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"` + 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"` + 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"` + 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. +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{} + 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), + 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]++ + // 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 { + // 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 + } + if !outcome.Passed { + passedForTask = false + } + 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 { + // 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. + // 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{} + } + classSpanTotals[class][span.Name] += ms + } + } + } + result.TasksAttempted++ + + // 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]++ + } + } + } + + 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], + 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{} + } + 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), + // 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) + } + 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") + 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 { + 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 { + // 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)} + } + _ = 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 + + 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 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" + } + outcome.Err = fmt.Errorf("zero exec failed: %s", detail) + return outcome + } + + // 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 + } + } + + // 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) + 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 + } + return outcome + } +} + +// 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 != "" { + 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..bd5250ddb --- /dev/null +++ b/internal/perfbench/turn_bench_test.go @@ -0,0 +1,455 @@ +package perfbench + +import ( + "bytes" + "context" + "encoding/json" + "os" + "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"}, // 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", + 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) + } + // 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) + } + if result.Date != "2026-01-02T03:04:05Z" { + t.Fatalf("date = %q", result.Date) + } + + // 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 != 4 { + t.Fatalf("generation count = %d, want 4", gen.Count) + } + if gen.TotalMs != 750 { + t.Fatalf("generation totalMs = %v, want 750", gen.TotalMs) + } + tool := result.PerSpan[trace.SpanToolExecution] + if tool.TotalMs != 90 { + t.Fatalf("tool totalMs = %v, want 90", tool.TotalMs) + } + + // 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) + } + if result.TopLatency[0].Share <= result.TopLatency[1].Share { + t.Fatalf("top latency not ranked by share: %+v", result.TopLatency) + } + + // 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 != 4 { + t.Fatalf("toolCalls = %d, want 4", result.Totals.ToolCalls) + } + if result.Totals.InputTokens != 5500 { + t.Fatalf("inputTokens = %d, want 5500", result.Totals.InputTokens) + } + if result.Totals.OutputTokens != 2750 { + t.Fatalf("outputTokens = %d, want 2750", result.Totals.OutputTokens) + } + + // 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.Verified != 0 || nav.Passed != 0 || nav.LatencyOnly != 2 { + t.Fatalf("nav class = %+v", nav) + } + edit := result.PerClass["edit"] + 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) { + 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: "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", + 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 { + 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) + } +} + +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, + // 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) + } + 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) + } + 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) + } + } +} + +func approxEqual(a, b, tol float64) bool { + d := a - b + if d < 0 { + d = -d + } + 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) + } +} 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..374269f65 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" ) @@ -371,9 +372,15 @@ func ScanSSEDataWithContext( // 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/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..a1e1a70ed --- /dev/null +++ b/internal/trace/emit.go @@ -0,0 +1,193 @@ +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 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 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 + } + 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()), + "coverage": round3(t.Coverage()), + "attribution": round3(t.AttributionRatio()), + }); err != nil { + return err + } + + spans := append([]Span(nil), t.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) + }) + for _, span := range spans { + 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 + } + } + + 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 +// 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 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() { + write(" first_visible_event=%s (+%s)\n", formatTime(t.FirstVisibleEventAt), t.FirstVisibleEventAt.Sub(t.StartedAt)) + } + if !t.FirstUsefulActionAt.IsZero() { + write(" first_useful_action=%s (+%s)\n", formatTime(t.FirstUsefulActionAt), t.FirstUsefulActionAt.Sub(t.StartedAt)) + } + if !t.FirstTokenAt.IsZero() { + write(" first_token=%s (+%s)\n", formatTime(t.FirstTokenAt), t.FirstTokenAt.Sub(t.StartedAt)) + } + + spans := append([]Span(nil), t.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.Exclusive) / float64(wall) + } + parent := "" + if span.Parent != "" { + parent = " [" + span.Parent + "]" + } + write(" %-18s %10s excl=%-10s %5.1f%%%s\n", span.Name, span.Duration, span.Exclusive, share*100, parent) + } + + counters := append([]Counter(nil), t.Counters...) + sort.Slice(counters, func(i, j int) bool { return counters[i].Name < counters[j].Name }) + write("counters:\n") + for _, c := range counters { + write(" %-22s %d\n", c.Name, c.Value) + } + return firstErr +} + +// 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..490918c14 --- /dev/null +++ b/internal/trace/parse.go @@ -0,0 +1,183 @@ +package trace + +import ( + "bufio" + "encoding/json" + "errors" + "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. +// +// It fails loudly on a corrupt file rather than silently returning an empty +// 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 + } + 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 + 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)") + } + 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) + 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": + if !sawTraceHeader { + return nil, errors.New("parse trace: not a valid NDJSON trace (no type:trace header)") + } + name, _ := obj["name"].(string) + 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) + } + // 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 { + 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 { + // 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 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 +} + +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)) +} + +// 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 { + 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: + 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..1327f97fd --- /dev/null +++ b/internal/trace/recorder.go @@ -0,0 +1,325 @@ +package trace + +import ( + "sort" + "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. +// +// 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 + 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 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.addOccurrence(s.name, s.start, time.Now()) + }) +} + +// 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 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.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. +func (r *Recorder) Counter(name string, n int64) { + if r == nil { + return + } + r.mu.Lock() + defer r.mu.Unlock() + if r.finished { + return + } + 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.finished || 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.finished || 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.finished || r.firstActionStamped { + return + } + r.firstActionStamped = true + r.tr.FirstUsefulActionAt = time.Now() +} + +// 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 { + return nil + } + r.mu.Lock() + defer r.mu.Unlock() + 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. + snap.Spans = append([]Span(nil), r.tr.Spans...) + snap.Counters = append([]Counter(nil), r.tr.Counters...) + return &snap +} + +// 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 + } + d := end.Sub(start) + if d < 0 { + d = 0 + } + r.tr.Spans = append(r.tr.Spans, Span{Name: name, Start: start, End: end, 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}) +} + +// 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. + 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 + } + 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 new file mode 100644 index 000000000..3c86fedf9 --- /dev/null +++ b/internal/trace/trace.go @@ -0,0 +1,233 @@ +// 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. +// +// 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 +// 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 ( + 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}. +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 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"` + 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). +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 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 { + if span.Parent == "" { + total += span.Duration + } + } + return total +} + +// 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 + } + union := unionIntervalDuration(t.Spans) + if union <= 0 { + return 0 + } + ratio := float64(union) / float64(wall) + if ratio > 1 { + ratio = 1 + } + return ratio +} + +// 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 { + total += span.Duration + } + } + 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. +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 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:" + SpanToolPartition, + "span:" + SpanGeneration, + "span:" + SpanProviderConnect, + "counter:" + CounterModelRequests, + "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 new file mode 100644 index 000000000..08507cc4d --- /dev/null +++ b/internal/trace/trace_test.go @@ -0,0 +1,542 @@ +package trace + +import ( + "bytes" + "context" + "encoding/json" + "errors" + "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) + } + // 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)) + } +} + +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 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() + 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(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(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:" + SpanToolPartition: 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 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() + // 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 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 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 + } + } + // 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()) + } +} + +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) + } +} + +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(SpanToolPartition, 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") + } +} + +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") + } +} + +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) + } +}