diff --git a/core/dev/turn-split.mjs b/core/dev/turn-split.mjs index 6f3c6e45d..f81c01249 100644 --- a/core/dev/turn-split.mjs +++ b/core/dev/turn-split.mjs @@ -3,7 +3,7 @@ // and the task (the message that opened the turn). // // node dev/turn-split.mjs [--sessions ] [--session ] [--turn ] -// [--tz ] [--top ] [--json] +// [--tz ] [--top ] [--stats] [--room ] [--json] // // `--sessions` is the DSH session root (default `$DSH_HOME/sessions`); the script walks it // for `session.v4.jsonl.zstd` files. Every Session log carries, per call, the provider's own @@ -27,7 +27,7 @@ import { join, resolve } from 'node:path' import { pathToFileURL } from 'node:url' import { zstdDecompressSync } from 'node:zlib' -const USAGE = 'usage: node dev/turn-split.mjs [--sessions ] [--session ] [--turn ] [--tz ] [--days] [--top ] [--json]' +const USAGE = 'usage: node dev/turn-split.mjs [--sessions ] [--session ] [--turn ] [--tz ] [--days] [--top ] [--stats] [--room ] [--json]' const ZSTD_MAGIC = 4247762216 function die(message) { @@ -36,7 +36,7 @@ function die(message) { } function parseArgs(argv) { - const flags = { sessions: null, session: null, turn: null, tz: 'UTC', days: false, top: 5, json: false } + const flags = { sessions: null, session: null, turn: null, tz: 'UTC', days: false, top: 5, json: false, stats: false, room: null } for (let index = 0; index < argv.length; index += 1) { const arg = argv[index] const value = () => { @@ -52,6 +52,8 @@ function parseArgs(argv) { case '--tz': flags.tz = value(); break case '--top': flags.top = Number(value()); break case '--days': flags.days = true; break + case '--stats': flags.stats = true; break + case '--room': flags.room = value(); break case '--json': flags.json = true; break case '--help': case '-h': console.log(USAGE); process.exit(0); break default: die(`unknown argument ${arg}\n${USAGE}`) @@ -59,6 +61,14 @@ function parseArgs(argv) { } if (!Number.isSafeInteger(flags.top) || flags.top < 1) die('--top must be a whole number') if (flags.turn !== null && !Number.isSafeInteger(flags.turn)) die('--turn must be a whole number') + // A zone the runtime does not know would otherwise reach `Intl.DateTimeFormat` and throw an + // uncaught RangeError from inside `localDay`, after the whole sample has been read. + try { + new Intl.DateTimeFormat('en-CA', { timeZone: flags.tz }) + } catch { + die(`unknown time zone ${flags.tz}`) + } + if (flags.stats && flags.days) die('--stats and --days measure different things; pass one of them') return flags } @@ -144,6 +154,11 @@ export function foldSessionEvents(events) { let toolCallNames = new Map() const largestTool = new Map() const toolTotal = new Map() + const toolCount = new Map() + const toolAddedByName = new Map() + const turnStarts = [] + const retries = [] + const attempts = [] for (const event of events) { const data = event?.data ?? {} switch (event?.type) { @@ -155,6 +170,7 @@ export function foldSessionEvents(events) { break case 'turn/start': turn = data.turn ?? null + turnStarts.push({ turn, time: event.time }) open = true for (let index = messages.length - pending; index < messages.length; index += 1) messages[index].turn = turn pending = 0 @@ -179,8 +195,13 @@ export function foldSessionEvents(events) { const callId = data.message?.toolCallId ?? data.message?.source?.callId const resultTurn = open ? turn : (data.turn ?? null) const resultChars = textOf(data.message?.content).length + const resultName = toolCallNames.get(callId) ?? data.message?.toolName ?? '' largestTool.set(resultTurn, Math.max(largestTool.get(resultTurn) ?? 0, resultChars)) toolTotal.set(resultTurn, (toolTotal.get(resultTurn) ?? 0) + resultChars) + toolCount.set(resultTurn, (toolCount.get(resultTurn) ?? 0) + 1) + const byName = toolAddedByName.get(resultTurn) ?? {} + byName[resultName] = (byName[resultName] ?? 0) + resultChars + toolAddedByName.set(resultTurn, byName) messages.push({ role: 'tool', turn: open ? turn : (data.turn ?? null), @@ -189,6 +210,12 @@ export function foldSessionEvents(events) { }) break } + case 'llm/retry': + retries.push({ time: event.time }) + break + case 'assistant/attempt': + attempts.push({ time: event.time, usage: usageOf(data.stream) }) + break case 'assistant/message': { const usage = usageOf(data.stream) const current = data.turn ?? null @@ -241,7 +268,7 @@ export function foldSessionEvents(events) { break } } - return { steps, turns: [...turns.values()], largestTool, toolTotal, systemChars: system.length, toolsChars: tools.length } + return { steps, turns: [...turns.values()], largestTool, toolTotal, toolCount, toolAddedByName, turnStarts, retries, attempts, systemChars: system.length, toolsChars: tools.length } } // The fixed block is constant for every call of one Session, so it is that Session's @@ -290,18 +317,22 @@ export function splitStep(step, fit) { return { fixed, task: share(step.chars.task), history: share(step.chars.history), tool: share(step.chars.tool) } } -export function readSessionFile(file) { +// The decoded artifact: its events, and the text they came from, which is how the fan-out +// statistic learns that a Session names a room. +export function decodeSession(file) { const buffer = readFileSync(file) const { frames } = scanZstdFrames(buffer) const events = [] + let text = '' for (const { start, end } of frames) { - let text + let frame try { - text = zstdDecompressSync(buffer.subarray(start, end)).toString('utf8') + frame = zstdDecompressSync(buffer.subarray(start, end)).toString('utf8') } catch { continue } - for (const line of text.split('\n')) { + text += frame + for (const line of frame.split('\n')) { if (!line.trim()) continue try { events.push(JSON.parse(line)) @@ -310,7 +341,11 @@ export function readSessionFile(file) { } } } - return events + return { events, text } +} + +export function readSessionFile(file) { + return decodeSession(file).events } export function findSessionFiles(root) { @@ -341,6 +376,139 @@ const localDay = (time, tz) => { } const integer = (value) => Math.round(value).toLocaleString('en-US') +// The statistics §5, §7 and §8 of the report quote, so each number there has one command +// behind it. Every figure is either counted in the log or derived by the formula printed +// beside it; nothing here estimates. +const FANOUT_WINDOW = 10 * 60_000 + +function printStats({ flags, sessions, rows, root }) { + const percentile = (values, q) => { + if (values.length === 0) return 0 + const sorted = values.slice().sort((a, b) => a - b) + return sorted[Math.min(sorted.length - 1, Math.floor((sorted.length - 1) * q))] + } + const dayOf = (time) => localDay(time, flags.tz) + const out = { sample: { root: resolve(root), sessions: sessions.length, tz: flags.tz }, toolResults: null, fanout: null, retries: [] } + const lines = [] + + // §5: the tool results of one turn — the one with the most tool text unless --turn names it. + const sampleTurn = flags.turn !== null + ? rows.find((row) => row.turn === flags.turn) + : rows.slice().sort((a, b) => b.toolTotal - a.toolTotal)[0] + lines.push('## Tool results') + if (sampleTurn) { + const added = sampleTurn.toolTotal + const bash = sampleTurn.addedByName.bash ?? 0 + const share = added > 0 ? bash / added * 100 : 0 + out.toolResults = { + session: sampleTurn.session, + turn: sampleTurn.turn, + results: sampleTurn.toolCount, + characters: added, + onLastSurface: sampleTurn.toolAdded, + largest: sampleTurn.largestTool, + bash, + bashShare: share, + carried: sampleTurn.tool, + } + lines.push(`${sampleTurn.session} turn ${sampleTurn.turn} (the turn with the most tool text): ` + + `results ${integer(sampleTurn.toolCount)}; characters added ${integer(added)}; largest single result ${integer(sampleTurn.largestTool)}; ` + + `bash ${integer(bash)} chars (${share.toFixed(1)}%); still on the last call's surface ${integer(sampleTurn.toolAdded)} chars; ` + + `carried in the turn's prompts ${integer(sampleTurn.tool)} tokens`) + } else { + lines.push('not measured: no turn in the sample could be split (every Session needs 8 calls)') + } + lines.push('') + + // §7: fan-out around one room's own Session — how many member Bots a single room message + // wakes within the window, and what their calls cost that day. + lines.push('## Fan-out') + if (flags.room === null) { + lines.push('not measured: pass --room ') + } else { + const room = sessions.find((session) => session.id.startsWith(flags.room)) + if (!room) die(`no Session matching --room ${flags.room}`) + const members = sessions.filter((session) => session.id !== room.id && session.text.includes(room.id)) + const messages = room.turnStarts.map((start) => start.time).filter((time) => Number.isFinite(time)) + if (messages.length === 0) die(`no room message in ${room.id}`) + const bots = [] + const turns = [] + for (const time of messages) { + const waking = [] + for (const session of members) { + for (const start of session.turnStarts) { + if (start.time > time && start.time <= time + FANOUT_WINDOW) waking.push(session.id) + } + } + bots.push(new Set(waking).size) + turns.push(waking.length) + } + const days = new Map() + for (const session of members) { + for (const step of session.steps) { + const day = dayOf(step.time) + const row = days.get(day) ?? { day, calls: 0, prompt: 0, fixed: 0 } + row.calls += 1 + row.prompt += step.prompt + row.fixed += session.fixed ? splitStep(step, session.fixed).fixed : 0 + days.set(day, row) + } + } + const rowsOut = [...days.values()].sort((a, b) => a.day.localeCompare(b.day)) + const fixed = rowsOut.reduce((sum, row) => sum + row.fixed, 0) + out.fanout = { + room: room.id, + windowMinutes: FANOUT_WINDOW / 60_000, + messages: messages.length, + members: members.length, + bots: { p50: percentile(bots, 0.5), p90: percentile(bots, 0.9), max: Math.max(0, ...bots) }, + turns: { p50: percentile(turns, 0.5), p90: percentile(turns, 0.9), max: Math.max(0, ...turns) }, + days: rowsOut, + fixedPerMessage: messages.length === 0 ? 0 : fixed / messages.length, + } + lines.push(`${room.id}: ${integer(messages.length)} user messages; ${integer(members.length)} member Sessions name it; window ${FANOUT_WINDOW / 60_000} minutes`) + lines.push(`member Bots per message p50/p90/max ${percentile(bots, 0.5)}/${percentile(bots, 0.9)}/${Math.max(0, ...bots)}`) + lines.push(`member turns per message p50/p90/max ${percentile(turns, 0.5)}/${percentile(turns, 0.9)}/${Math.max(0, ...turns)}`) + lines.push('day calls prompt fixed fixed share') + for (const row of rowsOut) { + lines.push(`${row.day} ${String(row.calls).padStart(6)} ${integer(row.prompt).padStart(13)} ${integer(row.fixed).padStart(12)} ${(row.prompt > 0 ? row.fixed / row.prompt * 100 : 0).toFixed(1).padStart(11)}%`) + } + lines.push(`fixed block per user message: ${integer(fixed / messages.length)} tokens (${integer(fixed)} / ${integer(messages.length)} messages)`) + } + lines.push('') + + // §8: retries and attempts — how many, and how many attempts ever reported usage. + const retryDays = new Map() + const row = (time) => { + const day = dayOf(time) + const found = retryDays.get(day) ?? { day, retries: 0, attempts: 0, used: 0 } + retryDays.set(day, found) + return found + } + for (const session of sessions) { + for (const retry of session.retries) row(retry.time).retries += 1 + for (const attempt of session.attempts) { + const found = row(attempt.time) + found.attempts += 1 + const usage = attempt.usage ?? {} + if (['inputTokens', 'cacheReadTokens', 'cacheWriteTokens', 'outputTokens'].some((key) => Number.isFinite(usage[key]) && usage[key] > 0)) found.used += 1 + } + } + const retryRows = [...retryDays.values()].sort((a, b) => a.day.localeCompare(b.day)) + out.retries = retryRows + lines.push('## Retries') + lines.push('day llm/retry attempts attempts with non-zero usage') + for (const values of retryRows) { + lines.push(`${values.day} ${String(values.retries).padStart(9)} ${String(values.attempts).padStart(10)} ${String(values.used).padStart(27)}`) + } + + if (flags.json) { + console.log(JSON.stringify(out, null, 2)) + return + } + for (const line of lines) console.log(line) +} + function main(argv) { const flags = parseArgs(argv) const root = flags.sessions === null ? join(process.env.DSH_HOME ?? join(homedir(), '.dsh'), 'sessions') : flags.sessions @@ -356,9 +524,10 @@ function main(argv) { for (const file of files) { const id = file.split('/').at(-2) if (flags.session !== null && !id.startsWith(flags.session)) continue - const folded = foldSessionEvents(readSessionFile(file)) + const { events, text } = decodeSession(file) + const folded = foldSessionEvents(events) if (folded.steps.length === 0) continue - sessions.push({ id, file, ...folded, fixed: fitFixed(folded.steps) }) + sessions.push({ id, file, text, ...folded, fixed: fitFixed(folded.steps) }) } if (sessions.length === 0) die('no Session in the sample carried a provider usage report') const rows = [] @@ -385,6 +554,8 @@ function main(argv) { prompt: total.prompt, output: turn.output, toolAdded: steps.at(-1).chars.tool, + toolCount: session.toolCount?.get(turn.turn) ?? 0, + addedByName: session.toolAddedByName?.get(turn.turn) ?? {}, largestTool: session.largestTool?.get(turn.turn) ?? 0, toolTotal: session.toolTotal?.get(turn.turn) ?? 0, fixed: total.fixed, @@ -438,6 +609,10 @@ function main(argv) { } return } + if (flags.stats) { + printStats({ flags, sessions, rows, root }) + return + } if (rows.length === 0) die('no turn in the sample could be split (every Session needs 8 calls)') if (flags.turn !== null) { const only = rows.filter((row) => row.turn === flags.turn) @@ -454,8 +629,12 @@ function main(argv) { console.log(`sample: ${sessions.length} Sessions under ${resolve(root)}, zone ${flags.tz}`) console.log('') console.log('## Fixed block per call (measured: the intercept of each Session\'s prompt fit)') + // A Session whose prompt falls as its messages grow has a fixed block but no + // characters-per-token figure; the median is taken over the Sessions that have one. + const perToken = fits.map((fit) => fit.charsPerToken).filter((value) => Number.isFinite(value)) console.log(`Sessions with a fit: ${fits.length}; fixed tokens p50 ${integer(median(fits.map((fit) => fit.fixedTokens)))}; ` - + `fixed chars p50 ${integer(median(fits.map((fit) => fit.fixedChars)))}; message chars/token p50 ${median(fits.map((fit) => fit.charsPerToken)).toFixed(2)}; ` + + `fixed chars p50 ${integer(median(fits.map((fit) => fit.fixedChars)))} (first call's surface); ` + + `message chars/token p50 ${perToken.length === 0 ? 'n/a' : median(perToken).toFixed(2)}; ` + `R2 p50 ${median(fits.map((fit) => fit.r2)).toFixed(3)}`) console.log('') console.log('## Top turns by prompt') @@ -469,9 +648,13 @@ function main(argv) { const first = top[0] if (first) { console.log('') - console.log(`## Turn ${first.turn} of ${first.session}: one call's surface`) - console.log(`system prompt ${integer(first.systemChars)} chars; tool schemas ${integer(first.toolsChars)} chars; ` - + `fixed block ${integer(first.fit.fixedTokens)} tokens (${(first.fit.fixedChars / first.fit.fixedTokens).toFixed(2)} chars/token)`) + // §4 of the report is the turn's LAST call, not its first: the surface grows inside a + // turn, so the two are not interchangeable. + const surface = first.steps.at(-1) + const surfaceChars = surface.systemChars + surface.toolsChars + console.log(`## Turn ${first.turn} of ${first.session}: the turn's last call's surface`) + console.log(`system prompt ${integer(surface.systemChars)} chars; tool schemas ${integer(surface.toolsChars)} chars; ` + + `fixed block ${integer(first.fit.fixedTokens)} tokens (${(surfaceChars / first.fit.fixedTokens).toFixed(2)} chars/token)`) console.log(`calls ${first.calls}; provider prompt ${integer(first.prompt)} tokens (${integer(first.prompt / first.calls)} per call); output ${integer(first.output)} tokens`) console.log(`tool text added by the turn ${integer(first.toolTotal)} chars; still on the last call's surface ${integer(first.toolAdded)} chars; largest single result ${integer(first.largestTool)} chars`) if (first.toolNames.size > 0) { diff --git a/core/test/turn-split.test.js b/core/test/turn-split.test.js index 9e49dab78..481f2eec2 100644 --- a/core/test/turn-split.test.js +++ b/core/test/turn-split.test.js @@ -212,3 +212,200 @@ test('every row of the committed split report carries its provenance', () => { assert.equal(row.cells.length, row.header.length, `a row has ${row.cells.length} cells, its table ${row.header.length}: | ${row.cells.join(' | ')} |`) } }) + +// ---- #1259: the three follow-ups #1241's INC left open ------------------------------- + +const TOOLS = JSON.stringify([{ name: 'bash', description: 'd'.repeat(900) }]) + +// One Session whose system prompt grows mid-way: the first call's surface is not the last +// call's, which is the §2/§4 mismatch this issue is about. +function grownFixture(t) { + const dir = mkdtempSync(join(tmpdir(), 'turn-split-grown-')) + const workspace = join(dir, 'sessions', '--workspace--') + mkdirSync(workspace, { recursive: true }) + const events = [system('S'.repeat(100)), header([{ name: 'bash', description: 'd'.repeat(900) }]), { type: 'turn/start', data: { turn: 1 } }] + for (let step = 1; step <= 10; step += 1) { + if (step === 6) events.push(system('S'.repeat(300))) + events.push(user(`task ${step} `.repeat(step * 10))) + events.push(assistant(1, step, 100, 48_000 + step * 500, 10)) + } + const folder = join(workspace, 'session-grown') + mkdirSync(folder) + writeFileSync(join(folder, 'session.v4.jsonl.zstd'), sessionFile(events)) + t.after(() => rmSync(dir, { recursive: true, force: true })) + return join(dir, 'sessions') +} + +test('#1259: the report and the CLI name the moment each fixed-block number is measured at', (t) => { + if (typeof zstdCompressSync !== 'function') { + t.skip('this Node has no zstd in node:zlib (needs 22.15+)') + return + } + const root = grownFixture(t) + const result = spawnSync(process.execPath, [SCRIPT, '--sessions', root], { encoding: 'utf8' }) + assert.equal(result.status, 0, result.stderr) + // §2's number is each Session's FIRST call: 100 system chars + the tool schema, never the + // 300-character system prompt that comes later in the same Session. + const fixedChars = 100 + TOOLS.length + assert.match(result.stdout, new RegExp(`fixed chars p50 ${fixedChars.toLocaleString('en-US')} \\(first call's surface\\)`)) + // §4's number is the sample turn's LAST call, and the block that backs it says so. + assert.match(result.stdout, /the turn's last call's surface/) + assert.match(result.stdout, /system prompt 300 chars/) + assert.match(result.stdout, new RegExp(`tool schemas ${TOOLS.length.toLocaleString('en-US')} chars`)) +}) + +test('#1259: the committed report says which moment §2 and §4 each measure', () => { + const report = readFileSync(REPORT, 'utf8') + const row = report.split(/\r?\n/).find((line) => line.startsWith('| Fixed characters per call')) + assert.ok(row, 'the report has no "Fixed characters per call" row') + assert.match(row, /each Session's first call/) + const section4 = report.slice(report.indexOf('## 4.')) + assert.match(section4, /the sample turn's last call/) + assert.match(report, /different moments/) + assert.match(report, /not comparable/) +}) + +// A Session whose prompt falls as its messages grow: the slope is negative, so the fit has a +// fixed block but no characters-per-token figure. Half the sample looking like this used to +// reach `.toFixed(2)` as a null median. +function degenerateFixture(t) { + const dir = mkdtempSync(join(tmpdir(), 'turn-split-degenerate-')) + const workspace = join(dir, 'sessions', '--workspace--') + mkdirSync(workspace, { recursive: true }) + for (const name of ['session-null-a', 'session-null-b']) { + const folder = join(workspace, name) + mkdirSync(folder) + const events = [system('S'.repeat(100)), header([{ name: 'bash', description: 'd'.repeat(900) }]), { type: 'turn/start', data: { turn: 1 } }] + for (let step = 1; step <= 10; step += 1) { + events.push(user(`task ${step} `.repeat(step * 10))) + // Fewer prompt tokens per call as the message surface grows: slope < 0. + events.push(assistant(1, step, 100, 100_000 - step * 2_000, 10)) + } + writeFileSync(join(folder, 'session.v4.jsonl.zstd'), sessionFile(events)) + } + t.after(() => rmSync(dir, { recursive: true, force: true })) + return join(dir, 'sessions') +} + +test('#1259: a fit with no characters-per-token figure does not crash the summary', (t) => { + if (typeof zstdCompressSync !== 'function') { + t.skip('this Node has no zstd in node:zlib (needs 22.15+)') + return + } + const root = degenerateFixture(t) + const result = spawnSync(process.execPath, [SCRIPT, '--sessions', root], { encoding: 'utf8' }) + // Before the fix this exits 1 with `Cannot read properties of null (reading 'toFixed')`. + assert.equal(result.status, 0, result.stderr) + assert.match(result.stdout, /message chars\/token p50 n\/a/) +}) + +test('#1259: an unknown --tz is refused by name instead of an uncaught RangeError', (t) => { + if (typeof zstdCompressSync !== 'function') { + t.skip('this Node has no zstd in node:zlib (needs 22.15+)') + return + } + const root = sample(t) + const result = spawnSync(process.execPath, [SCRIPT, '--sessions', root, '--tz', 'Not/AZone'], { encoding: 'utf8' }) + assert.equal(result.status, 1) + assert.match(result.stderr, /turn-split: unknown time zone Not\/AZone/) + assert.doesNotMatch(result.stderr, /RangeError|Invalid time zone/) +}) + +// ---- #1259 item 2: a command per quoted number in §5, §7 and §8 ---------------------- + +const BASE = Date.UTC(2026, 9, 25, 1, 0, 0) +const MINUTE = 60_000 +const at = (ms) => 1_792_900_000_000 + ms + +function roomSession() { + const events = [] + for (let index = 1; index <= 3; index += 1) { + events.push({ type: 'turn/start', data: { turn: index }, time: BASE + (index - 1) * 20 * MINUTE }) + events.push({ type: 'user/message', data: { content: [{ type: 'text', text: `message ${index}` }] }, time: BASE + (index - 1) * 20 * MINUTE }) + events.push({ type: 'assistant/message', time: BASE + (index - 1) * 20 * MINUTE + 1000, data: { turn: index, step: 1, message: { role: 'assistant', content: [{ type: 'text', text: 'ok' }] }, stream: [{ type: 'chunk', chunk: { type: 'usage', usage: { inputTokens: 30, cacheReadTokens: 3000, outputTokens: 5 } } }] } }) + events.push({ type: 'turn/end', data: { turn: index } }) + } + return events +} + +function memberSession(startTimes, shares) { + const events = [system('S'.repeat(100)), header([{ name: 'bash', description: 'd'.repeat(900) }]), + { type: 'user/message', data: { content: [{ type: 'text', text: `room session-room` }] }, time: BASE }] + let step = 0 + for (const [index, start] of startTimes.entries()) { + const share = shares[index] + events.push({ type: 'turn/start', data: { turn: 1 }, time: start }) + for (let call = 1; call <= 8; call += 1) { + step += 1 + events.push({ type: 'user/message', data: { content: [{ type: 'text', text: 'x'.repeat(100 * call) }] }, time: start + call * 1000 }) + events.push({ type: 'assistant/message', time: at(start - BASE + call * 1000), data: { turn: 1, step, message: { role: 'assistant', content: [{ type: 'text', text: 'ok' }] }, stream: [{ type: 'chunk', chunk: { type: 'usage', usage: { inputTokens: 10, cacheReadTokens: 40_000 + call * 1000, outputTokens: 3 } } }] } }) + if (share && call === 1) { + events.push(toolCall(`call-${step}`, 'bash')) + events.push({ type: 'tool/result', data: { message: { role: 'tool', toolCallId: `call-${step}`, content: [{ type: 'text', text: 'B'.repeat(1000) }] } }, time: start + call * 1000 }) + events.push(toolCall(`call-g-${step}`, 'github')) + events.push({ type: 'tool/result', data: { message: { role: 'tool', toolCallId: `call-g-${step}`, content: [{ type: 'text', text: 'G'.repeat(100) }] } }, time: start + call * 1000 }) + } + if (share && call === 2) { + events.push(toolCall(`call-2-${step}`, 'bash')) + events.push({ type: 'tool/result', data: { message: { role: 'tool', toolCallId: `call-2-${step}`, content: [{ type: 'text', text: 'C'.repeat(500) }] } }, time: start + call * 1000 }) + } + if (share && call === 3) events.push({ type: 'llm/retry', data: { attempt: 1 }, time: start + call * 1000 }) + if (share && call === 4) events.push({ type: 'llm/retry', data: { attempt: 2 }, time: start + call * 1000 }) + if (share && call <= 3) events.push({ type: 'assistant/attempt', time: start + call * 1000, data: { turn: 1, stream: [{ type: 'chunk', chunk: { type: 'usage', usage: { inputTokens: call === 1 ? 7 : 0, cacheReadTokens: 0, outputTokens: 0 } } }] } }) + } + events.push({ type: 'turn/end', data: { turn: 1 } }) + } + return events +} + +function statsSample(t) { + const dir = mkdtempSync(join(tmpdir(), 'turn-split-stats-')) + const workspace = join(dir, 'sessions', '--workspace--') + mkdirSync(workspace, { recursive: true }) + const sessions = { + 'session-room': roomSession(), + 'session-mem-a': memberSession([BASE + 1 * MINUTE, BASE + 21 * MINUTE], [true, false]), + 'session-mem-b': memberSession([BASE + 2 * MINUTE, BASE + 41 * MINUTE], [false, false]), + } + for (const [name, events] of Object.entries(sessions)) { + const folder = join(workspace, name) + mkdirSync(folder) + writeFileSync(join(folder, 'session.v4.jsonl.zstd'), sessionFile(events)) + } + t.after(() => rmSync(dir, { recursive: true, force: true })) + return join(dir, 'sessions') +} + +test('#1259: --stats re-derives the §5, §7 and §8 numbers from one command', (t) => { + if (typeof zstdCompressSync !== 'function') { + t.skip('this Node has no zstd in node:zlib (needs 22.15+)') + return + } + const root = statsSample(t) + const result = spawnSync(process.execPath, [SCRIPT, '--sessions', root, '--stats', '--room', 'session-room'], { encoding: 'utf8' }) + assert.equal(result.status, 0, result.stderr) + // §5 — the sample turn's tool results, counted in the log. + assert.match(result.stdout, /## Tool results/) + assert.match(result.stdout, /results 3; characters added 1,600; largest single result 1,000; bash 1,500 chars \(93\.8%\)/) + // §7 — fan-out: three room messages, member Bots per message 2/1/1, turns 2/1/1. + assert.match(result.stdout, /## Fan-out/) + assert.match(result.stdout, /member Bots per message p50\/p90\/max 1\/1\/2/) + assert.match(result.stdout, /member turns per message p50\/p90\/max 1\/1\/2/) + // §8 — retries and attempts, by day, with the non-zero usage count. + assert.match(result.stdout, /## Retries/) + const retries = result.stdout.slice(result.stdout.indexOf('## Retries')) + const day = retries.split('\n').find((line) => /^2026-10-25\s+\d/.test(line)) + assert.ok(day, `no per-day retry row:\n${result.stdout}`) + assert.match(day, /^\S+\s+2\s+3\s+1\s*$/) +}) + +test('#1259: --stats says which command measures §7 when no room is named', (t) => { + if (typeof zstdCompressSync !== 'function') { + t.skip('this Node has no zstd in node:zlib (needs 22.15+)') + return + } + const root = statsSample(t) + const result = spawnSync(process.execPath, [SCRIPT, '--sessions', root, '--stats'], { encoding: 'utf8' }) + assert.equal(result.status, 0, result.stderr) + assert.match(result.stdout, /not measured: pass --room /) +}) diff --git a/docs/reports/2026-10-26-turn-input-split.md b/docs/reports/2026-10-26-turn-input-split.md index 834ba6dd3..fa1e68353 100644 --- a/docs/reports/2026-10-26-turn-input-split.md +++ b/docs/reports/2026-10-26-turn-input-split.md @@ -66,10 +66,12 @@ A working day is **~1.6 billion prompt tokens**, of which **~36%** is the same f | Statistic | p10 | p50 | p90 | Source | | --- | --- | --- | --- | --- | | Fixed tokens per call | 34,210 | 48,583 | 56,239 | derived: intercept of the Session's prompt fit | -| Fixed characters per call | 125,377 | 132,270 | 142,655 | measured: system prompt + tool schemas on the surface | +| Fixed characters per call (each Session's first call) | 125,377 | 132,270 | 142,655 | measured: system prompt + tool schemas on the surface | | Message characters per token | 2.85 | 3.32 | 3.62 | derived: 1 / slope of the same fit | | Fit R² | 0.921 | 0.986 | 0.995 | derived: least squares over the Session's calls | +**§2 and §4 measure different moments.** This table takes the surface of each Session's **first** call; §4 below takes the sample turn's **last** call. The surface grows inside a Session and inside a turn, so the two character counts measure different moments and are not comparable. + The fixed block is dense — 2.7 characters per token against 3.32 for the messages — because it is mostly a JSON tool schema plus a Chinese system prompt: no prose padding to average out. ## 3. One real turn @@ -100,7 +102,7 @@ On the largest call (248,706 tokens) the split is fixed **57,940** (23.3%), hist ## 4. What the fixed block is made of -The same turn's surface, last call. Characters are measured; the token column splits the measured fixed block (57,940 tokens) by character share. +The same turn's surface, the sample turn's last call. Characters are measured; the token column splits the measured fixed block (57,940 tokens) by character share. | Piece | Characters | Tokens (derived) | Source | | --- | --- | --- | --- | @@ -119,6 +121,8 @@ The tool schemas are **79%** of the fixed block's characters. The group notice p ## 5. Tool results +`node dev/turn-split.mjs --stats` prints the `## Tool results` block: the `tool/result` count, the characters added across the turn, the largest single result, the share by tool, what is still on the last call's surface, and the derived tokens carried. + | Measure | Value | Source | | --- | --- | --- | | Tool results in the turn | 125 | measured: `tool/result` count | @@ -158,6 +162,8 @@ A checkpoint buys back roughly twenty minutes of growth at this rate; the fixed ## 7. Fan-out in the group +`node dev/turn-split.mjs --stats --room ` prints the `## Fan-out` block: per-message member-Bot and member-turn counts (10-minute window), the day totals of the member Sessions that name the room, and the fixed block per user message. + FlyBot 交付组, 2026-10-25, 511 user messages in the room (one per `turn/start` of the room's own relay Session): | Measure | p50 | p90 | max | Source | @@ -173,6 +179,8 @@ One message in the delivery group costs its members **21.7 calls** and **1.17 mi ## 8. Retries and repeated work +`node dev/turn-split.mjs --stats` prints the `## Retries` block: `llm/retry` and `assistant/attempt` counts by local day, and how many attempts carried a non-zero usage chunk. + | Measure | 2026-10-25 | 2026-10-26 (partial) | Source | | --- | --- | --- | --- | | `llm/retry` events | 290 | 553 | measured: log events | diff --git a/docs/subsystems/ds-bot-core.md b/docs/subsystems/ds-bot-core.md index f29f27328..a95d32a23 100644 --- a/docs/subsystems/ds-bot-core.md +++ b/docs/subsystems/ds-bot-core.md @@ -42,7 +42,7 @@ holds. Task bookkeeping does not imply runtime execution or tool permission. | `scripts/ds-bot-patches.mjs` | generate / check patches. | | `core/dev/eval/` | User-scenario runner (#358): pure rubrics (`rubric.mjs`), canonical journey specs (`specs.mjs`), optional model judge (`judge.mjs`), grader hashing (#398, `guard.mjs`) and a CLI (`run.mjs`). Dev only, not part of `npm test`. | | `core/dev/token-report.mjs` | Reads the usage ledger into per-Bot, per-Session and per-day token numbers and each Session's prompt growth, keeping fresh input, cache read and cache write apart (#799). Read-only; `--db`, `--from`, `--to`, `--tz`, `--bot`, `--top`, `--growth`, `--json`. | -| `core/dev/turn-split.mjs` | Reads Session logs into the split of one turn's prompt: the fixed block (system prompt plus tool schemas) measured as each Session's fit intercept, then history, tool results and task by character share (#796). Read-only; `--sessions`, `--session`, `--turn`, `--tz`, `--days`, `--top`, `--json`. | +| `core/dev/turn-split.mjs` | Reads Session logs into the split of one turn's prompt: the fixed block (system prompt plus tool schemas) measured as each Session's fit intercept, then history, tool results and task by character share (#796). Read-only; `--sessions`, `--session`, `--turn`, `--tz`, `--days`, `--top`, `--stats`, `--room`, `--json`. | | `core/dev/experience/` | Offline experience library (#874 Step 2): JSON lessons under `repos///` and `stacks//`. The read API is `core/src/host/experience.js` (see [core-host](core-host.md)). `check.mjs` validates the tree and can add one entry file. Not part of the npm `files` list, and not injected into a harness tier. | | `core/src/host/hooks.js` (approvals) | Held sends bound to their owner — provenance, owner-bound decisions, stale revalidation. Chief replacement invalidates sender-side holds eagerly on `setMain` (not via `staleReason`). The authority contract lives in [team](team.md) (#52). | @@ -106,7 +106,10 @@ history, tool results and task. The fixed block is measured, not assumed: it is intercept of `prompt = fixed + k × messageChars` fitted over the same Session's own calls, so a per-part token figure stays a share of a measured total. The report it backs is [docs/reports/2026-10-26-turn-input-split.md](../../docs/reports/2026-10-26-turn-input-split.md) -and `core/test/turn-split.test.js` pins the four rules behind the split. +and `core/test/turn-split.test.js` pins the four rules behind the split. `--stats` re-derives +the tool-result, fan-out and retry numbers the report quotes in §5, §7 and §8 from one +command — `--room` names the room Session the fan-out is measured around — so a number on +that page has a command behind it. ## Common mistakes diff --git a/patches/ds-bot/files/dev/turn-split.mjs b/patches/ds-bot/files/dev/turn-split.mjs index 6f3c6e45d..f81c01249 100644 --- a/patches/ds-bot/files/dev/turn-split.mjs +++ b/patches/ds-bot/files/dev/turn-split.mjs @@ -3,7 +3,7 @@ // and the task (the message that opened the turn). // // node dev/turn-split.mjs [--sessions ] [--session ] [--turn ] -// [--tz ] [--top ] [--json] +// [--tz ] [--top ] [--stats] [--room ] [--json] // // `--sessions` is the DSH session root (default `$DSH_HOME/sessions`); the script walks it // for `session.v4.jsonl.zstd` files. Every Session log carries, per call, the provider's own @@ -27,7 +27,7 @@ import { join, resolve } from 'node:path' import { pathToFileURL } from 'node:url' import { zstdDecompressSync } from 'node:zlib' -const USAGE = 'usage: node dev/turn-split.mjs [--sessions ] [--session ] [--turn ] [--tz ] [--days] [--top ] [--json]' +const USAGE = 'usage: node dev/turn-split.mjs [--sessions ] [--session ] [--turn ] [--tz ] [--days] [--top ] [--stats] [--room ] [--json]' const ZSTD_MAGIC = 4247762216 function die(message) { @@ -36,7 +36,7 @@ function die(message) { } function parseArgs(argv) { - const flags = { sessions: null, session: null, turn: null, tz: 'UTC', days: false, top: 5, json: false } + const flags = { sessions: null, session: null, turn: null, tz: 'UTC', days: false, top: 5, json: false, stats: false, room: null } for (let index = 0; index < argv.length; index += 1) { const arg = argv[index] const value = () => { @@ -52,6 +52,8 @@ function parseArgs(argv) { case '--tz': flags.tz = value(); break case '--top': flags.top = Number(value()); break case '--days': flags.days = true; break + case '--stats': flags.stats = true; break + case '--room': flags.room = value(); break case '--json': flags.json = true; break case '--help': case '-h': console.log(USAGE); process.exit(0); break default: die(`unknown argument ${arg}\n${USAGE}`) @@ -59,6 +61,14 @@ function parseArgs(argv) { } if (!Number.isSafeInteger(flags.top) || flags.top < 1) die('--top must be a whole number') if (flags.turn !== null && !Number.isSafeInteger(flags.turn)) die('--turn must be a whole number') + // A zone the runtime does not know would otherwise reach `Intl.DateTimeFormat` and throw an + // uncaught RangeError from inside `localDay`, after the whole sample has been read. + try { + new Intl.DateTimeFormat('en-CA', { timeZone: flags.tz }) + } catch { + die(`unknown time zone ${flags.tz}`) + } + if (flags.stats && flags.days) die('--stats and --days measure different things; pass one of them') return flags } @@ -144,6 +154,11 @@ export function foldSessionEvents(events) { let toolCallNames = new Map() const largestTool = new Map() const toolTotal = new Map() + const toolCount = new Map() + const toolAddedByName = new Map() + const turnStarts = [] + const retries = [] + const attempts = [] for (const event of events) { const data = event?.data ?? {} switch (event?.type) { @@ -155,6 +170,7 @@ export function foldSessionEvents(events) { break case 'turn/start': turn = data.turn ?? null + turnStarts.push({ turn, time: event.time }) open = true for (let index = messages.length - pending; index < messages.length; index += 1) messages[index].turn = turn pending = 0 @@ -179,8 +195,13 @@ export function foldSessionEvents(events) { const callId = data.message?.toolCallId ?? data.message?.source?.callId const resultTurn = open ? turn : (data.turn ?? null) const resultChars = textOf(data.message?.content).length + const resultName = toolCallNames.get(callId) ?? data.message?.toolName ?? '' largestTool.set(resultTurn, Math.max(largestTool.get(resultTurn) ?? 0, resultChars)) toolTotal.set(resultTurn, (toolTotal.get(resultTurn) ?? 0) + resultChars) + toolCount.set(resultTurn, (toolCount.get(resultTurn) ?? 0) + 1) + const byName = toolAddedByName.get(resultTurn) ?? {} + byName[resultName] = (byName[resultName] ?? 0) + resultChars + toolAddedByName.set(resultTurn, byName) messages.push({ role: 'tool', turn: open ? turn : (data.turn ?? null), @@ -189,6 +210,12 @@ export function foldSessionEvents(events) { }) break } + case 'llm/retry': + retries.push({ time: event.time }) + break + case 'assistant/attempt': + attempts.push({ time: event.time, usage: usageOf(data.stream) }) + break case 'assistant/message': { const usage = usageOf(data.stream) const current = data.turn ?? null @@ -241,7 +268,7 @@ export function foldSessionEvents(events) { break } } - return { steps, turns: [...turns.values()], largestTool, toolTotal, systemChars: system.length, toolsChars: tools.length } + return { steps, turns: [...turns.values()], largestTool, toolTotal, toolCount, toolAddedByName, turnStarts, retries, attempts, systemChars: system.length, toolsChars: tools.length } } // The fixed block is constant for every call of one Session, so it is that Session's @@ -290,18 +317,22 @@ export function splitStep(step, fit) { return { fixed, task: share(step.chars.task), history: share(step.chars.history), tool: share(step.chars.tool) } } -export function readSessionFile(file) { +// The decoded artifact: its events, and the text they came from, which is how the fan-out +// statistic learns that a Session names a room. +export function decodeSession(file) { const buffer = readFileSync(file) const { frames } = scanZstdFrames(buffer) const events = [] + let text = '' for (const { start, end } of frames) { - let text + let frame try { - text = zstdDecompressSync(buffer.subarray(start, end)).toString('utf8') + frame = zstdDecompressSync(buffer.subarray(start, end)).toString('utf8') } catch { continue } - for (const line of text.split('\n')) { + text += frame + for (const line of frame.split('\n')) { if (!line.trim()) continue try { events.push(JSON.parse(line)) @@ -310,7 +341,11 @@ export function readSessionFile(file) { } } } - return events + return { events, text } +} + +export function readSessionFile(file) { + return decodeSession(file).events } export function findSessionFiles(root) { @@ -341,6 +376,139 @@ const localDay = (time, tz) => { } const integer = (value) => Math.round(value).toLocaleString('en-US') +// The statistics §5, §7 and §8 of the report quote, so each number there has one command +// behind it. Every figure is either counted in the log or derived by the formula printed +// beside it; nothing here estimates. +const FANOUT_WINDOW = 10 * 60_000 + +function printStats({ flags, sessions, rows, root }) { + const percentile = (values, q) => { + if (values.length === 0) return 0 + const sorted = values.slice().sort((a, b) => a - b) + return sorted[Math.min(sorted.length - 1, Math.floor((sorted.length - 1) * q))] + } + const dayOf = (time) => localDay(time, flags.tz) + const out = { sample: { root: resolve(root), sessions: sessions.length, tz: flags.tz }, toolResults: null, fanout: null, retries: [] } + const lines = [] + + // §5: the tool results of one turn — the one with the most tool text unless --turn names it. + const sampleTurn = flags.turn !== null + ? rows.find((row) => row.turn === flags.turn) + : rows.slice().sort((a, b) => b.toolTotal - a.toolTotal)[0] + lines.push('## Tool results') + if (sampleTurn) { + const added = sampleTurn.toolTotal + const bash = sampleTurn.addedByName.bash ?? 0 + const share = added > 0 ? bash / added * 100 : 0 + out.toolResults = { + session: sampleTurn.session, + turn: sampleTurn.turn, + results: sampleTurn.toolCount, + characters: added, + onLastSurface: sampleTurn.toolAdded, + largest: sampleTurn.largestTool, + bash, + bashShare: share, + carried: sampleTurn.tool, + } + lines.push(`${sampleTurn.session} turn ${sampleTurn.turn} (the turn with the most tool text): ` + + `results ${integer(sampleTurn.toolCount)}; characters added ${integer(added)}; largest single result ${integer(sampleTurn.largestTool)}; ` + + `bash ${integer(bash)} chars (${share.toFixed(1)}%); still on the last call's surface ${integer(sampleTurn.toolAdded)} chars; ` + + `carried in the turn's prompts ${integer(sampleTurn.tool)} tokens`) + } else { + lines.push('not measured: no turn in the sample could be split (every Session needs 8 calls)') + } + lines.push('') + + // §7: fan-out around one room's own Session — how many member Bots a single room message + // wakes within the window, and what their calls cost that day. + lines.push('## Fan-out') + if (flags.room === null) { + lines.push('not measured: pass --room ') + } else { + const room = sessions.find((session) => session.id.startsWith(flags.room)) + if (!room) die(`no Session matching --room ${flags.room}`) + const members = sessions.filter((session) => session.id !== room.id && session.text.includes(room.id)) + const messages = room.turnStarts.map((start) => start.time).filter((time) => Number.isFinite(time)) + if (messages.length === 0) die(`no room message in ${room.id}`) + const bots = [] + const turns = [] + for (const time of messages) { + const waking = [] + for (const session of members) { + for (const start of session.turnStarts) { + if (start.time > time && start.time <= time + FANOUT_WINDOW) waking.push(session.id) + } + } + bots.push(new Set(waking).size) + turns.push(waking.length) + } + const days = new Map() + for (const session of members) { + for (const step of session.steps) { + const day = dayOf(step.time) + const row = days.get(day) ?? { day, calls: 0, prompt: 0, fixed: 0 } + row.calls += 1 + row.prompt += step.prompt + row.fixed += session.fixed ? splitStep(step, session.fixed).fixed : 0 + days.set(day, row) + } + } + const rowsOut = [...days.values()].sort((a, b) => a.day.localeCompare(b.day)) + const fixed = rowsOut.reduce((sum, row) => sum + row.fixed, 0) + out.fanout = { + room: room.id, + windowMinutes: FANOUT_WINDOW / 60_000, + messages: messages.length, + members: members.length, + bots: { p50: percentile(bots, 0.5), p90: percentile(bots, 0.9), max: Math.max(0, ...bots) }, + turns: { p50: percentile(turns, 0.5), p90: percentile(turns, 0.9), max: Math.max(0, ...turns) }, + days: rowsOut, + fixedPerMessage: messages.length === 0 ? 0 : fixed / messages.length, + } + lines.push(`${room.id}: ${integer(messages.length)} user messages; ${integer(members.length)} member Sessions name it; window ${FANOUT_WINDOW / 60_000} minutes`) + lines.push(`member Bots per message p50/p90/max ${percentile(bots, 0.5)}/${percentile(bots, 0.9)}/${Math.max(0, ...bots)}`) + lines.push(`member turns per message p50/p90/max ${percentile(turns, 0.5)}/${percentile(turns, 0.9)}/${Math.max(0, ...turns)}`) + lines.push('day calls prompt fixed fixed share') + for (const row of rowsOut) { + lines.push(`${row.day} ${String(row.calls).padStart(6)} ${integer(row.prompt).padStart(13)} ${integer(row.fixed).padStart(12)} ${(row.prompt > 0 ? row.fixed / row.prompt * 100 : 0).toFixed(1).padStart(11)}%`) + } + lines.push(`fixed block per user message: ${integer(fixed / messages.length)} tokens (${integer(fixed)} / ${integer(messages.length)} messages)`) + } + lines.push('') + + // §8: retries and attempts — how many, and how many attempts ever reported usage. + const retryDays = new Map() + const row = (time) => { + const day = dayOf(time) + const found = retryDays.get(day) ?? { day, retries: 0, attempts: 0, used: 0 } + retryDays.set(day, found) + return found + } + for (const session of sessions) { + for (const retry of session.retries) row(retry.time).retries += 1 + for (const attempt of session.attempts) { + const found = row(attempt.time) + found.attempts += 1 + const usage = attempt.usage ?? {} + if (['inputTokens', 'cacheReadTokens', 'cacheWriteTokens', 'outputTokens'].some((key) => Number.isFinite(usage[key]) && usage[key] > 0)) found.used += 1 + } + } + const retryRows = [...retryDays.values()].sort((a, b) => a.day.localeCompare(b.day)) + out.retries = retryRows + lines.push('## Retries') + lines.push('day llm/retry attempts attempts with non-zero usage') + for (const values of retryRows) { + lines.push(`${values.day} ${String(values.retries).padStart(9)} ${String(values.attempts).padStart(10)} ${String(values.used).padStart(27)}`) + } + + if (flags.json) { + console.log(JSON.stringify(out, null, 2)) + return + } + for (const line of lines) console.log(line) +} + function main(argv) { const flags = parseArgs(argv) const root = flags.sessions === null ? join(process.env.DSH_HOME ?? join(homedir(), '.dsh'), 'sessions') : flags.sessions @@ -356,9 +524,10 @@ function main(argv) { for (const file of files) { const id = file.split('/').at(-2) if (flags.session !== null && !id.startsWith(flags.session)) continue - const folded = foldSessionEvents(readSessionFile(file)) + const { events, text } = decodeSession(file) + const folded = foldSessionEvents(events) if (folded.steps.length === 0) continue - sessions.push({ id, file, ...folded, fixed: fitFixed(folded.steps) }) + sessions.push({ id, file, text, ...folded, fixed: fitFixed(folded.steps) }) } if (sessions.length === 0) die('no Session in the sample carried a provider usage report') const rows = [] @@ -385,6 +554,8 @@ function main(argv) { prompt: total.prompt, output: turn.output, toolAdded: steps.at(-1).chars.tool, + toolCount: session.toolCount?.get(turn.turn) ?? 0, + addedByName: session.toolAddedByName?.get(turn.turn) ?? {}, largestTool: session.largestTool?.get(turn.turn) ?? 0, toolTotal: session.toolTotal?.get(turn.turn) ?? 0, fixed: total.fixed, @@ -438,6 +609,10 @@ function main(argv) { } return } + if (flags.stats) { + printStats({ flags, sessions, rows, root }) + return + } if (rows.length === 0) die('no turn in the sample could be split (every Session needs 8 calls)') if (flags.turn !== null) { const only = rows.filter((row) => row.turn === flags.turn) @@ -454,8 +629,12 @@ function main(argv) { console.log(`sample: ${sessions.length} Sessions under ${resolve(root)}, zone ${flags.tz}`) console.log('') console.log('## Fixed block per call (measured: the intercept of each Session\'s prompt fit)') + // A Session whose prompt falls as its messages grow has a fixed block but no + // characters-per-token figure; the median is taken over the Sessions that have one. + const perToken = fits.map((fit) => fit.charsPerToken).filter((value) => Number.isFinite(value)) console.log(`Sessions with a fit: ${fits.length}; fixed tokens p50 ${integer(median(fits.map((fit) => fit.fixedTokens)))}; ` - + `fixed chars p50 ${integer(median(fits.map((fit) => fit.fixedChars)))}; message chars/token p50 ${median(fits.map((fit) => fit.charsPerToken)).toFixed(2)}; ` + + `fixed chars p50 ${integer(median(fits.map((fit) => fit.fixedChars)))} (first call's surface); ` + + `message chars/token p50 ${perToken.length === 0 ? 'n/a' : median(perToken).toFixed(2)}; ` + `R2 p50 ${median(fits.map((fit) => fit.r2)).toFixed(3)}`) console.log('') console.log('## Top turns by prompt') @@ -469,9 +648,13 @@ function main(argv) { const first = top[0] if (first) { console.log('') - console.log(`## Turn ${first.turn} of ${first.session}: one call's surface`) - console.log(`system prompt ${integer(first.systemChars)} chars; tool schemas ${integer(first.toolsChars)} chars; ` - + `fixed block ${integer(first.fit.fixedTokens)} tokens (${(first.fit.fixedChars / first.fit.fixedTokens).toFixed(2)} chars/token)`) + // §4 of the report is the turn's LAST call, not its first: the surface grows inside a + // turn, so the two are not interchangeable. + const surface = first.steps.at(-1) + const surfaceChars = surface.systemChars + surface.toolsChars + console.log(`## Turn ${first.turn} of ${first.session}: the turn's last call's surface`) + console.log(`system prompt ${integer(surface.systemChars)} chars; tool schemas ${integer(surface.toolsChars)} chars; ` + + `fixed block ${integer(first.fit.fixedTokens)} tokens (${(surfaceChars / first.fit.fixedTokens).toFixed(2)} chars/token)`) console.log(`calls ${first.calls}; provider prompt ${integer(first.prompt)} tokens (${integer(first.prompt / first.calls)} per call); output ${integer(first.output)} tokens`) console.log(`tool text added by the turn ${integer(first.toolTotal)} chars; still on the last call's surface ${integer(first.toolAdded)} chars; largest single result ${integer(first.largestTool)} chars`) if (first.toolNames.size > 0) { diff --git a/patches/ds-bot/files/test/turn-split.test.js b/patches/ds-bot/files/test/turn-split.test.js index 9e49dab78..481f2eec2 100644 --- a/patches/ds-bot/files/test/turn-split.test.js +++ b/patches/ds-bot/files/test/turn-split.test.js @@ -212,3 +212,200 @@ test('every row of the committed split report carries its provenance', () => { assert.equal(row.cells.length, row.header.length, `a row has ${row.cells.length} cells, its table ${row.header.length}: | ${row.cells.join(' | ')} |`) } }) + +// ---- #1259: the three follow-ups #1241's INC left open ------------------------------- + +const TOOLS = JSON.stringify([{ name: 'bash', description: 'd'.repeat(900) }]) + +// One Session whose system prompt grows mid-way: the first call's surface is not the last +// call's, which is the §2/§4 mismatch this issue is about. +function grownFixture(t) { + const dir = mkdtempSync(join(tmpdir(), 'turn-split-grown-')) + const workspace = join(dir, 'sessions', '--workspace--') + mkdirSync(workspace, { recursive: true }) + const events = [system('S'.repeat(100)), header([{ name: 'bash', description: 'd'.repeat(900) }]), { type: 'turn/start', data: { turn: 1 } }] + for (let step = 1; step <= 10; step += 1) { + if (step === 6) events.push(system('S'.repeat(300))) + events.push(user(`task ${step} `.repeat(step * 10))) + events.push(assistant(1, step, 100, 48_000 + step * 500, 10)) + } + const folder = join(workspace, 'session-grown') + mkdirSync(folder) + writeFileSync(join(folder, 'session.v4.jsonl.zstd'), sessionFile(events)) + t.after(() => rmSync(dir, { recursive: true, force: true })) + return join(dir, 'sessions') +} + +test('#1259: the report and the CLI name the moment each fixed-block number is measured at', (t) => { + if (typeof zstdCompressSync !== 'function') { + t.skip('this Node has no zstd in node:zlib (needs 22.15+)') + return + } + const root = grownFixture(t) + const result = spawnSync(process.execPath, [SCRIPT, '--sessions', root], { encoding: 'utf8' }) + assert.equal(result.status, 0, result.stderr) + // §2's number is each Session's FIRST call: 100 system chars + the tool schema, never the + // 300-character system prompt that comes later in the same Session. + const fixedChars = 100 + TOOLS.length + assert.match(result.stdout, new RegExp(`fixed chars p50 ${fixedChars.toLocaleString('en-US')} \\(first call's surface\\)`)) + // §4's number is the sample turn's LAST call, and the block that backs it says so. + assert.match(result.stdout, /the turn's last call's surface/) + assert.match(result.stdout, /system prompt 300 chars/) + assert.match(result.stdout, new RegExp(`tool schemas ${TOOLS.length.toLocaleString('en-US')} chars`)) +}) + +test('#1259: the committed report says which moment §2 and §4 each measure', () => { + const report = readFileSync(REPORT, 'utf8') + const row = report.split(/\r?\n/).find((line) => line.startsWith('| Fixed characters per call')) + assert.ok(row, 'the report has no "Fixed characters per call" row') + assert.match(row, /each Session's first call/) + const section4 = report.slice(report.indexOf('## 4.')) + assert.match(section4, /the sample turn's last call/) + assert.match(report, /different moments/) + assert.match(report, /not comparable/) +}) + +// A Session whose prompt falls as its messages grow: the slope is negative, so the fit has a +// fixed block but no characters-per-token figure. Half the sample looking like this used to +// reach `.toFixed(2)` as a null median. +function degenerateFixture(t) { + const dir = mkdtempSync(join(tmpdir(), 'turn-split-degenerate-')) + const workspace = join(dir, 'sessions', '--workspace--') + mkdirSync(workspace, { recursive: true }) + for (const name of ['session-null-a', 'session-null-b']) { + const folder = join(workspace, name) + mkdirSync(folder) + const events = [system('S'.repeat(100)), header([{ name: 'bash', description: 'd'.repeat(900) }]), { type: 'turn/start', data: { turn: 1 } }] + for (let step = 1; step <= 10; step += 1) { + events.push(user(`task ${step} `.repeat(step * 10))) + // Fewer prompt tokens per call as the message surface grows: slope < 0. + events.push(assistant(1, step, 100, 100_000 - step * 2_000, 10)) + } + writeFileSync(join(folder, 'session.v4.jsonl.zstd'), sessionFile(events)) + } + t.after(() => rmSync(dir, { recursive: true, force: true })) + return join(dir, 'sessions') +} + +test('#1259: a fit with no characters-per-token figure does not crash the summary', (t) => { + if (typeof zstdCompressSync !== 'function') { + t.skip('this Node has no zstd in node:zlib (needs 22.15+)') + return + } + const root = degenerateFixture(t) + const result = spawnSync(process.execPath, [SCRIPT, '--sessions', root], { encoding: 'utf8' }) + // Before the fix this exits 1 with `Cannot read properties of null (reading 'toFixed')`. + assert.equal(result.status, 0, result.stderr) + assert.match(result.stdout, /message chars\/token p50 n\/a/) +}) + +test('#1259: an unknown --tz is refused by name instead of an uncaught RangeError', (t) => { + if (typeof zstdCompressSync !== 'function') { + t.skip('this Node has no zstd in node:zlib (needs 22.15+)') + return + } + const root = sample(t) + const result = spawnSync(process.execPath, [SCRIPT, '--sessions', root, '--tz', 'Not/AZone'], { encoding: 'utf8' }) + assert.equal(result.status, 1) + assert.match(result.stderr, /turn-split: unknown time zone Not\/AZone/) + assert.doesNotMatch(result.stderr, /RangeError|Invalid time zone/) +}) + +// ---- #1259 item 2: a command per quoted number in §5, §7 and §8 ---------------------- + +const BASE = Date.UTC(2026, 9, 25, 1, 0, 0) +const MINUTE = 60_000 +const at = (ms) => 1_792_900_000_000 + ms + +function roomSession() { + const events = [] + for (let index = 1; index <= 3; index += 1) { + events.push({ type: 'turn/start', data: { turn: index }, time: BASE + (index - 1) * 20 * MINUTE }) + events.push({ type: 'user/message', data: { content: [{ type: 'text', text: `message ${index}` }] }, time: BASE + (index - 1) * 20 * MINUTE }) + events.push({ type: 'assistant/message', time: BASE + (index - 1) * 20 * MINUTE + 1000, data: { turn: index, step: 1, message: { role: 'assistant', content: [{ type: 'text', text: 'ok' }] }, stream: [{ type: 'chunk', chunk: { type: 'usage', usage: { inputTokens: 30, cacheReadTokens: 3000, outputTokens: 5 } } }] } }) + events.push({ type: 'turn/end', data: { turn: index } }) + } + return events +} + +function memberSession(startTimes, shares) { + const events = [system('S'.repeat(100)), header([{ name: 'bash', description: 'd'.repeat(900) }]), + { type: 'user/message', data: { content: [{ type: 'text', text: `room session-room` }] }, time: BASE }] + let step = 0 + for (const [index, start] of startTimes.entries()) { + const share = shares[index] + events.push({ type: 'turn/start', data: { turn: 1 }, time: start }) + for (let call = 1; call <= 8; call += 1) { + step += 1 + events.push({ type: 'user/message', data: { content: [{ type: 'text', text: 'x'.repeat(100 * call) }] }, time: start + call * 1000 }) + events.push({ type: 'assistant/message', time: at(start - BASE + call * 1000), data: { turn: 1, step, message: { role: 'assistant', content: [{ type: 'text', text: 'ok' }] }, stream: [{ type: 'chunk', chunk: { type: 'usage', usage: { inputTokens: 10, cacheReadTokens: 40_000 + call * 1000, outputTokens: 3 } } }] } }) + if (share && call === 1) { + events.push(toolCall(`call-${step}`, 'bash')) + events.push({ type: 'tool/result', data: { message: { role: 'tool', toolCallId: `call-${step}`, content: [{ type: 'text', text: 'B'.repeat(1000) }] } }, time: start + call * 1000 }) + events.push(toolCall(`call-g-${step}`, 'github')) + events.push({ type: 'tool/result', data: { message: { role: 'tool', toolCallId: `call-g-${step}`, content: [{ type: 'text', text: 'G'.repeat(100) }] } }, time: start + call * 1000 }) + } + if (share && call === 2) { + events.push(toolCall(`call-2-${step}`, 'bash')) + events.push({ type: 'tool/result', data: { message: { role: 'tool', toolCallId: `call-2-${step}`, content: [{ type: 'text', text: 'C'.repeat(500) }] } }, time: start + call * 1000 }) + } + if (share && call === 3) events.push({ type: 'llm/retry', data: { attempt: 1 }, time: start + call * 1000 }) + if (share && call === 4) events.push({ type: 'llm/retry', data: { attempt: 2 }, time: start + call * 1000 }) + if (share && call <= 3) events.push({ type: 'assistant/attempt', time: start + call * 1000, data: { turn: 1, stream: [{ type: 'chunk', chunk: { type: 'usage', usage: { inputTokens: call === 1 ? 7 : 0, cacheReadTokens: 0, outputTokens: 0 } } }] } }) + } + events.push({ type: 'turn/end', data: { turn: 1 } }) + } + return events +} + +function statsSample(t) { + const dir = mkdtempSync(join(tmpdir(), 'turn-split-stats-')) + const workspace = join(dir, 'sessions', '--workspace--') + mkdirSync(workspace, { recursive: true }) + const sessions = { + 'session-room': roomSession(), + 'session-mem-a': memberSession([BASE + 1 * MINUTE, BASE + 21 * MINUTE], [true, false]), + 'session-mem-b': memberSession([BASE + 2 * MINUTE, BASE + 41 * MINUTE], [false, false]), + } + for (const [name, events] of Object.entries(sessions)) { + const folder = join(workspace, name) + mkdirSync(folder) + writeFileSync(join(folder, 'session.v4.jsonl.zstd'), sessionFile(events)) + } + t.after(() => rmSync(dir, { recursive: true, force: true })) + return join(dir, 'sessions') +} + +test('#1259: --stats re-derives the §5, §7 and §8 numbers from one command', (t) => { + if (typeof zstdCompressSync !== 'function') { + t.skip('this Node has no zstd in node:zlib (needs 22.15+)') + return + } + const root = statsSample(t) + const result = spawnSync(process.execPath, [SCRIPT, '--sessions', root, '--stats', '--room', 'session-room'], { encoding: 'utf8' }) + assert.equal(result.status, 0, result.stderr) + // §5 — the sample turn's tool results, counted in the log. + assert.match(result.stdout, /## Tool results/) + assert.match(result.stdout, /results 3; characters added 1,600; largest single result 1,000; bash 1,500 chars \(93\.8%\)/) + // §7 — fan-out: three room messages, member Bots per message 2/1/1, turns 2/1/1. + assert.match(result.stdout, /## Fan-out/) + assert.match(result.stdout, /member Bots per message p50\/p90\/max 1\/1\/2/) + assert.match(result.stdout, /member turns per message p50\/p90\/max 1\/1\/2/) + // §8 — retries and attempts, by day, with the non-zero usage count. + assert.match(result.stdout, /## Retries/) + const retries = result.stdout.slice(result.stdout.indexOf('## Retries')) + const day = retries.split('\n').find((line) => /^2026-10-25\s+\d/.test(line)) + assert.ok(day, `no per-day retry row:\n${result.stdout}`) + assert.match(day, /^\S+\s+2\s+3\s+1\s*$/) +}) + +test('#1259: --stats says which command measures §7 when no room is named', (t) => { + if (typeof zstdCompressSync !== 'function') { + t.skip('this Node has no zstd in node:zlib (needs 22.15+)') + return + } + const root = statsSample(t) + const result = spawnSync(process.execPath, [SCRIPT, '--sessions', root, '--stats'], { encoding: 'utf8' }) + assert.equal(result.status, 0, result.stderr) + assert.match(result.stdout, /not measured: pass --room /) +})