| 1 | package main |
| 2 | |
| 3 | import ( |
| 4 | "os" |
| 5 | "path/filepath" |
| 6 | "strings" |
| 7 | "testing" |
| 8 | ) |
| 9 | |
| 10 | func TestSummarizeTrajectoryAttributesTimeAndSkipsTruncatedTail(t *testing.T) { |
| 11 | path := filepath.Join(t.TempDir(), "task.trajectory.jsonl") |
| 12 | lines := []string{ |
| 13 | `{"schema_version":1,"seq":1,"ts":1000,"event":{"kind":"turn_started"}}`, |
| 14 | `{"schema_version":1,"seq":2,"ts":1500,"event":{"kind":"tool_dispatch","tool":{"name":"bash"}}}`, |
| 15 | `{"schema_version":1,"seq":3,"ts":2000,"event":{"kind":"tool_result","tool":{"name":"bash","durationMs":400}}}`, |
| 16 | `{"schema_version":1,"seq":4,"ts":2500,"event":{"kind":"tool_result","tool":{"name":"grep","durationMs":300,"parentId":"task-1"}}}`, |
| 17 | `{"schema_version":1,"seq":5,"ts":4000,"event":{"kind":"turn_done"}}`, |
| 18 | `{"schema_version":1,"seq":6,"ts":4100,"event":{"kind":"tool_res`, // killed mid-write |
| 19 | } |
| 20 | if err := os.WriteFile(path, []byte(strings.Join(lines, "\n")), 0o644); err != nil { |
| 21 | t.Fatalf("write fixture: %v", err) |
| 22 | } |
| 23 | |
| 24 | s, err := summarizeTrajectory(path) |
| 25 | if err != nil { |
| 26 | t.Fatalf("summarizeTrajectory: %v", err) |
| 27 | } |
| 28 | if s.Records != 5 { |
| 29 | t.Errorf("records = %d, want 5 (truncated tail skipped)", s.Records) |
| 30 | } |
| 31 | if s.SpanMs != 3000 { |
| 32 | t.Errorf("span = %d, want 3000", s.SpanMs) |
| 33 | } |
| 34 | if s.ToolMs != 400 { |
| 35 | t.Errorf("tool ms = %d, want 400 (subagent call must not double-book)", s.ToolMs) |
| 36 | } |
| 37 | if s.ModelMs != 2600 { |
| 38 | t.Errorf("model ms = %d, want 2600", s.ModelMs) |
| 39 | } |
| 40 | } |
| 41 | |
| 42 | func TestSummarizeTrajectoryDecomposesModelRounds(t *testing.T) { |
| 43 | path := filepath.Join(t.TempDir(), "rounds.trajectory.jsonl") |
| 44 | lines := []string{ |
| 45 | `{"seq":1,"ts":1000,"event":{"kind":"turn_started"}}`, |
| 46 | `{"seq":2,"ts":3000,"event":{"kind":"tool_dispatch","tool":{"name":"read_file","partial":true}}}`, // round 1 gap: 2000 |
| 47 | `{"seq":3,"ts":3400,"event":{"kind":"tool_dispatch","tool":{"name":"read_file"}}}`, // same batch: no new round |
| 48 | `{"seq":4,"ts":5000,"event":{"kind":"tool_result","tool":{"name":"read_file","durationMs":400}}}`, |
| 49 | `{"seq":5,"ts":5100,"event":{"kind":"tool_dispatch","tool":{"name":"grep","parentId":"task-1"}}}`, // subagent: ignored |
| 50 | `{"seq":6,"ts":5200,"event":{"kind":"tool_result","tool":{"name":"grep","durationMs":50,"parentId":"task-1"}}}`, |
| 51 | `{"seq":7,"ts":6000,"event":{"kind":"retrying"}}`, |
| 52 | `{"seq":8,"ts":9000,"event":{"kind":"tool_dispatch","tool":{"name":"bash"}}}`, // round 2 gap: 9000-5000=4000 |
| 53 | `{"seq":9,"ts":9500,"event":{"kind":"tool_result","tool":{"name":"bash","durationMs":450}}}`, |
| 54 | `{"seq":10,"ts":12000,"event":{"kind":"turn_done"}}`, // final answer round gap: 2500 |
| 55 | } |
| 56 | if err := os.WriteFile(path, []byte(strings.Join(lines, "\n")), 0o644); err != nil { |
| 57 | t.Fatalf("write fixture: %v", err) |
| 58 | } |
| 59 | s, err := summarizeTrajectory(path) |
| 60 | if err != nil { |
| 61 | t.Fatalf("summarizeTrajectory: %v", err) |
| 62 | } |
| 63 | if s.ModelRounds != 3 { |
| 64 | t.Errorf("model rounds = %d, want 3 (two tool rounds + final answer)", s.ModelRounds) |
| 65 | } |
| 66 | if s.ModelGapTotalMs != 8500 { |
| 67 | t.Errorf("model gap total = %d, want 8500", s.ModelGapTotalMs) |
| 68 | } |
| 69 | if s.ModelGapP95Ms != 4000 { |
| 70 | t.Errorf("model gap p95 = %d, want 4000", s.ModelGapP95Ms) |
| 71 | } |
| 72 | if s.Retries != 1 { |
| 73 | t.Errorf("retries = %d, want 1", s.Retries) |
| 74 | } |
| 75 | if s.ToolMs != 850 { |
| 76 | t.Errorf("tool ms = %d, want 850 (subagent excluded)", s.ToolMs) |
| 77 | } |
| 78 | } |
| 79 | |
| 80 | func TestSummarizeTrajectoryDecomposesBatches(t *testing.T) { |
| 81 | path := filepath.Join(t.TempDir(), "batches.trajectory.jsonl") |
| 82 | lines := []string{ |
| 83 | `{"seq":1,"ts":1000,"event":{"kind":"turn_started"}}`, |
| 84 | // Batch 1: three reads dispatched together, executed overlapping. |
| 85 | `{"seq":2,"ts":2000,"event":{"kind":"tool_dispatch","tool":{"id":"a","name":"read_file","readOnly":true}}}`, |
| 86 | `{"seq":3,"ts":2010,"event":{"kind":"tool_dispatch","tool":{"id":"b","name":"read_file","readOnly":true}}}`, |
| 87 | `{"seq":4,"ts":2020,"event":{"kind":"tool_dispatch","tool":{"id":"c","name":"read_file","readOnly":true}}}`, |
| 88 | `{"seq":5,"ts":2500,"event":{"kind":"tool_result","tool":{"id":"a","name":"read_file","readOnly":true,"durationMs":400,"startedAt":2050,"endedAt":2450}}}`, |
| 89 | `{"seq":6,"ts":2500,"event":{"kind":"tool_result","tool":{"id":"b","name":"read_file","readOnly":true,"durationMs":300,"startedAt":2060,"endedAt":2360}}}`, |
| 90 | `{"seq":7,"ts":2510,"event":{"kind":"tool_result","tool":{"id":"c","name":"read_file","readOnly":true,"durationMs":200,"startedAt":2070,"endedAt":2270}}}`, |
| 91 | // Batches 2+3: the serialized single-read anti-pattern, streak of two. |
| 92 | `{"seq":8,"ts":4000,"event":{"kind":"tool_dispatch","tool":{"id":"d","name":"read_file","readOnly":true}}}`, |
| 93 | `{"seq":9,"ts":4300,"event":{"kind":"tool_result","tool":{"id":"d","name":"read_file","readOnly":true,"durationMs":280,"startedAt":4010,"endedAt":4290}}}`, |
| 94 | `{"seq":10,"ts":5000,"event":{"kind":"tool_dispatch","tool":{"id":"e","name":"grep","readOnly":true}}}`, |
| 95 | `{"seq":11,"ts":5200,"event":{"kind":"tool_result","tool":{"id":"e","name":"grep","readOnly":true,"durationMs":180,"startedAt":5010,"endedAt":5190}}}`, |
| 96 | `{"seq":12,"ts":6000,"event":{"kind":"turn_done"}}`, |
| 97 | } |
| 98 | if err := os.WriteFile(path, []byte(strings.Join(lines, "\n")), 0o644); err != nil { |
| 99 | t.Fatalf("write fixture: %v", err) |
| 100 | } |
| 101 | s, err := summarizeTrajectory(path) |
| 102 | if err != nil { |
| 103 | t.Fatalf("summarizeTrajectory: %v", err) |
| 104 | } |
| 105 | if s.ToolBatches != 3 || s.TopLevelCalls != 5 || s.MaxBatchSize != 3 { |
| 106 | t.Errorf("batches=%d calls=%d max=%d, want 3/5/3", s.ToolBatches, s.TopLevelCalls, s.MaxBatchSize) |
| 107 | } |
| 108 | if s.ParallelBatches != 1 || s.ParallelSavedMs != 500 { |
| 109 | t.Errorf("parallel=%d saved=%d, want 1/500 (900 serial vs 400 wall)", s.ParallelBatches, s.ParallelSavedMs) |
| 110 | } |
| 111 | if s.SingleReadRounds != 2 || s.SingleReadStreak != 2 { |
| 112 | t.Errorf("singleReads=%d streak=%d, want 2/2", s.SingleReadRounds, s.SingleReadStreak) |
| 113 | } |
| 114 | if s.ToolWallMs != 860 { |
| 115 | t.Errorf("tool wall = %d, want 860 (400 union + 280 + 180)", s.ToolWallMs) |
| 116 | } |
| 117 | if s.ToolMs != 1360 { |
| 118 | t.Errorf("tool ms = %d, want 1360 (duration sum)", s.ToolMs) |
| 119 | } |
| 120 | if s.ModelMs != 4140 { |
| 121 | t.Errorf("model ms = %d, want 4140 (span 5000 − wall 860)", s.ModelMs) |
| 122 | } |
| 123 | if s.ModelRounds != 4 { |
| 124 | t.Errorf("model rounds = %d, want 4 (three tool rounds + final answer)", s.ModelRounds) |
| 125 | } |
| 126 | if s.StartDelayP95Ms != 50 { |
| 127 | t.Errorf("start delay p95 = %d, want 50", s.StartDelayP95Ms) |
| 128 | } |
| 129 | } |
| 130 | |
| 131 | func TestSummarizeTrajectoryAnchorsStartDelayToFullDispatch(t *testing.T) { |
| 132 | path := filepath.Join(t.TempDir(), "partial.trajectory.jsonl") |
| 133 | lines := []string{ |
| 134 | `{"seq":1,"ts":1000,"event":{"kind":"turn_started"}}`, |
| 135 | // Streamed partial announcement ~900ms before the full dispatch; the |
| 136 | // stream tail must not be booked as pre-exec queueing. |
| 137 | `{"seq":2,"ts":2000,"event":{"kind":"tool_dispatch","tool":{"id":"a","name":"bash","partial":true}}}`, |
| 138 | `{"seq":3,"ts":2900,"event":{"kind":"tool_dispatch","tool":{"id":"a","name":"bash"}}}`, |
| 139 | `{"seq":4,"ts":3000,"event":{"kind":"tool_result","tool":{"id":"a","name":"bash","durationMs":90,"startedAt":2910,"endedAt":3000}}}`, |
| 140 | `{"seq":5,"ts":4000,"event":{"kind":"turn_done"}}`, |
| 141 | } |
| 142 | if err := os.WriteFile(path, []byte(strings.Join(lines, "\n")), 0o644); err != nil { |
| 143 | t.Fatalf("write fixture: %v", err) |
| 144 | } |
| 145 | s, err := summarizeTrajectory(path) |
| 146 | if err != nil { |
| 147 | t.Fatalf("summarizeTrajectory: %v", err) |
| 148 | } |
| 149 | if s.TopLevelCalls != 1 || s.ToolBatches != 1 { |
| 150 | t.Errorf("calls=%d batches=%d, want 1/1 (partial+full is one call)", s.TopLevelCalls, s.ToolBatches) |
| 151 | } |
| 152 | if s.StartDelayP95Ms != 10 { |
| 153 | t.Errorf("start delay p95 = %d, want 10 (2910 − full dispatch 2900)", s.StartDelayP95Ms) |
| 154 | } |
| 155 | } |
| 156 | |
| 157 | func TestSummarizeTrajectorySplitsCleanAndRecoveryRounds(t *testing.T) { |
| 158 | path := filepath.Join(t.TempDir(), "recovery.trajectory.jsonl") |
| 159 | lines := []string{ |
| 160 | `{"seq":1,"ts":1000,"event":{"kind":"turn_started"}}`, |
| 161 | // Round 1 (clean, gap 1000). |
| 162 | `{"seq":2,"ts":2000,"event":{"kind":"tool_dispatch","tool":{"id":"a","name":"bash"}}}`, |
| 163 | `{"seq":3,"ts":2100,"event":{"kind":"tool_result","tool":{"id":"a","name":"bash","durationMs":100,"startedAt":2000,"endedAt":2100}}}`, |
| 164 | // Round 2 (gap 8900): stream-interrupted retry mid-gap. |
| 165 | `{"seq":4,"ts":4000,"event":{"kind":"retrying","retryAttempt":1,"retryScope":"stream"}}`, |
| 166 | `{"seq":5,"ts":11000,"event":{"kind":"tool_dispatch","tool":{"id":"b","name":"bash"}}}`, |
| 167 | `{"seq":6,"ts":11100,"event":{"kind":"tool_result","tool":{"id":"b","name":"bash","durationMs":100,"startedAt":11000,"endedAt":11100}}}`, |
| 168 | // Round 3 (gap 2900): missing-reasoning exact replay. |
| 169 | `{"seq":7,"ts":12000,"protocol_recovery":"missing_reasoning_retry_attempted"}`, |
| 170 | `{"seq":8,"ts":14000,"event":{"kind":"tool_dispatch","tool":{"id":"c","name":"bash"}}}`, |
| 171 | `{"seq":9,"ts":14100,"event":{"kind":"tool_result","tool":{"id":"c","name":"bash","durationMs":100,"startedAt":14000,"endedAt":14100}}}`, |
| 172 | // Final answer round (gap 5900): empty-final retry. |
| 173 | `{"seq":10,"ts":16000,"event":{"kind":"notice","code":"empty_final"}}`, |
| 174 | `{"seq":11,"ts":20000,"event":{"kind":"turn_done"}}`, |
| 175 | } |
| 176 | if err := os.WriteFile(path, []byte(strings.Join(lines, "\n")), 0o644); err != nil { |
| 177 | t.Fatalf("write fixture: %v", err) |
| 178 | } |
| 179 | s, err := summarizeTrajectory(path) |
| 180 | if err != nil { |
| 181 | t.Fatalf("summarizeTrajectory: %v", err) |
| 182 | } |
| 183 | if s.StreamRetries != 1 || s.HeaderRetries != 0 || s.Retries != 1 { |
| 184 | t.Errorf("stream=%d header=%d retries=%d, want 1/0/1", s.StreamRetries, s.HeaderRetries, s.Retries) |
| 185 | } |
| 186 | if s.ReasoningReplays != 1 || s.EmptyFinalRetries != 1 { |
| 187 | t.Errorf("replays=%d emptyFinal=%d, want 1/1", s.ReasoningReplays, s.EmptyFinalRetries) |
| 188 | } |
| 189 | if s.ModelRounds != 4 || s.RecoveryRounds != 3 { |
| 190 | t.Errorf("rounds=%d recovery=%d, want 4/3", s.ModelRounds, s.RecoveryRounds) |
| 191 | } |
| 192 | if s.RecoveryGapMs != 8900+2900+5900 { |
| 193 | t.Errorf("recovery gap = %d, want 17700", s.RecoveryGapMs) |
| 194 | } |
| 195 | if s.CleanGapP95Ms != 1000 { |
| 196 | t.Errorf("clean gap p95 = %d, want 1000 (only round 1 is clean)", s.CleanGapP95Ms) |
| 197 | } |
| 198 | if s.ModelGapP95Ms != 8900 { |
| 199 | t.Errorf("recovery-inclusive gap p95 = %d, want 8900", s.ModelGapP95Ms) |
| 200 | } |
| 201 | } |
| 202 | |
| 203 | func TestClipIntervals(t *testing.T) { |
| 204 | got := clipIntervals([][2]int64{{0, 10}, {20, 30}}, [][2]int64{{5, 25}}) |
| 205 | want := [][2]int64{{0, 5}, {25, 30}} |
| 206 | if len(got) != len(want) || got[0] != want[0] || got[1] != want[1] { |
| 207 | t.Fatalf("clip = %v, want %v", got, want) |
| 208 | } |
| 209 | if rest := clipIntervals([][2]int64{{5, 8}}, [][2]int64{{0, 10}}); len(rest) != 0 { |
| 210 | t.Fatalf("fully covered base must clip to empty, got %v", rest) |
| 211 | } |
| 212 | } |
| 213 | |
| 214 | func TestSummarizeTrajectoryDecomposesWallClock(t *testing.T) { |
| 215 | path := filepath.Join(t.TempDir(), "wall.trajectory.jsonl") |
| 216 | lines := []string{ |
| 217 | `{"seq":1,"ts":1000,"event":{"kind":"turn_started"}}`, |
| 218 | // Planner call: 3000ms, tagged by its usage source. |
| 219 | `{"seq":2,"ts":1000,"event":{"kind":"stream_attempt","streamAttempt":{"id":"p1","action":"begin"}}}`, |
| 220 | `{"seq":3,"ts":4000,"event":{"kind":"stream_attempt","streamAttempt":{"id":"p1","action":"commit"}}}`, |
| 221 | `{"seq":4,"ts":4010,"event":{"kind":"usage","usage":{"source":"planner"}}}`, |
| 222 | // Executor call: 1900ms, then one 100ms tool. |
| 223 | `{"seq":5,"ts":4100,"event":{"kind":"stream_attempt","streamAttempt":{"id":"e1","action":"begin"}}}`, |
| 224 | `{"seq":6,"ts":6000,"event":{"kind":"stream_attempt","streamAttempt":{"id":"e1","action":"commit"}}}`, |
| 225 | `{"seq":7,"ts":6010,"event":{"kind":"usage","usage":{"source":"executor"}}}`, |
| 226 | `{"seq":8,"ts":6100,"event":{"kind":"tool_dispatch","tool":{"id":"a","name":"bash"}}}`, |
| 227 | `{"seq":9,"ts":6200,"event":{"kind":"tool_result","tool":{"id":"a","name":"bash","durationMs":100,"startedAt":6100,"endedAt":6200}}}`, |
| 228 | // Retry backoff 2000ms, then a 500ms executor attempt. |
| 229 | `{"seq":10,"ts":7000,"event":{"kind":"retrying","retryScope":"stream"}}`, |
| 230 | `{"seq":11,"ts":9000,"event":{"kind":"stream_attempt","streamAttempt":{"id":"e2","action":"begin"}}}`, |
| 231 | `{"seq":12,"ts":9500,"event":{"kind":"stream_attempt","streamAttempt":{"id":"e2","action":"commit"}}}`, |
| 232 | `{"seq":13,"ts":9510,"event":{"kind":"usage","usage":{"source":"executor"}}}`, |
| 233 | // Compaction 1000ms; its inner summarize attempt must book as compaction. |
| 234 | `{"seq":14,"ts":10000,"event":{"kind":"compaction_started"}}`, |
| 235 | `{"seq":15,"ts":10100,"event":{"kind":"stream_attempt","streamAttempt":{"id":"c1","action":"begin"}}}`, |
| 236 | `{"seq":16,"ts":10800,"event":{"kind":"stream_attempt","streamAttempt":{"id":"c1","action":"commit"}}}`, |
| 237 | `{"seq":17,"ts":10810,"event":{"kind":"usage","usage":{"source":"executor"}}}`, |
| 238 | `{"seq":18,"ts":11000,"event":{"kind":"compaction_done"}}`, |
| 239 | `{"seq":19,"ts":12000,"event":{"kind":"turn_done"}}`, |
| 240 | } |
| 241 | if err := os.WriteFile(path, []byte(strings.Join(lines, "\n")), 0o644); err != nil { |
| 242 | t.Fatalf("write fixture: %v", err) |
| 243 | } |
| 244 | s, err := summarizeTrajectory(path) |
| 245 | if err != nil { |
| 246 | t.Fatalf("summarizeTrajectory: %v", err) |
| 247 | } |
| 248 | if s.RetryWaitMs != 2000 { |
| 249 | t.Errorf("retry wait = %d, want 2000", s.RetryWaitMs) |
| 250 | } |
| 251 | if s.CompactionMs != 1000 { |
| 252 | t.Errorf("compaction = %d, want 1000", s.CompactionMs) |
| 253 | } |
| 254 | if s.PlannerStreamMs != 3000 { |
| 255 | t.Errorf("planner stream = %d, want 3000", s.PlannerStreamMs) |
| 256 | } |
| 257 | if s.ModelStreamMs != 2400 { |
| 258 | t.Errorf("model stream = %d, want 2400 (1900+500; compaction-inner attempt clipped)", s.ModelStreamMs) |
| 259 | } |
| 260 | if s.AgentOtherMs != 2500 { |
| 261 | t.Errorf("agent other = %d, want 2500 (span 11000 − 100 − 2000 − 1000 − 3000 − 2400)", s.AgentOtherMs) |
| 262 | } |
| 263 | if s.Compactions != 1 { |
| 264 | t.Errorf("compactions = %d, want 1", s.Compactions) |
| 265 | } |
| 266 | } |
| 267 | |
| 268 | func TestSummarizeTrajectoryCollectsPhaseTraceInputs(t *testing.T) { |
| 269 | path := filepath.Join(t.TempDir(), "phase.trajectory.jsonl") |
| 270 | lines := []string{ |
| 271 | `{"seq":1,"ts":1000,"event":{"kind":"turn_started"}}`, |
| 272 | `{"seq":2,"ts":1870,"event":{"kind":"reasoning"}}`, |
| 273 | `{"seq":3,"ts":2000,"event":{"kind":"usage","usage":{"source":"planner"}}}`, |
| 274 | `{"seq":4,"ts":2400,"event":{"kind":"reasoning"}}`, |
| 275 | `{"seq":5,"ts":3000,"event":{"kind":"tool_dispatch","tool":{"id":"a","name":"bash"}}}`, |
| 276 | `{"seq":6,"ts":3300,"event":{"kind":"tool_result","tool":{"id":"a","name":"bash","durationMs":90,"startedAt":3210,"endedAt":3300}}}`, |
| 277 | `{"seq":7,"ts":3400,"event":{"kind":"usage","usage":{"source":"executor"}}}`, |
| 278 | `{"seq":8,"ts":3500,"event":{"kind":"usage","usage":{"source":"subagent"}}}`, |
| 279 | `{"seq":9,"ts":3600,"event":{"kind":"notice","code":"progress_guard"}}`, |
| 280 | `{"seq":10,"ts":4000,"event":{"kind":"turn_done"}}`, |
| 281 | } |
| 282 | if err := os.WriteFile(path, []byte(strings.Join(lines, "\n")), 0o644); err != nil { |
| 283 | t.Fatalf("write fixture: %v", err) |
| 284 | } |
| 285 | s, err := summarizeTrajectory(path) |
| 286 | if err != nil { |
| 287 | t.Fatalf("summarizeTrajectory: %v", err) |
| 288 | } |
| 289 | if s.TTFTMs != 870 { |
| 290 | t.Errorf("ttft = %d, want 870 (first reasoning delta)", s.TTFTMs) |
| 291 | } |
| 292 | if s.FirstToolMs != 2210 { |
| 293 | t.Errorf("first tool = %d, want 2210 (startedAt 3210 − span start)", s.FirstToolMs) |
| 294 | } |
| 295 | if s.PlannerRequests != 1 || s.ExecutorRequests != 1 || s.SubagentRequests != 1 { |
| 296 | t.Errorf("requests planner=%d executor=%d subagent=%d, want 1/1/1", |
| 297 | s.PlannerRequests, s.ExecutorRequests, s.SubagentRequests) |
| 298 | } |
| 299 | if s.ToolQueueMs != 210 { |
| 300 | t.Errorf("tool queue = %d, want 210 (start 3210 − dispatch 3000)", s.ToolQueueMs) |
| 301 | } |
| 302 | if s.NoProgressSignals != 1 { |
| 303 | t.Errorf("no-progress signals = %d, want 1", s.NoProgressSignals) |
| 304 | } |
| 305 | } |
| 306 | |
| 307 | func TestBuildPhaseTrace(t *testing.T) { |
| 308 | r := result{task: task{ID: "a"}, Passed: true, WallMs: 92341} |
| 309 | r.PromptTokens = 84320 |
| 310 | r.CompletionTokens = 12013 |
| 311 | r.Trajectory = &trajectorySummary{ |
| 312 | TTFTMs: 870, FirstToolMs: 4210, |
| 313 | PlannerRequests: 1, PlannerStreamMs: 11020, |
| 314 | ExecutorRequests: 7, ModelStreamMs: 56100, |
| 315 | TopLevelCalls: 14, ToolQueueMs: 430, ToolWallMs: 8120, |
| 316 | StreamRetries: 1, RecoveryGapMs: 9530, |
| 317 | CompactionMs: 800, NoProgressSignals: 3, |
| 318 | } |
| 319 | p := buildPhaseTrace(r) |
| 320 | if p == nil { |
| 321 | t.Fatal("trace must be built when a trajectory exists") |
| 322 | } |
| 323 | if p.TotalMs != 92341 || p.TTFTMs != 870 || p.TimeToFirstTool != 4210 { |
| 324 | t.Errorf("totals = %d/%d/%d, want 92341/870/4210", p.TotalMs, p.TTFTMs, p.TimeToFirstTool) |
| 325 | } |
| 326 | if p.Planner != (phaseModel{Requests: 1, Ms: 11020}) || p.Executor != (phaseModel{Requests: 7, Ms: 56100}) { |
| 327 | t.Errorf("planner=%+v executor=%+v", p.Planner, p.Executor) |
| 328 | } |
| 329 | if p.Tool != (phaseTool{Calls: 14, QueueMs: 430, CriticalPathMs: 8120}) { |
| 330 | t.Errorf("tool = %+v", p.Tool) |
| 331 | } |
| 332 | if p.Recovery != (phaseModel{Requests: 1, Ms: 9530}) { |
| 333 | t.Errorf("recovery = %+v", p.Recovery) |
| 334 | } |
| 335 | if p.CompactionMs != 800 || p.NoProgressSignals != 3 || !p.Solved { |
| 336 | t.Errorf("compaction=%d signals=%d solved=%v", p.CompactionMs, p.NoProgressSignals, p.Solved) |
| 337 | } |
| 338 | if p.PromptTokens != 84320 || p.CompletionTokens != 12013 { |
| 339 | t.Errorf("tokens = %d/%d", p.PromptTokens, p.CompletionTokens) |
| 340 | } |
| 341 | if buildPhaseTrace(result{}) != nil { |
| 342 | t.Fatal("no trajectory must mean no trace") |
| 343 | } |
| 344 | } |
| 345 | |
| 346 | func TestSummarizeTrajectoryClassifiesRoundOutcomes(t *testing.T) { |
| 347 | path := filepath.Join(t.TempDir(), "outcomes.trajectory.jsonl") |
| 348 | lines := []string{ |
| 349 | `{"seq":1,"ts":1000,"event":{"kind":"turn_started"}}`, |
| 350 | // Round 1: planner usage in the gap outranks the batch's mutation. |
| 351 | `{"seq":2,"ts":1500,"event":{"kind":"usage","usage":{"source":"planner"}}}`, |
| 352 | `{"seq":3,"ts":2000,"event":{"kind":"tool_dispatch","tool":{"id":"a","name":"write_file","args":"{\"p\":1}"}}}`, |
| 353 | `{"seq":4,"ts":2100,"event":{"kind":"tool_result","tool":{"id":"a","name":"write_file","durationMs":100,"startedAt":2000,"endedAt":2100}}}`, |
| 354 | // Round 2: successful write → mutation. |
| 355 | `{"seq":5,"ts":3000,"event":{"kind":"tool_dispatch","tool":{"id":"b","name":"write_file","args":"{\"p\":2}"}}}`, |
| 356 | `{"seq":6,"ts":3100,"event":{"kind":"tool_result","tool":{"id":"b","name":"write_file","durationMs":100,"startedAt":3000,"endedAt":3100}}}`, |
| 357 | // Round 3: first read of this target → evidence_gain. |
| 358 | `{"seq":7,"ts":4000,"event":{"kind":"tool_dispatch","tool":{"id":"c","name":"read_file","args":"{\"f\":\"x\"}","readOnly":true}}}`, |
| 359 | `{"seq":8,"ts":4100,"event":{"kind":"tool_result","tool":{"id":"c","name":"read_file","readOnly":true,"durationMs":100,"startedAt":4000,"endedAt":4100}}}`, |
| 360 | // Round 4: the exact same read again → duplicate_work. |
| 361 | `{"seq":9,"ts":5000,"event":{"kind":"tool_dispatch","tool":{"id":"d","name":"read_file","args":"{\"f\":\"x\"}","readOnly":true}}}`, |
| 362 | `{"seq":10,"ts":5100,"event":{"kind":"tool_result","tool":{"id":"d","name":"read_file","readOnly":true,"durationMs":100,"startedAt":5000,"endedAt":5100}}}`, |
| 363 | // Round 5: verification command → verification. |
| 364 | `{"seq":11,"ts":6000,"event":{"kind":"tool_dispatch","tool":{"id":"e","name":"bash","args":"{\"cmd\":\"go test\"}","readOnly":true}}}`, |
| 365 | `{"seq":12,"ts":6200,"event":{"kind":"tool_result","tool":{"id":"e","name":"bash","readOnly":true,"durationMs":200,"startedAt":6000,"endedAt":6200,"execution":{"verification":"passed"}}}}`, |
| 366 | // Round 6: ledger-only batch → bookkeeping. |
| 367 | `{"seq":13,"ts":7000,"event":{"kind":"tool_dispatch","tool":{"id":"f","name":"complete_step","args":"{\"s\":1}"}}}`, |
| 368 | `{"seq":14,"ts":7100,"event":{"kind":"tool_result","tool":{"id":"f","name":"complete_step","durationMs":100,"startedAt":7000,"endedAt":7100}}}`, |
| 369 | `{"seq":15,"ts":8000,"event":{"kind":"turn_done"}}`, |
| 370 | } |
| 371 | if err := os.WriteFile(path, []byte(strings.Join(lines, "\n")), 0o644); err != nil { |
| 372 | t.Fatalf("write fixture: %v", err) |
| 373 | } |
| 374 | s, err := summarizeTrajectory(path) |
| 375 | if err != nil { |
| 376 | t.Fatalf("summarizeTrajectory: %v", err) |
| 377 | } |
| 378 | want := map[string]int{ |
| 379 | "planning": 1, "mutation": 1, "evidence_gain": 1, "duplicate_work": 1, |
| 380 | "verification": 1, "bookkeeping": 1, "finalization": 1, |
| 381 | } |
| 382 | for outcome, n := range want { |
| 383 | if s.RoundOutcomes[outcome] != n { |
| 384 | t.Errorf("outcome %s = %d, want %d (all: %v)", outcome, s.RoundOutcomes[outcome], n, s.RoundOutcomes) |
| 385 | } |
| 386 | } |
| 387 | if s.UsefulRounds != 4 { |
| 388 | t.Errorf("useful rounds = %d, want 4 (mutation, evidence, verification, finalization)", s.UsefulRounds) |
| 389 | } |
| 390 | if s.WastedGapMs != 1000+900+800 { |
| 391 | t.Errorf("wasted gap = %d, want 2700 (planning 1000 + duplicate 900 + bookkeeping 800)", s.WastedGapMs) |
| 392 | } |
| 393 | if s.RoundOutcomeMs["planning"] != 1000 { |
| 394 | t.Errorf("planning ms = %d, want 1000", s.RoundOutcomeMs["planning"]) |
| 395 | } |
| 396 | } |
| 397 | |
| 398 | func TestRenderTimeAttributionIncludesRoundEfficiency(t *testing.T) { |
| 399 | r := result{task: task{ID: "a"}, Passed: true} |
| 400 | r.Trajectory = &trajectorySummary{ |
| 401 | Records: 5, SpanMs: 8000, ToolMs: 700, ModelMs: 7300, ModelRounds: 7, |
| 402 | UsefulRounds: 4, WastedGapMs: 2700, |
| 403 | RoundOutcomes: map[string]int{ |
| 404 | "planning": 1, "mutation": 1, "evidence_gain": 1, "duplicate_work": 1, |
| 405 | "verification": 1, "bookkeeping": 1, "finalization": 1, |
| 406 | }, |
| 407 | RoundOutcomeMs: map[string]int64{ |
| 408 | "planning": 1000, "mutation": 900, "evidence_gain": 900, "duplicate_work": 900, |
| 409 | "verification": 900, "bookkeeping": 800, "finalization": 900, |
| 410 | }, |
| 411 | } |
| 412 | got := renderTimeAttribution([]result{r}) |
| 413 | for _, want := range []string{ |
| 414 | "**Round efficiency**: **useful rounds** 4/7 (57%)", |
| 415 | "**wasted model time** 2.7s (**2.7s/solved**)", |
| 416 | "**waste breakdown**: planning ×1 (1.0s) · duplicate_work ×1 (0.9s) · bookkeeping ×1 (0.8s)", |
| 417 | } { |
| 418 | if !strings.Contains(got, want) { |
| 419 | t.Fatalf("round efficiency missing %q:\n%s", want, got) |
| 420 | } |
| 421 | } |
| 422 | } |
| 423 | |
| 424 | func TestRunTrajModeRedigestsRecordedFiles(t *testing.T) { |
| 425 | dir := t.TempDir() |
| 426 | lines := []string{ |
| 427 | `{"seq":1,"ts":1000,"event":{"kind":"turn_started"}}`, |
| 428 | `{"seq":2,"ts":1000,"event":{"kind":"stream_attempt","streamAttempt":{"id":"e1","action":"begin"}}}`, |
| 429 | `{"seq":3,"ts":2000,"event":{"kind":"stream_attempt","streamAttempt":{"id":"e1","action":"commit"}}}`, |
| 430 | `{"seq":4,"ts":2010,"event":{"kind":"usage","usage":{"source":"executor"}}}`, |
| 431 | `{"seq":5,"ts":3000,"event":{"kind":"turn_done"}}`, |
| 432 | } |
| 433 | if err := os.WriteFile(filepath.Join(dir, "t1.trajectory.jsonl"), []byte(strings.Join(lines, "\n")), 0o644); err != nil { |
| 434 | t.Fatalf("write fixture: %v", err) |
| 435 | } |
| 436 | got, err := runTrajMode(dir) |
| 437 | if err != nil { |
| 438 | t.Fatalf("runTrajMode: %v", err) |
| 439 | } |
| 440 | for _, want := range []string{"Trajectory digest", "Wall decomposition", "### `t1`", `"model_stream_ms": 1000`} { |
| 441 | if !strings.Contains(got, want) { |
| 442 | t.Fatalf("traj mode output missing %q:\n%s", want, got) |
| 443 | } |
| 444 | } |
| 445 | if _, err := runTrajMode(filepath.Join(dir, "empty")); err == nil { |
| 446 | t.Fatalf("missing dir must error") |
| 447 | } |
| 448 | } |
| 449 | |
| 450 | func TestRenderTimeAttributionIncludesBatchingLine(t *testing.T) { |
| 451 | r := result{task: task{ID: "a"}, Passed: true} |
| 452 | r.Trajectory = &trajectorySummary{ |
| 453 | Records: 12, SpanMs: 5000, ToolMs: 1360, ToolWallMs: 860, ModelMs: 4140, |
| 454 | ModelRounds: 4, ModelGapTotalMs: 3990, |
| 455 | ToolBatches: 3, TopLevelCalls: 5, MaxBatchSize: 3, |
| 456 | ParallelBatches: 1, ParallelSavedMs: 500, |
| 457 | SingleReadRounds: 2, SingleReadStreak: 2, StartDelayP95Ms: 50, |
| 458 | } |
| 459 | got := renderTimeAttribution([]result{r}) |
| 460 | for _, want := range []string{ |
| 461 | "**Batching** (3 tool rounds)", |
| 462 | "**calls/round** 1.7", |
| 463 | "**single-read rounds** 2 (67%)", |
| 464 | "**parallel rounds** 1 (saved 0.5s)", |
| 465 | "**start-delay p95** 50ms", |
| 466 | } { |
| 467 | if !strings.Contains(got, want) { |
| 468 | t.Fatalf("batching line missing %q:\n%s", want, got) |
| 469 | } |
| 470 | } |
| 471 | } |
| 472 | |
| 473 | func TestFilterTasks(t *testing.T) { |
| 474 | tasks := []task{{ID: "a"}, {ID: "b"}, {ID: "c"}} |
| 475 | got, err := filterTasks(tasks, " b, a ") |
| 476 | if err != nil { |
| 477 | t.Fatalf("filterTasks: %v", err) |
| 478 | } |
| 479 | if len(got) != 2 || got[0].ID != "b" || got[1].ID != "a" { |
| 480 | t.Fatalf("filtered = %v, want [b a] in request order", got) |
| 481 | } |
| 482 | if all, err := filterTasks(tasks, ""); err != nil || len(all) != 3 { |
| 483 | t.Fatalf("empty filter must keep the suite: %v %v", all, err) |
| 484 | } |
| 485 | if _, err := filterTasks(tasks, "typo"); err == nil || !strings.Contains(err.Error(), "available: a, b, c") { |
| 486 | t.Fatalf("unknown id must fail loudly with the available set, got %v", err) |
| 487 | } |
| 488 | } |
| 489 | |
| 490 | func TestRenderBodyReportsTTCSKPIs(t *testing.T) { |
| 491 | a := result{task: task{ID: "a"}, Passed: true, WallMs: 60_000, Attempt: 1, TTCSMs: 60_000} |
| 492 | b1 := result{task: task{ID: "b"}, WallMs: 40_000, Attempt: 1} |
| 493 | b2 := result{task: task{ID: "b"}, Passed: true, WallMs: 50_000, Attempt: 2, TTCSMs: 90_000} |
| 494 | c1 := result{task: task{ID: "c"}, WallMs: 30_000, Attempt: 1} |
| 495 | c2 := result{task: task{ID: "c"}, WallMs: 20_000, Attempt: 2} |
| 496 | |
| 497 | got := renderBody([]result{a, b1, b2, c1, c2}) |
| 498 | for _, want := range []string{ |
| 499 | "**Solved:** 2/3 (67%)", // attempts must not inflate the task denominator |
| 500 | "**Pass@1** 33%", |
| 501 | "**Pass@≤2** 67%", |
| 502 | "**TTCS median** 1m30s", // b's solve charges its failed first attempt |
| 503 | "**TTCS p90** 1m30s", |
| 504 | "**Solved/hour** 36.0", // 2 solves over 200s of total attempt wall |
| 505 | "`b` (try 2)", |
| 506 | } { |
| 507 | if !strings.Contains(got, want) { |
| 508 | t.Fatalf("KPI line missing %q:\n%s", want, got) |
| 509 | } |
| 510 | } |
| 511 | |
| 512 | single := renderBody([]result{a}) |
| 513 | if strings.Contains(single, "Pass@≤") { |
| 514 | t.Fatalf("single-attempt suite must not report Pass@≤k:\n%s", single) |
| 515 | } |
| 516 | if !strings.Contains(single, "**Pass@1** 100%") { |
| 517 | t.Fatalf("single-attempt suite missing Pass@1:\n%s", single) |
| 518 | } |
| 519 | } |
| 520 | |
| 521 | func TestRenderBodyReportsPerSolvedEfficiency(t *testing.T) { |
| 522 | solved := result{task: task{ID: "a"}, Passed: true, WallMs: 60_000} |
| 523 | solved.Steps = 6 |
| 524 | solved.ToolCalls = 9 |
| 525 | solved.Trajectory = &trajectorySummary{ModelRounds: 5} |
| 526 | failed := result{task: task{ID: "b"}, WallMs: 40_000} |
| 527 | failed.Steps = 8 |
| 528 | failed.ToolCalls = 3 |
| 529 | failed.Trajectory = &trajectorySummary{ModelRounds: 7} |
| 530 | |
| 531 | got := renderBody([]result{solved, failed}) |
| 532 | for _, want := range []string{ |
| 533 | "**Per solved task:**", |
| 534 | "**model requests** 14.0", // failures' spend charged to the solve |
| 535 | "tool calls 12.0", |
| 536 | "wall 1m40s", |
| 537 | "model rounds 12.0", |
| 538 | } { |
| 539 | if !strings.Contains(got, want) { |
| 540 | t.Fatalf("per-solved line missing %q:\n%s", want, got) |
| 541 | } |
| 542 | } |
| 543 | |
| 544 | if got := renderBody([]result{failed}); strings.Contains(got, "Per solved task") { |
| 545 | t.Fatalf("no solves must mean no per-solved line:\n%s", got) |
| 546 | } |
| 547 | } |
| 548 | |
| 549 | func TestRenderBodyIncludesTimeAttributionOnlyForRecordedRuns(t *testing.T) { |
| 550 | plain := result{task: task{ID: "a"}, Passed: true} |
| 551 | if got := renderBody([]result{plain}); strings.Contains(got, "Time attribution") { |
| 552 | t.Fatalf("unrecorded run must not report time attribution:\n%s", got) |
| 553 | } |
| 554 | |
| 555 | recorded := plain |
| 556 | recorded.Trajectory = &trajectorySummary{Records: 5, SpanMs: 3000, ToolMs: 1000, ModelMs: 2000} |
| 557 | got := renderBody([]result{recorded}) |
| 558 | if !strings.Contains(got, "Time attribution") || !strings.Contains(got, "(1 recorded runs)") { |
| 559 | t.Fatalf("recorded run missing time attribution:\n%s", got) |
| 560 | } |
| 561 | } |
| 562 |