From 85b582159f2ab98b8b4ebf07d9edb74bdccfe72b Mon Sep 17 00:00:00 2001 From: axisrow Date: Tue, 22 Sep 2026 00:00:57 +0800 Subject: [PATCH 1/4] feat(cli): wait_loop finding, API-time metrics, longest-turn inventory MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - wait_loop: a round billing >=50k tokens with <=300 of output is a "sleep tick"; a turn with >=5 ticks is a wait-loop (corpus scan: such rounds are 47.5% of all billed tokens across 1266 local sessions). Router-retry copies (#15) are excluded from tick counting. - analyze:session: activeMinutes per turn and per session (inter-round gaps capped at 10 min — idle no longer counts as duration), dur column in BY TURN, longest-turn line + totals; loop_streak finding (back-to-back identical calls, no-op/env flavors); long_turn finding (>=45 active minutes with tool-calls breakdown). - analyze:sessions: active/wall/max turn columns, --sort active|turn, --min-turn-minutes filter; --min-minutes now measures active (API) time instead of wall-clock. Turn-boundary proxy mirrors isParsedUserChunkMessage: teammate pings and isMeta carriers do not split turns. - turnOf attribution reads ledger.turns instead of a parallel rounds array; roundsByTurn/countTools/sumBilled helpers replace per-callsite groupings. Co-Authored-By: Claude Code --- src/cli/analyzeSession.ts | 199 +++++++++++++++++++++++-- src/cli/sessionInventory.ts | 74 +++++++-- test/main/cli/analyzeSession.test.ts | 183 +++++++++++++++++++++++ test/main/cli/sessionInventory.test.ts | 75 ++++++++++ 4 files changed, 507 insertions(+), 24 deletions(-) diff --git a/src/cli/analyzeSession.ts b/src/cli/analyzeSession.ts index 192e6d4f..fbf2e0aa 100644 --- a/src/cli/analyzeSession.ts +++ b/src/cli/analyzeSession.ts @@ -78,8 +78,21 @@ export const WASTE_THRESHOLDS = { contextSpikeTokens: 30000, cacheDeadContextTokens: 20000, thinkingHeavyTokens: 8000, + longTurnActiveMinutes: 45, + loopStreakMin: 3, + waitLoopTicks: 5, } as const; +// gaps between a turn's rounds longer than this are idle, not work +// ponytail: calibration knob — tune after live runs +export const TURN_IDLE_GAP_CAP_MINUTES = 10; + +// wait-loop tick: a round that billed a huge context and produced ~nothing +// (self-waking night watches, poll cycles). Corpus-calibrated: such rounds are +// 47.5% of all billed tokens across 1266 local sessions +export const WAIT_TICK_CONTEXT_TOKENS = 50_000; +export const WAIT_TICK_OUTPUT_TOKENS = 300; + // Tool results that look like errors but are normal flow (user said no / aborted) const REJECTION_PATTERNS = [ "The user doesn't want to proceed with this tool use", @@ -92,7 +105,10 @@ export type FindingType = | 'oversized_output' | 'context_spike' | 'cache_dead' - | 'thinking_heavy'; + | 'thinking_heavy' + | 'long_turn' + | 'loop_streak' + | 'wait_loop'; export interface Finding { type: FindingType; @@ -102,6 +118,16 @@ export interface Finding { summary: string; } +// run of back-to-back identical calls being tracked for loop_streak +interface StreakState { + count: number; + tokens: number; + errors: number; + turn?: number; + start: Date; + end: Date; +} + export interface RoundRow { index: number; timestamp: Date; @@ -122,6 +148,8 @@ export interface RoundRow { export interface TurnRow { index: number; start: Date; + /** active work time: inter-round gaps capped at TURN_IDLE_GAP_CAP_MINUTES */ + activeMinutes: number; } export interface SessionLedger { @@ -137,11 +165,14 @@ export interface SessionLedger { thinkingTokens: number; noUsageRounds: number; retryCopies: number; + longestTurn?: { turn: number; activeMinutes: number; rounds: number }; costUsd?: number; costPartial?: boolean; }; models: string[]; durationMs: number; + /** sum of turn activeMinutes — API work time, idle excluded (the honest "how long did it run") */ + activeMinutes: number; billing: BillingScheme; } @@ -171,6 +202,42 @@ export function roundCostUsd(r: RoundRow): number | null { ); } +// active work time of a turn: gaps between consecutive rounds, each capped — +// hours of orchestrator silence between pings count as zero, not as a "turn" +export function turnActiveMinutes(rounds: RoundRow[]): number { + let ms = 0; + for (let i = 1; i < rounds.length; i++) { + const gap = rounds[i].timestamp.getTime() - rounds[i - 1].timestamp.getTime(); + ms += Math.min(Math.max(gap, 0), TURN_IDLE_GAP_CAP_MINUTES * 60000); + } + return Math.round(ms / 60000); +} + +// one grouping of rounds by turn, shared by totals, findings and the report +function roundsByTurn(rounds: RoundRow[]): Map { + const byTurn = new Map(); + for (const r of rounds) { + const list = byTurn.get(r.turnIndex); + if (list) list.push(r); + else byTurn.set(r.turnIndex, [r]); + } + return byTurn; +} + +const countTools = (rs: RoundRow[]): Map => { + const counts = new Map(); + for (const r of rs) { + for (const name of r.tools) counts.set(name, (counts.get(name) ?? 0) + 1); + } + return counts; +}; + +const sumBilled = (rs: RoundRow[]): number => + rs.reduce( + (s, r) => s + r.inputTokens + r.cacheReadTokens + r.cacheCreationTokens + r.outputTokens, + 0 + ); + export function totalsFromRounds(rounds: RoundRow[]): SessionLedger['totals'] { const t = { inputTokens: 0, @@ -197,10 +264,18 @@ export function totalsFromRounds(rounds: RoundRow[]): SessionLedger['totals'] { t.rereadShare = t.billedTokens > 0 ? t.cacheReadTokens / t.billedTokens : 0; const noUsageRounds = rounds.filter((r) => r.contextSize === 0).length; const retryCopies = rounds.filter((r) => r.isRetryCopy === true).length; + let longestTurn: SessionLedger['totals']['longestTurn']; + for (const [turn, rs] of roundsByTurn(rounds)) { + const active = turnActiveMinutes(rs); + if (!longestTurn || active > longestTurn.activeMinutes) { + longestTurn = { turn, activeMinutes: active, rounds: rs.length }; + } + } return { ...t, noUsageRounds, retryCopies, + ...(longestTurn ? { longestTurn } : {}), ...(costUsd > 0 ? { costUsd, costPartial: unpriced } : {}), }; } @@ -262,12 +337,19 @@ export function filterLedgerByDate( minTs = Math.min(minTs, r.timestamp.getTime()); maxTs = Math.max(maxTs, r.timestamp.getTime()); } + // turns are copies: activeMinutes must reflect the filtered window, not the + // whole session + const byTurn = roundsByTurn(rounds); + const turns = ledger.turns + .filter((t) => keptTurns.has(t.index)) + .map((t) => ({ ...t, activeMinutes: turnActiveMinutes(byTurn.get(t.index) ?? []) })); return { - turns: ledger.turns.filter((t) => keptTurns.has(t.index)), + turns, rounds, totals: totalsFromRounds(rounds), models: [...new Set(rounds.map((r) => r.model))], durationMs: Number.isFinite(minTs) ? Math.max(0, maxTs - minTs) : 0, + activeMinutes: turns.reduce((s, t) => s + t.activeMinutes, 0), billing: detectBillingScheme(rounds), }; } @@ -333,7 +415,7 @@ export function buildLedger(allMessages: ParsedMessage[]): SessionLedger { let maxTs = Number.NEGATIVE_INFINITY; const newTurn = (ts: Date): TurnRow => { - const turn: TurnRow = { index: turns.length + 1, start: ts }; + const turn: TurnRow = { index: turns.length + 1, start: ts, activeMinutes: 0 }; turns.push(turn); currentTurn = turn; return turn; @@ -384,12 +466,18 @@ export function buildLedger(allMessages: ParsedMessage[]): SessionLedger { models.add(model); } + const byTurn = roundsByTurn(rounds); + for (const turn of turns) { + turn.activeMinutes = turnActiveMinutes(byTurn.get(turn.index) ?? []); + } + return { turns, rounds, totals: totalsFromRounds(rounds), models: [...models], durationMs: Number.isFinite(minTs) ? Math.max(0, maxTs - minTs) : 0, + activeMinutes: turns.reduce((s, t) => s + t.activeMinutes, 0), billing: detectBillingScheme(rounds), }; } @@ -466,6 +554,36 @@ export function computeFindings( // with the original — counting them doubles duplicate/failed/oversized const retryCopies = getRetryCopyMessageIds(messages); const seen = new Map(); + + // loop_streak: the same call repeated back-to-back — model no-op loops + // (Bash true x114) and env retry loops (same failure hammered). Turn + // attribution walks the ledger's turn starts (sorted by construction). + let turnCursor = 0; + const turnOf = (ts: number): number | undefined => { + const turns = ledger.turns; + if (turns.length === 0 || ts < turns[0].start.getTime()) return undefined; + while (turnCursor + 1 < turns.length && turns[turnCursor + 1].start.getTime() <= ts) { + turnCursor += 1; + } + return turns[turnCursor].index; + }; + let streakKey: string | null = null; + let streak: StreakState | null = null; + const flushStreak = (): void => { + if (streak && streakKey && streak.count >= th.loopStreakMin) { + const env = streak.errors === streak.count; + findings.push({ + type: 'loop_streak', + severity: streak.count >= 5 ? 'high' : 'medium', + tokensWasted: streak.tokens, + turnIndex: streak.turn, + summary: `${short(streakKey, 60)} — x${streak.count} back-to-back (${env ? 'env loop — same failure each time' : 'no-op loop'}) ${hhmm(streak.start)}–${hhmm(streak.end)}`, + }); + } + streak = null; + streakKey = null; + }; + for (const msg of messages) { if (msg.isSidechain) continue; if (retryCopies.has(msg.uuid)) continue; @@ -476,6 +594,24 @@ export function computeFindings( const text = result ? resultText(result.content) : ''; const resultTok = estimateTokens(text); + if (streak && streakKey === key) { + streak.count += 1; + streak.tokens += resultTok; + if (result?.isError) streak.errors += 1; + streak.end = msg.timestamp; + } else { + flushStreak(); + streakKey = key; + streak = { + count: 1, + tokens: 0, + errors: result?.isError ? 1 : 0, + turn: turnOf(msg.timestamp.getTime()), + start: msg.timestamp, + end: msg.timestamp, + }; + } + if (result?.isError) { const rejected = REJECTION_PATTERNS.some((p) => text.includes(p)); if (!rejected) { @@ -506,6 +642,7 @@ export function computeFindings( } } } + flushStreak(); for (const [key, { count, tokens, first }] of seen) { if (count > 1) { const reread = tokens - first; // repeats only — the first read was legitimate @@ -544,10 +681,10 @@ export function computeFindings( }); } } + const byTurn = roundsByTurn(ledger.rounds); for (const turn of ledger.turns) { - const think = ledger.rounds - .filter((r) => r.turnIndex === turn.index) - .reduce((s, r) => s + r.thinkingTokens, 0); + const rs = byTurn.get(turn.index) ?? []; + const think = rs.reduce((s, r) => s + r.thinkingTokens, 0); if (think > th.thinkingHeavyTokens) { findings.push({ type: 'thinking_heavy', @@ -557,6 +694,38 @@ export function computeFindings( summary: `thinking ~${formatTokensCompact(think)} tok in turn ${turn.index}`, }); } + if (turn.activeMinutes >= th.longTurnActiveMinutes) { + const calls = rs.reduce((s, r) => s + r.tools.length, 0); + const top = [...countTools(rs)] + .sort((a, b) => b[1] - a[1]) + .slice(0, 5) + .map(([n, c]) => `${n} ${c}`) + .join(', '); + const billed = sumBilled(rs); + findings.push({ + type: 'long_turn', + severity: 'high', + tokensWasted: billed, + turnIndex: turn.index, + summary: `active ${turn.activeMinutes} min, ${calls} tool calls (${top || 'no tools'})`, + }); + } + const ticks = rs.filter( + (r) => + !r.isRetryCopy && + r.contextSize >= WAIT_TICK_CONTEXT_TOKENS && + r.outputTokens <= WAIT_TICK_OUTPUT_TOKENS + ); + if (ticks.length >= th.waitLoopTicks) { + const wasted = ticks.reduce((s, r) => s + r.contextSize, 0); + findings.push({ + type: 'wait_loop', + severity: ticks.length >= 20 ? 'high' : 'medium', + tokensWasted: wasted, + turnIndex: turn.index, + summary: `wait-loop: ${ticks.length} quiet rounds re-read ~${formatTokensCompact(wasted)} tok (≤300 tok of output each)`, + }); + } } const order = { high: 0, medium: 1, low: 2 } as const; @@ -736,7 +905,7 @@ function printReport( console.log('=== SESSION ==='); console.log('file :', path.basename(file)); console.log( - `turns: ${activeTurns} rounds: ${ledger.rounds.length} duration: ${dur(ledger.durationMs)}` + `turns: ${activeTurns} rounds: ${ledger.rounds.length} active: ${dur(ledger.activeMinutes * 60000)} (wall ${dur(ledger.durationMs)})` ); console.log('models:', ledger.models.join(', ') || 'n/a'); console.log('billing:', ledger.billing); @@ -748,6 +917,11 @@ function printReport( if (t.retryCopies > 0) { console.log(`ℹ ${t.retryCopies} router-retry copies detected (sums untouched — #15)`); } + if (t.longestTurn) { + console.log( + `longest turn: #${t.longestTurn.turn} (active ${t.longestTurn.activeMinutes}m, ${t.longestTurn.rounds} rounds)` + ); + } if (t.costUsd !== undefined && !opts.noCost) { const partial = t.costPartial ? ' (partial — unpriced models excluded)' : ''; console.log('est. cost: $' + t.costUsd.toFixed(2) + partial); @@ -781,10 +955,11 @@ function printReport( } console.log('=== BY TURN ==='); console.log( - `${pad('#', 3)} ${pad('time', 6)} ${padL('context', 9)} ${padL('reread', 9)} ${padL('new', 8)} ${padL('out', 7)} ${pad('think%', 7)} tools` + `${pad('#', 3)} ${pad('time', 6)} ${padL('dur', 5)} ${padL('context', 9)} ${padL('reread', 9)} ${padL('new', 8)} ${padL('out', 7)} ${pad('think%', 7)} tools` ); + const byTurn = roundsByTurn(ledger.rounds); for (const turn of ledger.turns) { - const rs = ledger.rounds.filter((r) => r.turnIndex === turn.index); + const rs = byTurn.get(turn.index) ?? []; if (rs.length === 0) continue; // trailing user msg / empty implicit turn const ctx = rs.filter((r) => r.contextSize > 0).at(-1)?.contextSize ?? 0; // ghosts (#14) don't hide the real context const reread = rs.reduce((s, r) => s + r.cacheReadTokens, 0); @@ -793,12 +968,10 @@ function printReport( const think = rs.reduce((s, r) => s + r.thinkingTokens, 0); const genTotal = think + out; const thinkPct = genTotal > 0 ? Math.round((think / genTotal) * 100) : 0; - const toolCounts = new Map(); - for (const r of rs) - for (const name of r.tools) toolCounts.set(name, (toolCounts.get(name) ?? 0) + 1); + const toolCounts = countTools(rs); const tools = [...toolCounts].map(([n, c]) => `${n} x${c}`).join(', '); console.log( - `${pad(String(turn.index), 3)} ${pad(hhmm(turn.start), 6)} ${padL(fmt(ctx), 9)} ${padL(fmt(reread), 9)} ${padL(fmt(fresh), 8)} ${padL(fmt(out), 7)} ${pad(thinkPct + '%', 7)} ${short(tools, 60)}` + `${pad(String(turn.index), 3)} ${pad(hhmm(turn.start), 6)} ${padL(turn.activeMinutes + 'm', 5)} ${padL(fmt(ctx), 9)} ${padL(fmt(reread), 9)} ${padL(fmt(fresh), 8)} ${padL(fmt(out), 7)} ${pad(thinkPct + '%', 7)} ${short(tools, 60)}` ); } console.log(); diff --git a/src/cli/sessionInventory.ts b/src/cli/sessionInventory.ts index 9890d002..22532969 100644 --- a/src/cli/sessionInventory.ts +++ b/src/cli/sessionInventory.ts @@ -5,8 +5,9 @@ * Usage: * pnpm analyze:sessions [--project ] [flags] * Flags: - * --min-minutes N only sessions running at least N minutes - * --sort FIELD duration | tokens | date (default duration) + * --min-minutes N only sessions with at least N minutes of active (API) time + * --min-turn-minutes N only sessions whose longest turn ran at least N active minutes + * --sort FIELD duration | active | turn | tokens | date (default duration) * --limit N show first N rows * --breakdown per-session model token split (models column + JSON tokensByModel) * --since / --until DATE filter by session last-activity date (YYYY-MM-DD or YYYYMMDD) @@ -37,6 +38,7 @@ import { padL, resolveProjectDir, short, + TURN_IDLE_GAP_CAP_MINUTES, } from './analyzeSession'; import { inDateRange, lastDaysSince, parseDayBound, takeFlagValue, wantsHelp } from './args'; @@ -52,8 +54,9 @@ interface ScanEntry { timestamp?: string; requestId?: string; isSidechain?: boolean; + isMeta?: boolean; cwd?: string; - message?: { model?: string; usage?: RawUsage }; + message?: { model?: string; usage?: RawUsage; content?: unknown }; } function mergeUsage(a: RawUsage, b: RawUsage): RawUsage { @@ -71,6 +74,10 @@ export interface InventoryEntry { sessionId: string; filePath: string; durationMs: number; + /** API work time: capped gaps between main-chain usage lines — same cap as turnActiveMinutes */ + activeMs: number; + /** longest single turn's active time — a 96h-active session may have no turn over 20 min */ + longestTurnMs: number; lastTs: Date | null; models: string[]; messageCount: number; @@ -96,6 +103,10 @@ export async function scanSessionFile(filePath: string): Promise(); @@ -122,6 +133,21 @@ export async function scanSessionFile(filePath: string): Promise' ) { + // API time: gap to the previous main-chain usage line, capped — + // same accounting as turnActiveMinutes, hours of silence cost zero + if (prevUsageTs !== null) { + const gap = Math.min(Math.max(ts - prevUsageTs, 0), TURN_IDLE_GAP_CAP_MINUTES * 60000); + activeMs += gap; + turnActiveMs += gap; + } + prevUsageTs = ts; if (e.message.model) models.add(e.message.model); if (e.message.usage.cache_creation_input_tokens) sawWrite = true; else if (e.message.usage.cache_read_input_tokens) sawRead = true; @@ -147,6 +181,7 @@ export async function scanSessionFile(filePath: string): Promise(); @@ -179,6 +214,8 @@ export async function scanSessionFile(filePath: string): Promise export interface InventoryOpts { projectArg?: string; minMinutes: number; - sort: 'duration' | 'tokens' | 'date'; + sort: 'duration' | 'active' | 'turn' | 'tokens' | 'date'; limit: number; json: boolean; breakdown: boolean; + minTurnMinutes: number; since?: Date; until?: Date; error?: string; @@ -271,6 +309,7 @@ export function parseInventoryArgs(argv: string[]): InventoryOpts { limit: Number.POSITIVE_INFINITY, json: false, breakdown: false, + minTurnMinutes: 0, }; let i = 0; while (i < argv.length) { @@ -286,8 +325,16 @@ export function parseInventoryArgs(argv: string[]): InventoryOpts { i = next; continue; } + if (a === '--min-turn-minutes') { + opts.minTurnMinutes = parseInt(value, 10) || 0; + i = next; + continue; + } if (a === '--sort') { - opts.sort = value === 'tokens' || value === 'date' ? value : 'duration'; + opts.sort = + value === 'tokens' || value === 'date' || value === 'active' || value === 'turn' + ? value + : 'duration'; i = next; continue; } @@ -343,8 +390,9 @@ async function main(): Promise { 'usage: pnpm analyze:sessions [--project ] [flags]', '', 'flags:', - ' --min-minutes N only sessions running at least N minutes', - ' --sort FIELD duration | tokens | date (default duration)', + ' --min-minutes N only sessions with at least N minutes of active (API) time', + ' --min-turn-minutes N only sessions whose longest turn ran at least N active minutes', + ' --sort FIELD duration | active | turn | tokens | date (default duration)', ' --limit N show first N rows', ' --breakdown per-session model token split', ' --since DATE only sessions whose last activity is on/after this date (YYYY-MM-DD or YYYYMMDD)', @@ -377,6 +425,8 @@ async function main(): Promise { entries.sort((a, b) => { if (opts.sort === 'tokens') return b.totalTokens - a.totalTokens; if (opts.sort === 'date') return (b.lastTs?.getTime() ?? 0) - (a.lastTs?.getTime() ?? 0); + if (opts.sort === 'active') return b.activeMs - a.activeMs; + if (opts.sort === 'turn') return b.longestTurnMs - a.longestTurnMs; return b.durationMs - a.durationMs; }); const hasDateFilter = opts.since !== undefined || opts.until !== undefined; @@ -384,7 +434,8 @@ async function main(): Promise { // before --since still matches if it ended inside the window, but one that // ran past --until drops out const shown = entries - .filter((e) => e.durationMs >= opts.minMinutes * 60000) + .filter((e) => e.activeMs >= opts.minMinutes * 60000) + .filter((e) => e.longestTurnMs >= opts.minTurnMinutes * 60000) .filter((e) => hasDateFilter ? e.lastTs !== null && inDateRange(e.lastTs, opts.since, opts.until) : true ) @@ -403,7 +454,8 @@ async function main(): Promise { } const notes: string[] = []; - if (opts.minMinutes > 0) notes.push(`>= ${String(opts.minMinutes)} min`); + if (opts.minMinutes > 0) notes.push(`>= ${String(opts.minMinutes)} min active`); + if (opts.minTurnMinutes > 0) notes.push(`turn >= ${String(opts.minTurnMinutes)} min`); if (opts.since && opts.until) notes.push(`${ymd(opts.since)}..${ymd(opts.until)}`); else if (opts.since) notes.push(`since ${ymd(opts.since)}`); else if (opts.until) notes.push(`until ${ymd(opts.until)}`); @@ -411,14 +463,14 @@ async function main(): Promise { console.log(`sessions: ${entries.length} total, showing ${shown.length}${note}`); console.log(); console.log( - `${padL('duration', 9)} ${pad('date', 11)} ${pad('file', 9)} ${pad('project', 42)} ${pad(opts.breakdown ? 'by model (share)' : 'models', 30)} ${padL('tokens', 9)} ${padL('msgs', 6)} ${pad('billing', 15)}` + `${padL('active', 9)} ${padL('wall', 9)} ${padL('max turn', 8)} ${pad('date', 11)} ${pad('file', 9)} ${pad('project', 42)} ${pad(opts.breakdown ? 'by model (share)' : 'models', 30)} ${padL('tokens', 9)} ${padL('msgs', 6)} ${pad('billing', 15)}` ); for (const e of shown) { // real path from the session beats decoding the encoded dir name (lossy on dashes) const project = e.cwd ? shortenHome(e.cwd) : shortenHome(decodePath(e.projectId)); const models = opts.breakdown ? modelShareCell(e) : e.models.join(', '); console.log( - `${padL(dur(e.durationMs), 9)} ${pad(e.lastTs ? e.lastTs.toISOString().slice(0, 10) : 'n/a', 11)} ${pad(e.sessionId.slice(0, 8), 9)} ${pad(short(project, 42), 42)} ${pad(short(models, 30), 30)} ${padL(formatTokensCompact(e.totalTokens), 9)} ${padL(String(e.messageCount), 6)} ${pad(e.billing, 15)}` + `${padL(dur(e.activeMs), 9)} ${padL(dur(e.durationMs), 9)} ${padL(dur(e.longestTurnMs), 8)} ${pad(e.lastTs ? e.lastTs.toISOString().slice(0, 10) : 'n/a', 11)} ${pad(e.sessionId.slice(0, 8), 9)} ${pad(short(project, 42), 42)} ${pad(short(models, 30), 30)} ${padL(formatTokensCompact(e.totalTokens), 9)} ${padL(String(e.messageCount), 6)} ${pad(e.billing, 15)}` ); } } diff --git a/test/main/cli/analyzeSession.test.ts b/test/main/cli/analyzeSession.test.ts index 27c4dc69..797caff5 100644 --- a/test/main/cli/analyzeSession.test.ts +++ b/test/main/cli/analyzeSession.test.ts @@ -17,6 +17,7 @@ import { filterLedgerByDate, normalizeCallKey, parseArgs, + turnActiveMinutes, } from '../../../src/cli/analyzeSession'; import { mapWithConcurrency, scanSessionFile } from '../../../src/cli/sessionInventory'; import { estimateTokens } from '../../../src/shared/utils/tokenFormatting'; @@ -561,3 +562,185 @@ describe('data quality (issues #14/#15)', () => { expect(duplicates).toHaveLength(0); // the copy's call is not a real repeat }); }); + +describe('long turns and loop streaks', () => { + const at = (min: number): Date => new Date(Date.UTC(2026, 8, 20, 10, min)); + const call = (id: string, command = 'true') => ({ + id, + name: 'Bash', + input: { command }, + isTask: false, + }); + const ok = (id: string) => ({ toolUseId: id, content: 'ok', isError: false }); + const err = (id: string) => ({ toolUseId: id, content: 'Error: boom', isError: true }); + + it('flags back-to-back identical calls as a no-op loop streak', () => { + const messages = [ + makeMsg({ type: 'user', content: 'go' }), + makeMsg({ + type: 'assistant', + model: 'm1', + usage: usage(10, 0, 0, 1), + toolCalls: [call('a1'), call('a2'), call('a3')], + }), + makeMsg({ type: 'user', isMeta: true, toolResults: [ok('a1'), ok('a2'), ok('a3')] }), + ]; + const findings = computeFindings(messages, buildLedger(messages)); + const streak = findings.find((f) => f.type === 'loop_streak'); + expect(streak).toBeDefined(); + expect(streak?.severity).toBe('medium'); // x3 — not yet a hang + expect(streak?.summary).toContain('x3 back-to-back (no-op loop)'); + expect(streak?.tokensWasted).toBe(2 * estimateTokens('ok')); // repeats only + }); + + it('a streak where every result is an error is an env loop', () => { + const messages = [ + makeMsg({ type: 'user', content: 'go' }), + makeMsg({ + type: 'assistant', + model: 'm1', + usage: usage(10, 0, 0, 1), + toolCalls: [call('b1'), call('b2'), call('b3'), call('b4'), call('b5')], + }), + makeMsg({ + type: 'user', + isMeta: true, + toolResults: [err('b1'), err('b2'), err('b3'), err('b4'), err('b5')], + }), + ]; + const env = computeFindings(messages, buildLedger(messages)).find( + (f) => f.type === 'loop_streak' + ); + expect(env?.summary).toContain('env loop'); + expect(env?.severity).toBe('high'); // x5 + }); + + it('calls separated by a different call do not form a streak', () => { + const messages = [ + makeMsg({ type: 'user', content: 'go' }), + makeMsg({ + type: 'assistant', + model: 'm1', + usage: usage(10, 0, 0, 1), + toolCalls: [call('c1'), call('c2', 'ls -la'), call('c3'), call('c4')], + }), + makeMsg({ + type: 'user', + isMeta: true, + toolResults: [ok('c1'), ok('c2'), ok('c3'), ok('c4')], + }), + ]; + const findings = computeFindings(messages, buildLedger(messages)); + expect(findings.filter((f) => f.type === 'loop_streak')).toHaveLength(0); + expect(findings.some((f) => f.type === 'duplicate_call')).toBe(true); + }); + + it('retry copies do not grow a streak', () => { + const messages = [ + makeMsg({ type: 'user', content: 'go' }), + makeMsg({ + type: 'assistant', + model: 'glm-5.3-flash', + requestId: 'r1', // original was logged with a requestId + usage: usage(335200, 0, 0, 100), + toolCalls: [call('t1')], + }), + makeMsg({ + type: 'assistant', + model: 'glm-5.3-flash', // copy: no requestId, identical counters + usage: usage(335200, 0, 0, 100), + toolCalls: [call('t1-copy')], + }), + makeMsg({ + type: 'user', + isMeta: true, + toolResults: [ok('t1'), ok('t1-copy')], + }), + ]; + const streaks = computeFindings(messages, buildLedger(messages)).filter( + (f) => f.type === 'loop_streak' + ); + expect(streaks).toHaveLength(0); // the copy's call is skipped from the walk + }); + + it('a dense turn (gaps under the idle cap) is flagged long_turn', () => { + const messages = [ + makeMsg({ type: 'user', content: 'go', timestamp: at(0) }), + ...Array.from({ length: 14 }, (_, i) => + makeMsg({ + type: 'assistant', + model: 'm1', + timestamp: at(i * 5), + usage: usage(10, 0, 0, 1), + }) + ), + ]; + const ledger = buildLedger(messages); + const long = computeFindings(messages, ledger).find((f) => f.type === 'long_turn'); + expect(long).toBeDefined(); + expect(long?.severity).toBe('high'); + expect(long?.turnIndex).toBe(1); + expect(ledger.turns[0].activeMinutes).toBe(65); // 13 gaps × 5 min, под капом + expect(ledger.totals.longestTurn?.activeMinutes).toBe(65); + }); + + it('idle-heavy turns stay under the flag (anti-noise regression)', () => { + const messages = [ + makeMsg({ type: 'user', content: 'go', timestamp: at(0) }), + makeMsg({ type: 'assistant', model: 'm1', timestamp: at(0), usage: usage(10, 0, 0, 1) }), + makeMsg({ type: 'assistant', model: 'm1', timestamp: at(35), usage: usage(10, 0, 0, 1) }), + makeMsg({ type: 'assistant', model: 'm1', timestamp: at(40), usage: usage(10, 0, 0, 1) }), + ]; + const ledger = buildLedger(messages); + expect(computeFindings(messages, ledger).some((f) => f.type === 'long_turn')).toBe(false); + expect(ledger.turns[0].activeMinutes).toBe(15); // 10 (кап) + 5 + }); + + it('filterLedgerByDate recomputes activeMinutes in the window', () => { + const messages = [ + makeMsg({ type: 'user', content: 'go', timestamp: at(0) }), + makeMsg({ type: 'assistant', model: 'm1', timestamp: at(0), usage: usage(10, 0, 0, 1) }), + makeMsg({ type: 'assistant', model: 'm1', timestamp: at(35), usage: usage(10, 0, 0, 1) }), + makeMsg({ type: 'assistant', model: 'm1', timestamp: at(40), usage: usage(10, 0, 0, 1) }), + ]; + const ledger = filterLedgerByDate(buildLedger(messages), at(35)); + expect(ledger.turns[0].activeMinutes).toBe(5); + }); + + it('flags a turn of quiet expensive rounds as wait_loop', () => { + const messages = [ + makeMsg({ type: 'user', content: 'go', timestamp: at(0) }), + ...Array.from({ length: 5 }, (_, i) => + makeMsg({ + type: 'assistant', + model: 'm1', + timestamp: at(i + 1), + // distinct outputs: identical counters would read as router-retry copies + usage: usage(60_000, 0, 0, 100 + i), // tick: 60k billed, ~100 out + }) + ), + ]; + const findings = computeFindings(messages, buildLedger(messages)); + const wait = findings.find((f) => f.type === 'wait_loop'); + expect(wait).toBeDefined(); + expect(wait?.severity).toBe('medium'); // 5 ticks — not yet a night watch + expect(wait?.tokensWasted).toBe(5 * 60_000); + }); + + it('needs 5 ticks: loud rounds and retry copies do not count', () => { + const messages = [ + makeMsg({ type: 'user', content: 'go' }), + // 4 real ticks, distinct outputs so they don't match each other as copies + makeMsg({ type: 'assistant', model: 'm1', usage: usage(60_000, 0, 0, 100) }), + // a router-retry copy of tick 1 — identical counters, no requestId → skipped + makeMsg({ type: 'assistant', model: 'm1', usage: usage(60_000, 0, 0, 100) }), + makeMsg({ type: 'assistant', model: 'm1', usage: usage(60_000, 0, 0, 101) }), + makeMsg({ type: 'assistant', model: 'm1', usage: usage(60_000, 0, 0, 102) }), + makeMsg({ type: 'assistant', model: 'm1', usage: usage(60_000, 0, 0, 103) }), + // a loud round: 400 tok of output — not a tick + makeMsg({ type: 'assistant', model: 'm1', usage: usage(60_000, 0, 0, 400) }), + ]; + const findings = computeFindings(messages, buildLedger(messages)); + expect(findings.some((f) => f.type === 'wait_loop')).toBe(false); + }); +}); diff --git a/test/main/cli/sessionInventory.test.ts b/test/main/cli/sessionInventory.test.ts index 3d070193..e817e783 100644 --- a/test/main/cli/sessionInventory.test.ts +++ b/test/main/cli/sessionInventory.test.ts @@ -161,10 +161,85 @@ describe('scanSessionFile tokensByModel', () => { expect(entry?.models).toEqual(['claude-sonnet-5', 'claude-haiku-4-5']); expect(entry?.totalTokens).toBe(122); expect(entry?.messageCount).toBe(6); + // API time: capped gaps between main-chain usage lines (10:05→10:06→10:07) + expect(entry?.activeMs).toBe(120000); // real path from the session's cwd, not the lossy dash-decode of the dir name expect(entry?.cwd).toBe('/Users/x/tg-content-factory'); } finally { await rm(dir, { recursive: true, force: true }); } }); + + it('parses --sort turn and --min-turn-minutes', () => { + expect(parseInventoryArgs(['--sort', 'turn']).sort).toBe('turn'); + expect(parseInventoryArgs(['--min-turn-minutes', '30']).minTurnMinutes).toBe(30); + }); + + it('caps idle gaps in activeMs', async () => { + const dir = await mkdtemp(path.join(tmpdir(), 'devtools-am-')); + try { + const file = path.join(dir, 'session-am.jsonl'); + const lines = [ + JSON.stringify({ + type: 'assistant', + uuid: 'a1', + timestamp: '2026-09-20T10:00:00Z', + message: { model: 'claude-sonnet-5', usage: { input_tokens: 5 } }, + }), + JSON.stringify({ + type: 'assistant', + uuid: 'a2', + timestamp: '2026-09-20T10:35:00Z', + message: { model: 'claude-sonnet-5', usage: { input_tokens: 5 } }, + }), + JSON.stringify({ + type: 'assistant', + uuid: 'a3', + timestamp: '2026-09-20T10:37:00Z', + message: { model: 'claude-sonnet-5', usage: { input_tokens: 5 } }, + }), + ]; + await writeFile(file, lines.join('\n')); + const entry = await scanSessionFile(file); + // 35 min gap capped at 10, plus 2 min — not 37 + expect(entry?.activeMs).toBe(720000); + } finally { + await rm(dir, { recursive: true, force: true }); + } + }); + + it('longestTurnMs resets at user-turn boundaries', async () => { + const dir = await mkdtemp(path.join(tmpdir(), 'devtools-lt-')); + try { + const file = path.join(dir, 'session-lt.jsonl'); + const userLine = (ts: string): string => + JSON.stringify({ + type: 'user', + uuid: 'u', + timestamp: ts, + message: { role: 'user', content: 'go' }, + }); + const usageLine = (uuid: string, ts: string): string => + JSON.stringify({ + type: 'assistant', + uuid, + timestamp: ts, + message: { model: 'claude-sonnet-5', usage: { input_tokens: 5 } }, + }); + const lines = [ + usageLine('a1', '2026-09-20T10:00:00Z'), // implicit turn 1: 0 active + userLine('2026-09-20T10:35:00Z'), // boundary + usageLine('a2', '2026-09-20T10:37:00Z'), + usageLine('a3', '2026-09-20T10:39:00Z'), // turn 2: 2 min active + userLine('2026-09-20T10:41:00Z'), // boundary + usageLine('a4', '2026-09-20T10:42:00Z'), // turn 3: 0 active + ]; + await writeFile(file, lines.join('\n')); + const entry = await scanSessionFile(file); + expect(entry?.activeMs).toBe(120000); // only turn 2's gaps count + expect(entry?.longestTurnMs).toBe(120000); // turn 2, not the sum across turns + } finally { + await rm(dir, { recursive: true, force: true }); + } + }); }); From 293b32e2cf86d8721a43c1dbf89babc40570907f Mon Sep 17 00:00:00 2001 From: axisrow Date: Tue, 22 Sep 2026 01:27:18 +0800 Subject: [PATCH 2/4] =?UTF-8?q?feat(cli):=20cycle=20detection=20in=20inven?= =?UTF-8?q?tory=20=E2=80=94=20back-to-back=20loop=20runs=20per=20session?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Replaces "most-repeated call" ranking with true cycle detection: only runs of >= loopStreakMin back-to-back identical calls count. `git show X | wc -l` -style variants bucket together via bashStem (pipe-cut, exported next to normalizeCallKey). Calls are counted on all main-chain assistant lines — router sessions log usage on a separate final line. - InventoryEntry.cycles: every maximal run, longest first (cap 10); table column "Nc/Mx" (cycle count + longest run); --sort streak; --min-streak N - verified against analyze:session loop_streak: srouter-177 cycles 44/27/25/14 match exactly; hhru-512 flagged as 1 cycle of 416 `true` calls — a 1h43m stall caught in a 1h46m session Co-Authored-By: Claude Code --- src/cli/analyzeSession.ts | 9 +++ src/cli/sessionInventory.ts | 89 +++++++++++++++++++++++-- test/main/cli/sessionInventory.test.ts | 92 ++++++++++++++++++++++++++ 3 files changed, 184 insertions(+), 6 deletions(-) diff --git a/src/cli/analyzeSession.ts b/src/cli/analyzeSession.ts index fbf2e0aa..1c2ca3af 100644 --- a/src/cli/analyzeSession.ts +++ b/src/cli/analyzeSession.ts @@ -525,6 +525,15 @@ export function normalizeCallKey(name: string, input: Record): } } +// Bash key without its pipe tail — hundreds of `git show X | wc -l`-style +// variants are ONE re-read loop. +// ponytail: naive pipe cut — pipes inside quoted patterns merge, accepted +export function bashStem(key: string): string { + if (!key.startsWith('Bash|')) return key; + const pipe = key.indexOf('|', 5); + return pipe === -1 ? key : key.slice(0, pipe).trimEnd(); +} + function resultText(content: string | unknown[]): string { return typeof content === 'string' ? content : JSON.stringify(content); } diff --git a/src/cli/sessionInventory.ts b/src/cli/sessionInventory.ts index 22532969..52229714 100644 --- a/src/cli/sessionInventory.ts +++ b/src/cli/sessionInventory.ts @@ -7,7 +7,8 @@ * Flags: * --min-minutes N only sessions with at least N minutes of active (API) time * --min-turn-minutes N only sessions whose longest turn ran at least N active minutes - * --sort FIELD duration | active | turn | tokens | date (default duration) + * --min-streak N only sessions where some back-to-back cycle ran at least N times + * --sort FIELD duration | active | turn | streak | tokens | date (default duration) * --limit N show first N rows * --breakdown per-session model token split (models column + JSON tokensByModel) * --since / --until DATE filter by session last-activity date (YYYY-MM-DD or YYYYMMDD) @@ -31,14 +32,17 @@ import * as readline from 'readline'; import { pathToFileURL } from 'url'; import { + bashStem, billingFromFlags, type BillingScheme, dur, + normalizeCallKey, pad, padL, resolveProjectDir, short, TURN_IDLE_GAP_CAP_MINUTES, + WASTE_THRESHOLDS, } from './analyzeSession'; import { inDateRange, lastDaysSince, parseDayBound, takeFlagValue, wantsHelp } from './args'; @@ -78,6 +82,8 @@ export interface InventoryEntry { activeMs: number; /** longest single turn's active time — a 96h-active session may have no turn over 20 min */ longestTurnMs: number; + /** every maximal run of >= loopStreakMin back-to-back identical calls, longest first (cap 10) */ + cycles: { key: string; count: number }[]; lastTs: Date | null; models: string[]; messageCount: number; @@ -108,6 +114,42 @@ export async function scanSessionFile(filePath: string): Promise(); + // back-to-back run tracking: one entry per maximal run of >= loopStreakMin + // identical calls. Buckets Bash by stem (pipe-cut) — analyze:session's + // loop_streak keys on the full input, so the two may split one session + let lastStreakKey = ''; + let curStreak = 0; + const runs: { key: string; count: number }[] = []; + const flushStreak = (): void => { + if (lastStreakKey && curStreak >= WASTE_THRESHOLDS.loopStreakMin) { + runs.push({ key: lastStreakKey, count: curStreak }); + } + }; + const countCalls = (line: ScanEntry): void => { + const m = line.message; + if (!m || !Array.isArray(m.content)) return; + for (const block of m.content) { + const b = block as { + type?: string; + name?: string; + id?: string; + input?: Record; + }; + if (b?.type !== 'tool_use' || !b.name) continue; + const dedupId = `${line.requestId ?? ''}|${b.id ?? ''}`; + if (seenCallIds.has(dedupId)) continue; + seenCallIds.add(dedupId); + const key = bashStem(normalizeCallKey(b.name, b.input ?? {})); + if (key === lastStreakKey) { + curStreak += 1; + } else { + flushStreak(); + lastStreakKey = key; + curStreak = 1; + } + } + }; let cwd: string | undefined; const models = new Set(); // anthropic-style rounds report cache writes; routers report cache_read with cw=0 @@ -148,6 +190,18 @@ export async function scanSessionFile(filePath: string): Promise' + ) { + countCalls(e); + } + // sidechain (subagent) entries stay out of totals/models/billing — same // accounting as buildLedger; timestamps and message count cover the file if ( @@ -182,6 +236,7 @@ export async function scanSessionFile(filePath: string): Promise(); @@ -216,6 +271,7 @@ export async function scanSessionFile(filePath: string): Promise b.count - a.count).slice(0, 10), lastTs: new Date(lastTs), models: [...models], messageCount, @@ -292,11 +348,12 @@ const ymd = (d: Date): string => export interface InventoryOpts { projectArg?: string; minMinutes: number; - sort: 'duration' | 'active' | 'turn' | 'tokens' | 'date'; + sort: 'duration' | 'active' | 'turn' | 'streak' | 'tokens' | 'date'; limit: number; json: boolean; breakdown: boolean; minTurnMinutes: number; + minStreak: number; since?: Date; until?: Date; error?: string; @@ -310,6 +367,7 @@ export function parseInventoryArgs(argv: string[]): InventoryOpts { json: false, breakdown: false, minTurnMinutes: 0, + minStreak: 0, }; let i = 0; while (i < argv.length) { @@ -330,9 +388,18 @@ export function parseInventoryArgs(argv: string[]): InventoryOpts { i = next; continue; } + if (a === '--min-streak') { + opts.minStreak = parseInt(value, 10) || 0; + i = next; + continue; + } if (a === '--sort') { opts.sort = - value === 'tokens' || value === 'date' || value === 'active' || value === 'turn' + value === 'tokens' || + value === 'date' || + value === 'active' || + value === 'turn' || + value === 'streak' ? value : 'duration'; i = next; @@ -392,7 +459,8 @@ async function main(): Promise { 'flags:', ' --min-minutes N only sessions with at least N minutes of active (API) time', ' --min-turn-minutes N only sessions whose longest turn ran at least N active minutes', - ' --sort FIELD duration | active | turn | tokens | date (default duration)', + ' --min-streak N only sessions where some back-to-back cycle ran at least N times', + ' --sort FIELD duration | active | turn | streak | tokens | date (default duration)', ' --limit N show first N rows', ' --breakdown per-session model token split', ' --since DATE only sessions whose last activity is on/after this date (YYYY-MM-DD or YYYYMMDD)', @@ -427,6 +495,9 @@ async function main(): Promise { if (opts.sort === 'date') return (b.lastTs?.getTime() ?? 0) - (a.lastTs?.getTime() ?? 0); if (opts.sort === 'active') return b.activeMs - a.activeMs; if (opts.sort === 'turn') return b.longestTurnMs - a.longestTurnMs; + if (opts.sort === 'streak') { + return (b.cycles[0]?.count ?? 0) - (a.cycles[0]?.count ?? 0); + } return b.durationMs - a.durationMs; }); const hasDateFilter = opts.since !== undefined || opts.until !== undefined; @@ -436,6 +507,7 @@ async function main(): Promise { const shown = entries .filter((e) => e.activeMs >= opts.minMinutes * 60000) .filter((e) => e.longestTurnMs >= opts.minTurnMinutes * 60000) + .filter((e) => (e.cycles[0]?.count ?? 0) >= opts.minStreak) .filter((e) => hasDateFilter ? e.lastTs !== null && inDateRange(e.lastTs, opts.since, opts.until) : true ) @@ -456,6 +528,7 @@ async function main(): Promise { const notes: string[] = []; if (opts.minMinutes > 0) notes.push(`>= ${String(opts.minMinutes)} min active`); if (opts.minTurnMinutes > 0) notes.push(`turn >= ${String(opts.minTurnMinutes)} min`); + if (opts.minStreak > 0) notes.push(`cycle >= ${String(opts.minStreak)}x`); if (opts.since && opts.until) notes.push(`${ymd(opts.since)}..${ymd(opts.until)}`); else if (opts.since) notes.push(`since ${ymd(opts.since)}`); else if (opts.until) notes.push(`until ${ymd(opts.until)}`); @@ -463,18 +536,22 @@ async function main(): Promise { console.log(`sessions: ${entries.length} total, showing ${shown.length}${note}`); console.log(); console.log( - `${padL('active', 9)} ${padL('wall', 9)} ${padL('max turn', 8)} ${pad('date', 11)} ${pad('file', 9)} ${pad('project', 42)} ${pad(opts.breakdown ? 'by model (share)' : 'models', 30)} ${padL('tokens', 9)} ${padL('msgs', 6)} ${pad('billing', 15)}` + `${padL('active', 9)} ${padL('wall', 9)} ${padL('max turn', 8)} ${padL('cycle', 9)} ${pad('date', 11)} ${pad('file', 9)} ${pad('project', 42)} ${pad(opts.breakdown ? 'by model (share)' : 'models', 30)} ${padL('tokens', 9)} ${padL('msgs', 6)} ${pad('billing', 15)}` ); for (const e of shown) { // real path from the session beats decoding the encoded dir name (lossy on dashes) const project = e.cwd ? shortenHome(e.cwd) : shortenHome(decodePath(e.projectId)); const models = opts.breakdown ? modelShareCell(e) : e.models.join(', '); console.log( - `${padL(dur(e.activeMs), 9)} ${padL(dur(e.durationMs), 9)} ${padL(dur(e.longestTurnMs), 8)} ${pad(e.lastTs ? e.lastTs.toISOString().slice(0, 10) : 'n/a', 11)} ${pad(e.sessionId.slice(0, 8), 9)} ${pad(short(project, 42), 42)} ${pad(short(models, 30), 30)} ${padL(formatTokensCompact(e.totalTokens), 9)} ${padL(String(e.messageCount), 6)} ${pad(e.billing, 15)}` + `${padL(dur(e.activeMs), 9)} ${padL(dur(e.durationMs), 9)} ${padL(dur(e.longestTurnMs), 8)} ${padL(cycleCell(e), 9)} ${pad(e.lastTs ? e.lastTs.toISOString().slice(0, 10) : 'n/a', 11)} ${pad(e.sessionId.slice(0, 8), 9)} ${pad(short(project, 42), 42)} ${pad(short(models, 30), 30)} ${padL(formatTokensCompact(e.totalTokens), 9)} ${padL(String(e.messageCount), 6)} ${pad(e.billing, 15)}` ); } } +// "2c/40x" — number of distinct back-to-back cycles and the longest one +const cycleCell = (e: InventoryEntry): string => + e.cycles.length > 0 ? `${String(e.cycles.length)}c/${String(e.cycles[0].count)}x` : '-'; + function modelShareCell(e: InventoryEntry): string { const total = Object.values(e.tokensByModel).reduce((s, v) => s + v, 0); if (total === 0) return 'n/a'; diff --git a/test/main/cli/sessionInventory.test.ts b/test/main/cli/sessionInventory.test.ts index e817e783..b59994b2 100644 --- a/test/main/cli/sessionInventory.test.ts +++ b/test/main/cli/sessionInventory.test.ts @@ -175,6 +175,65 @@ describe('scanSessionFile tokensByModel', () => { expect(parseInventoryArgs(['--min-turn-minutes', '30']).minTurnMinutes).toBe(30); }); + it('parses --sort streak and --min-streak', () => { + expect(parseInventoryArgs(['--sort', 'streak']).sort).toBe('streak'); + expect(parseInventoryArgs(['--min-streak', '25']).minStreak).toBe(25); + }); + + it('tracks topRepeat across assistant lines with streaming dedup', async () => { + const dir = await mkdtemp(path.join(tmpdir(), 'devtools-tr-')); + try { + const file = path.join(dir, 'session-tr.jsonl'); + const usageLine = ( + uuid: string, + ts: string, + requestId?: string, + toolUse?: { + id: string; + command: string; + } + ): string => + JSON.stringify({ + type: 'assistant', + uuid, + timestamp: ts, + ...(requestId ? { requestId } : {}), + message: { + model: 'claude-sonnet-5', + usage: { input_tokens: 5 }, + content: toolUse + ? [ + { + type: 'tool_use', + id: toolUse.id, + name: 'Bash', + input: { command: toolUse.command }, + }, + ] + : [], + }, + }); + const lines = [ + // one stem, three calls: two exact + one piped variant (merged by stem) + usageLine('a1', '2026-09-20T10:00:00Z', 'r1', { id: 't1', command: 'git show abc' }), + usageLine('a2', '2026-09-20T10:01:00Z', 'r1', { id: 't2', command: 'git show abc' }), + usageLine('a3', '2026-09-20T10:02:00Z', undefined, { + id: 't3', + command: 'git show abc | wc -l', + }), + // streaming snapshot: same requestId + same toolUseId → counted once + usageLine('a4', '2026-09-20T10:03:00Z', 'r9', { id: 'd1', command: 'ls -la' }), + usageLine('a5', '2026-09-20T10:04:00Z', 'r9', { id: 'd1', command: 'ls -la' }), + ]; + await writeFile(file, lines.join('\n')); + const entry = await scanSessionFile(file); + // a1,a2,a3 share one stem back-to-back → one cycle of 3 + expect(entry?.cycles).toEqual([{ key: 'Bash|git show abc', count: 3 }]); + } finally { + await rm(dir, { recursive: true, force: true }); + } + }); + it('caps idle gaps in activeMs', async () => { const dir = await mkdtemp(path.join(tmpdir(), 'devtools-am-')); try { @@ -242,4 +301,37 @@ describe('scanSessionFile tokensByModel', () => { await rm(dir, { recursive: true, force: true }); } }); + + it('distinguishes cycles from scattered repeats', async () => { + const dir = await mkdtemp(path.join(tmpdir(), 'devtools-sc-')); + try { + const file = path.join(dir, 'session-sc.jsonl'); + const line = (uuid: string, n: number, command: string): string => + JSON.stringify({ + type: 'assistant', + uuid, + timestamp: `2026-09-20T10:0${n}:00Z`, + message: { + model: 'claude-sonnet-5', + usage: { input_tokens: 5 }, + content: [{ type: 'tool_use', id: uuid, name: 'Bash', input: { command } }], + }, + }); + // A,A,B,A,A,A — repeat(A)=5 but the longest back-to-back run is 3 + const lines = [ + line('a1', 0, 'probe one'), + line('a2', 1, 'probe one'), + line('a3', 2, 'git show xyz'), + line('a4', 3, 'probe one'), + line('a5', 4, 'probe one'), + line('a6', 5, 'probe one'), + ]; + await writeFile(file, lines.join('\n')); + const entry = await scanSessionFile(file); + // A appears 5 times total, but only its 3-run qualifies as a cycle + expect(entry?.cycles).toEqual([{ key: 'Bash|probe one', count: 3 }]); + } finally { + await rm(dir, { recursive: true, force: true }); + } + }); }); From 627310295301de45ac01a62a3763453ce1978452 Mon Sep 17 00:00:00 2001 From: axisrow Date: Tue, 22 Sep 2026 02:06:22 +0800 Subject: [PATCH 3/4] =?UTF-8?q?fix(cli):=20review=20follow-up=20=E2=80=94?= =?UTF-8?q?=20long=5Fturn=20waste,=20activeMs=20parity,=20honest=20--min-s?= =?UTF-8?q?treak?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - long_turn: tokensWasted is 0 — it is an observation, not waste; the summary carries the activity numbers, so consumers summing tokensWasted no longer book a healthy turn's whole billing as waste (drops the now-unused sumBilled) - inventory activeMs: streaming snapshots of an already-seen requestId no longer add gaps — one anchor per requestId, parity with analyze:session's request-deduplicated rounds (round timestamp = last snapshot) - --min-streak: help text states the 3x recording floor so 1-2 are not silent no-ops Co-Authored-By: Claude Code --- src/cli/analyzeSession.ts | 12 ++++-------- src/cli/sessionInventory.ts | 16 ++++++++++------ test/main/cli/analyzeSession.test.ts | 1 + test/main/cli/sessionInventory.test.ts | 6 ++++-- 4 files changed, 19 insertions(+), 16 deletions(-) diff --git a/src/cli/analyzeSession.ts b/src/cli/analyzeSession.ts index 1c2ca3af..5523d7d4 100644 --- a/src/cli/analyzeSession.ts +++ b/src/cli/analyzeSession.ts @@ -232,12 +232,6 @@ const countTools = (rs: RoundRow[]): Map => { return counts; }; -const sumBilled = (rs: RoundRow[]): number => - rs.reduce( - (s, r) => s + r.inputTokens + r.cacheReadTokens + r.cacheCreationTokens + r.outputTokens, - 0 - ); - export function totalsFromRounds(rounds: RoundRow[]): SessionLedger['totals'] { const t = { inputTokens: 0, @@ -710,11 +704,13 @@ export function computeFindings( .slice(0, 5) .map(([n, c]) => `${n} ${c}`) .join(', '); - const billed = sumBilled(rs); findings.push({ type: 'long_turn', severity: 'high', - tokensWasted: billed, + // observation, not waste — unlike other findings this books no redundant + // tokens (the summary carries the activity numbers), so consumers summing + // tokensWasted don't count a healthy turn's whole billing as waste + tokensWasted: 0, turnIndex: turn.index, summary: `active ${turn.activeMinutes} min, ${calls} tool calls (${top || 'no tools'})`, }); diff --git a/src/cli/sessionInventory.ts b/src/cli/sessionInventory.ts index 52229714..6080ed4d 100644 --- a/src/cli/sessionInventory.ts +++ b/src/cli/sessionInventory.ts @@ -7,7 +7,7 @@ * Flags: * --min-minutes N only sessions with at least N minutes of active (API) time * --min-turn-minutes N only sessions whose longest turn ran at least N active minutes - * --min-streak N only sessions where some back-to-back cycle ran at least N times + * --min-streak N only sessions where some back-to-back cycle ran at least N times (runs < 3x are never recorded) * --sort FIELD duration | active | turn | streak | tokens | date (default duration) * --limit N show first N rows * --breakdown per-session model token split (models column + JSON tokensByModel) @@ -78,7 +78,7 @@ export interface InventoryEntry { sessionId: string; filePath: string; durationMs: number; - /** API work time: capped gaps between main-chain usage lines — same cap as turnActiveMinutes */ + /** API work time: capped gaps between main-chain usage lines (one anchor per requestId) — same cap as turnActiveMinutes */ activeMs: number; /** longest single turn's active time — a 96h-active session may have no turn over 20 min */ longestTurnMs: number; @@ -210,9 +210,13 @@ export async function scanSessionFile(filePath: string): Promise' ) { - // API time: gap to the previous main-chain usage line, capped — - // same accounting as turnActiveMinutes, hours of silence cost zero - if (prevUsageTs !== null) { + // API time: gap to the previous main-chain usage line, capped — same + // accounting as turnActiveMinutes, hours of silence cost zero. Streaming + // snapshots of an already-seen requestId add no gap (analyze:session keeps + // one round per request, anchored at the last line) but still advance the + // anchor, so the next gap starts from the newest line of the request. + const snapshot = e.requestId !== undefined && usageByRequestId.has(e.requestId); + if (prevUsageTs !== null && !snapshot) { const gap = Math.min(Math.max(ts - prevUsageTs, 0), TURN_IDLE_GAP_CAP_MINUTES * 60000); activeMs += gap; turnActiveMs += gap; @@ -459,7 +463,7 @@ async function main(): Promise { 'flags:', ' --min-minutes N only sessions with at least N minutes of active (API) time', ' --min-turn-minutes N only sessions whose longest turn ran at least N active minutes', - ' --min-streak N only sessions where some back-to-back cycle ran at least N times', + ` --min-streak N only sessions where some back-to-back cycle ran at least N times (floor: ${String(WASTE_THRESHOLDS.loopStreakMin)}x — shorter runs are not recorded)`, ' --sort FIELD duration | active | turn | streak | tokens | date (default duration)', ' --limit N show first N rows', ' --breakdown per-session model token split', diff --git a/test/main/cli/analyzeSession.test.ts b/test/main/cli/analyzeSession.test.ts index 797caff5..1e985a24 100644 --- a/test/main/cli/analyzeSession.test.ts +++ b/test/main/cli/analyzeSession.test.ts @@ -680,6 +680,7 @@ describe('long turns and loop streaks', () => { expect(long).toBeDefined(); expect(long?.severity).toBe('high'); expect(long?.turnIndex).toBe(1); + expect(long?.tokensWasted).toBe(0); // observation, not waste — unlike other findings expect(ledger.turns[0].activeMinutes).toBe(65); // 13 gaps × 5 min, под капом expect(ledger.totals.longestTurn?.activeMinutes).toBe(65); }); diff --git a/test/main/cli/sessionInventory.test.ts b/test/main/cli/sessionInventory.test.ts index b59994b2..608046ec 100644 --- a/test/main/cli/sessionInventory.test.ts +++ b/test/main/cli/sessionInventory.test.ts @@ -161,8 +161,10 @@ describe('scanSessionFile tokensByModel', () => { expect(entry?.models).toEqual(['claude-sonnet-5', 'claude-haiku-4-5']); expect(entry?.totalTokens).toBe(122); expect(entry?.messageCount).toBe(6); - // API time: capped gaps between main-chain usage lines (10:05→10:06→10:07) - expect(entry?.activeMs).toBe(120000); + // API time: r1's two streaming snapshots (10:05, 10:06) anchor once — the + // only gap is r1-last (10:06) → haiku (10:07); the intra-request minute + // does not count (parity with analyze:session's one round per request) + expect(entry?.activeMs).toBe(60000); // real path from the session's cwd, not the lossy dash-decode of the dir name expect(entry?.cwd).toBe('/Users/x/tg-content-factory'); } finally { From 48fe08f5c6fbed1def5bc344ce5a9f801702900b Mon Sep 17 00:00:00 2001 From: axisrow Date: Tue, 22 Sep 2026 02:21:45 +0800 Subject: [PATCH 4/4] fix(cli): reuse isParsedUserChunkMessage for inventory turn boundaries MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Replace the hand-rolled string-content + teammate-substring check with the real guard (it reads only type/isMeta/content, all present on the raw scan line; cast is commented). Array-content user messages now split turns and system-output lines (// ) no longer do — matching buildLedger structurally, so the inventory turn model cannot drift from analyze:session again. The local !isSidechain check stays: sidechain lines never split main-chain turns. Co-Authored-By: Claude Code --- src/cli/sessionInventory.ts | 17 ++++--- test/main/cli/sessionInventory.test.ts | 67 ++++++++++++++++++++++++++ 2 files changed, 78 insertions(+), 6 deletions(-) diff --git a/src/cli/sessionInventory.ts b/src/cli/sessionInventory.ts index 6080ed4d..9204c114 100644 --- a/src/cli/sessionInventory.ts +++ b/src/cli/sessionInventory.ts @@ -17,6 +17,7 @@ * --json machine-readable output */ +import { isParsedUserChunkMessage, type ParsedMessage } from '@main/types'; import { decodePath, extractSessionId, @@ -175,15 +176,19 @@ export async function scanSessionFile(filePath: string): Promise { } }); + it('array-content user messages split turns (faithful isParsedUserChunkMessage guard)', async () => { + const dir = await mkdtemp(path.join(tmpdir(), 'devtools-ac-')); + try { + const file = path.join(dir, 'session-ac.jsonl'); + const usageLine = (uuid: string, ts: string): string => + JSON.stringify({ + type: 'assistant', + uuid, + timestamp: ts, + message: { model: 'claude-sonnet-5', usage: { input_tokens: 5 } }, + }); + const lines = [ + usageLine('a1', '2026-09-20T10:00:00Z'), + usageLine('a2', '2026-09-20T10:01:00Z'), // turn 1: 1 min active + // newer-format user turn: array content with a text block + JSON.stringify({ + type: 'user', + uuid: 'u2', + timestamp: '2026-09-20T10:02:00Z', + message: { role: 'user', content: [{ type: 'text', text: 'go again' }] }, + }), + usageLine('a3', '2026-09-20T10:10:00Z'), // turn 2: 0 active + ]; + await writeFile(file, lines.join('\n')); + const entry = await scanSessionFile(file); + expect(entry?.activeMs).toBe(60000); // turn 1 only; turn 2 has a single round + expect(entry?.longestTurnMs).toBe(60000); // not the uncapped merge (10 min) + } finally { + await rm(dir, { recursive: true, force: true }); + } + }); + + it('local-command-stdout lines do not split turns', async () => { + const dir = await mkdtemp(path.join(tmpdir(), 'devtools-so-')); + try { + const file = path.join(dir, 'session-so.jsonl'); + const usageLine = (uuid: string, ts: string): string => + JSON.stringify({ + type: 'assistant', + uuid, + timestamp: ts, + message: { model: 'claude-sonnet-5', usage: { input_tokens: 5 } }, + }); + const lines = [ + usageLine('a1', '2026-09-20T10:00:00Z'), + // bash-mode command output: type user, string content, falsy isMeta — + // must NOT be a boundary (buildLedger does not split here either) + JSON.stringify({ + type: 'user', + uuid: 'u1', + timestamp: '2026-09-20T10:01:00Z', + message: { + role: 'user', + content: 'done', + }, + }), + usageLine('a2', '2026-09-20T10:02:00Z'), // same turn: 2 min total + ]; + await writeFile(file, lines.join('\n')); + const entry = await scanSessionFile(file); + expect(entry?.activeMs).toBe(120000); // 10:00→10:02, the stdout line did not reset + expect(entry?.longestTurnMs).toBe(120000); + } finally { + await rm(dir, { recursive: true, force: true }); + } + }); + it('distinguishes cycles from scattered repeats', async () => { const dir = await mkdtemp(path.join(tmpdir(), 'devtools-sc-')); try {