From 2753f3d37b2a71f40b94001cd78176901f21b7df Mon Sep 17 00:00:00 2001 From: Huiyan Wan Date: Fri, 29 May 2026 12:04:58 +0100 Subject: [PATCH] fix(analyzer): count parallel subagents/tools by wall-clock union, not sum MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit computeEnhancedStats emitted one segment per tool/agent and summed their durations. When tools or subagents are fanned out in a single assistant turn (e.g. a 5-agent review panel, or parallel Read/Bash calls), those segments overlap in wall-clock time, so summing double-counts the concurrency — the 'Subagents' bar reported cumulative agent-seconds, not real elapsed time, and the active-time percentages could sum to >100% (e.g. 109%). Aggregate toolExec and subagent by wall-clock interval UNION instead: - subagent = time with >=1 subagent open - toolExec = busy-with-a-tool time NOT already counted as subagent (subagent wins the rare cross-kind overlap, e.g. Agent + Bash in one turn) claudeThink / planning / humanWait / humanAway are emitted as sequential, non-overlapping slices and are still summed (unchanged). On a fan-out-heavy session this dropped reported subagent time from ~53m (sum of 19 overlapping agents) to ~38m (true elapsed), and the breakdown now sums to ~100% instead of 109%. The per-call 'Tools' latency table (avg/p50/p95) is computed separately and is intentionally unchanged. Tests: 3 cases (parallel agents → union not sum; parallel non-agent tools → union; sequential agents still add up). 90/90 tests pass. --- CHANGELOG.md | 14 +++++++++++ src/analyzer.test.ts | 58 ++++++++++++++++++++++++++++++++++++++++++++ src/analyzer.ts | 43 +++++++++++++++++++++++++++++++- 3 files changed, 114 insertions(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 06ae374..54de548 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,20 @@ All notable changes to this project will be documented in this file. The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.1.0/), and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). +## [Unreleased] + +### Fixed + +- **Time Breakdown: count parallel subagents/tools by wall-clock union, not sum.** + `computeEnhancedStats` emitted one segment per tool/agent and summed them, so + tools and subagents fanned out in a single assistant turn (e.g. a panel of + review subagents) were double-counted. The `Subagents` and `Tool execution` + bars are now aggregated by wall-clock interval union (subagent wins on + cross-kind overlap), so they reflect real elapsed time and the active-time + percentages stay a true partition that sums to <=100% (previously could read + e.g. 109%). On a fan-out-heavy session this dropped reported subagent time from + ~53m (sum of 19 overlapping agents) to ~38m (true elapsed). + ## [1.0.0] - 2026-02-18 ### Added diff --git a/src/analyzer.test.ts b/src/analyzer.test.ts index b0810d5..366d12b 100644 --- a/src/analyzer.test.ts +++ b/src/analyzer.test.ts @@ -444,3 +444,61 @@ describe('analyzer: warmup cost', () => { expect(result.warmupCost.turnCount).toBe(1); }); }); + +describe('analyzer: parallel subagents counted by wall-clock union', () => { + it('does not sum overlapping (fanned-out) subagent durations', () => { + // 3 Agents dispatched in ONE assistant turn (parallel fan-out), all starting + // at 00:00:10, returning staggered at +60s / +120s / +180s. + // Per-agent durations sum to 360s; true wall-clock elapsed is 180s. + const messages: SessionMessage[] = [ + userMsg('2026-01-01T00:00:00Z', 'go'), + assistantMsg('2026-01-01T00:00:10Z', { + toolUses: [ + { id: 'a1', name: 'Agent' }, + { id: 'a2', name: 'Agent' }, + { id: 'a3', name: 'Agent' }, + ], + }), + toolResultMsg('2026-01-01T00:01:10Z', ['a1']), + toolResultMsg('2026-01-01T00:02:10Z', ['a2']), + toolResultMsg('2026-01-01T00:03:10Z', ['a3']), + assistantMsg('2026-01-01T00:03:20Z'), + ]; + const a = analyzeSession('s', messages); + expect(a.enhancedStats.subagent).toBe(180_000); // union, NOT 360_000 sum + expect(a.enhancedStats.toolExec).toBe(0); + }); + + it('does not sum overlapping parallel non-agent tool calls either', () => { + // 2 Bash calls in one turn, overlapping: spans 60s + 120s (sum 180s), union 120s. + const messages: SessionMessage[] = [ + userMsg('2026-01-01T00:00:00Z', 'go'), + assistantMsg('2026-01-01T00:00:10Z', { + toolUses: [ + { id: 'b1', name: 'Bash' }, + { id: 'b2', name: 'Bash' }, + ], + }), + toolResultMsg('2026-01-01T00:01:10Z', ['b1']), + toolResultMsg('2026-01-01T00:02:10Z', ['b2']), + assistantMsg('2026-01-01T00:02:20Z'), + ]; + const a = analyzeSession('s', messages); + expect(a.enhancedStats.toolExec).toBe(120_000); // union, NOT 180_000 sum + expect(a.enhancedStats.subagent).toBe(0); + }); + + it('sequential subagents still add up (no spurious union collapse)', () => { + // Two NON-overlapping agents: 60s then 60s = 120s union == 120s sum. + const messages: SessionMessage[] = [ + userMsg('2026-01-01T00:00:00Z', 'go'), + assistantMsg('2026-01-01T00:00:10Z', { toolUses: [{ id: 'a1', name: 'Agent' }] }), + toolResultMsg('2026-01-01T00:01:10Z', ['a1']), + assistantMsg('2026-01-01T00:01:20Z', { toolUses: [{ id: 'a2', name: 'Agent' }] }), + toolResultMsg('2026-01-01T00:02:20Z', ['a2']), + assistantMsg('2026-01-01T00:02:30Z'), + ]; + const a = analyzeSession('s', messages); + expect(a.enhancedStats.subagent).toBe(120_000); + }); +}); diff --git a/src/analyzer.ts b/src/analyzer.ts index a201f8e..83316f6 100644 --- a/src/analyzer.ts +++ b/src/analyzer.ts @@ -258,11 +258,52 @@ function detectEnhancedPhases(messages: SessionMessage[]): EnhancedTimeSegment[] return segments; } +/** Wall-clock union (ms) of possibly-overlapping [start, end] spans. */ +function unionMs(spans: Array<[number, number]>): number { + if (spans.length === 0) return 0; + const sorted = [...spans].sort((a, b) => a[0] - b[0]); + let total = 0; + let [curStart, curEnd] = sorted[0]; + for (let i = 1; i < sorted.length; i++) { + const [s, e] = sorted[i]; + if (s <= curEnd) { + if (e > curEnd) curEnd = e; + } else { + total += curEnd - curStart; + curStart = s; + curEnd = e; + } + } + return total + (curEnd - curStart); +} + function computeEnhancedStats(segments: EnhancedTimeSegment[]): EnhancedStats { const stats: EnhancedStats = { humanWait: 0, humanAway: 0, claudeThink: 0, toolExec: 0, subagent: 0, planning: 0 }; + + // claudeThink / planning / humanWait / humanAway are emitted as sequential, + // non-overlapping slices, so summing them is correct. But toolExec and + // subagent emit one segment PER tool/agent — when calls are fanned out in + // parallel (e.g. 5 review subagents from a single assistant turn) those + // segments overlap, and summing them double-counts the concurrency. Aggregate + // those two by WALL-CLOCK UNION instead so the breakdown reflects real elapsed + // time (and the active-time percentages stay a true partition that sums to + // <=100%, instead of e.g. 109%). + const subSpans: Array<[number, number]> = []; + const toolSpans: Array<[number, number]> = []; for (const seg of segments) { - stats[seg.phase] += seg.durationMs; + if (seg.phase === 'subagent') subSpans.push([seg.startTime, seg.endTime]); + else if (seg.phase === 'toolExec') toolSpans.push([seg.startTime, seg.endTime]); + else stats[seg.phase] += seg.durationMs; } + + // subagent = wall-clock with >=1 subagent open. + // toolExec = wall-clock busy with a tool but NOT already counted as subagent + // (subagent wins on the rare cross-kind overlap, e.g. Agent + Bash + // dispatched in the same turn), so the two never double-count. + const subagentMs = unionMs(subSpans); + const busyMs = unionMs([...subSpans, ...toolSpans]); + stats.subagent = subagentMs; + stats.toolExec = Math.max(0, busyMs - subagentMs); return stats; }