From df1c4b73973250ae6cb5abd32fcab66a3d0575e5 Mon Sep 17 00:00:00 2001 From: Day Dreamer <87640074+HugoXK@users.noreply.github.com> Date: Tue, 27 Oct 2026 10:14:34 +0800 Subject: [PATCH] fix(dev): name the fixed-block moment, add --stats, and stop two throwing edges (#1259) turn-split's report quoted two different moments as one number, and three sections of it had no command behind them. The summary now says the first call's surface and the backed block the last, `--stats` re-derives the tool-result, fan-out and retry rows, a null characters-per-token fit no longer reaches toFixed, and an unknown --tz is refused by name instead of an uncaught RangeError. Fixes #1259 Written-by: Dev-1 --- core/dev/turn-split.mjs | 213 +++++++++++++++++-- core/test/turn-split.test.js | 197 +++++++++++++++++ docs/reports/2026-10-26-turn-input-split.md | 12 +- docs/subsystems/ds-bot-core.md | 7 +- patches/ds-bot/files/dev/turn-split.mjs | 213 +++++++++++++++++-- patches/ds-bot/files/test/turn-split.test.js | 197 +++++++++++++++++ 6 files changed, 805 insertions(+), 34 deletions(-) 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 /) +})