diff --git a/changelog.d/799-token-report.added.md b/changelog.d/799-token-report.added.md new file mode 100644 index 000000000..af5a68401 --- /dev/null +++ b/changelog.d/799-token-report.added.md @@ -0,0 +1 @@ +`core/dev/token-report.mjs` reads the usage ledger into the numbers #796 asks for: per Bot, per Session and per day, with fresh input, cache read, cache write and their sum (prompt) as separate columns, per-call prompt percentiles, the top Sessions by prompt, and each Session's prompt growth between consecutive calls, splitting at a compaction or a new part instead of counting it as a negative delta. It opens the ledger read-only, defaults `--db` to `$DSH_HOME/usage.sqlite`, and exits non-zero naming the path when it is missing. The first report is [docs/reports/2026-10-23-token-spend.md](../docs/reports/2026-10-23-token-spend.md) ([#799](https://github.com/ThinkFlowLab/FlyBot/issues/799)). diff --git a/core/dev/token-report.mjs b/core/dev/token-report.mjs new file mode 100644 index 000000000..0afbd8920 --- /dev/null +++ b/core/dev/token-report.mjs @@ -0,0 +1,364 @@ +// Reads the usage ledger into the numbers #796 asks for: per Bot, per Session, per day, +// and the prompt a Session grows by from one call to the next. It is a report, not a +// change to what is sent: it opens the ledger read-only and prints. +// +// node dev/token-report.mjs [--db ] [--from ] [--to ] [--tz ] +// [--bot ] [--top ] [--growth ] [--json] +// +// `--db` defaults to `$DSH_HOME/usage.sqlite` (see src/host/usage.js). A missing file is an +// error, never an empty table: an empty report is exactly what a broken path looks like. +// +// Fresh input, cache read and cache write are kept apart in every total. A cache read is +// not a fresh input token and summing them hides which one moved (`#796`). `prompt` is the +// sum of the three and is printed as its own column, never used as the input figure. +// +// `--from` / `--to` take `YYYY-MM-DD` or `YYYY-MM-DDTHH:MM[:SS]`, read in `--tz` +// (default UTC) unless they carry `Z` or an offset. A bare `--to` date ends at the end of +// that day in `--tz`. `--bot` matches a Bot name (case-insensitive) or a Session id +// prefix. `--top` is how many Sessions the "top by prompt" table shows (default 10) and +// `--growth` how many carry the per-call growth table (default 5, 0 turns it off). +// +// Percentiles are nearest-rank: the sorted value at `ceil(p/100 * n) - 1`, so a p99 of a +// small sample is its maximum. The report prints that definition too. +import { DatabaseSync } from 'node:sqlite' +import { existsSync, readFileSync } from 'node:fs' +import { homedir } from 'node:os' +import { join, resolve } from 'node:path' +import { pathToFileURL } from 'node:url' + +const USAGE = 'usage: node dev/token-report.mjs [--db ] [--from ] [--to ] [--tz ] [--bot ] [--top ] [--growth ] [--json]' + +function die(message) { + console.error(`token-report: ${message}`) + process.exit(1) +} + +function parseArgs(argv) { + const flags = { db: null, from: null, to: null, tz: 'UTC', bot: null, top: 10, growth: 5, json: false } + for (let index = 0; index < argv.length; index += 1) { + const arg = argv[index] + const value = () => { + const next = argv[index + 1] + if (next === undefined || next.startsWith('--')) die(`${arg} needs a value`) + index += 1 + return next + } + switch (arg) { + case '--db': flags.db = value(); break + case '--from': flags.from = value(); break + case '--to': flags.to = value(); break + case '--tz': flags.tz = value(); break + case '--bot': flags.bot = value(); break + case '--top': flags.top = Number(value()); break + case '--growth': flags.growth = Number(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}`) + } + } + for (const key of ['top', 'growth']) { + if (!Number.isSafeInteger(flags[key]) || flags[key] < 0) die(`--${key} must be a whole number`) + } + return flags +} + +// The local wall-clock parts of an instant in a zone, and the epoch of those parts read +// as UTC (that difference is the zone's offset at that instant). +function localParts(tz, time) { + let format + try { + format = new Intl.DateTimeFormat('en-CA', { + timeZone: tz, year: 'numeric', month: '2-digit', day: '2-digit', + hour: '2-digit', minute: '2-digit', second: '2-digit', hourCycle: 'h23', + }) + } catch { + die(`unknown time zone ${tz}`) + } + const part = Object.fromEntries(format.formatToParts(new Date(time)).map(({ type, value }) => [type, value])) + return { year: Number(part.year), month: Number(part.month), day: Number(part.day), hour: Number(part.hour), minute: Number(part.minute), second: Number(part.second) } +} + +const DATE = /^(\d{4})-(\d{2})-(\d{2})(?:[T ](\d{2}):(\d{2})(?::(\d{2}))?)?(Z|[+-]\d{2}:\d{2})?$/ + +const daysInMonth = (year, month) => new Date(Date.UTC(year, month, 0)).getUTCDate() +const pad = value => String(value).padStart(2, '0') +const cannotRead = (text, why) => die(`cannot read ${JSON.stringify(text)} as a date${why === undefined ? '' : ` (${why})`}`) + +// An instant from a date in the report's zone; `endOfDay` turns a bare date into the last +// millisecond of that day. Two passes settle a zone whose offset itself depends on the +// instant (a DST boundary). The next day is a calendar step, not 24 hours: the day a zone +// falls back is 25 hours long, so adding a day in milliseconds stays inside the same one. +function parseInstant(text, tz, endOfDay) { + const match = DATE.exec(text) + if (match === null) cannotRead(text, 'expected YYYY-MM-DD or YYYY-MM-DDTHH:MM[:SS]') + const [, year, month, day, hour, minute, second, offset] = match + const [y, mo, d] = [Number(year), Number(month), Number(day)] + const [h, mi, s] = [Number(hour ?? 0), Number(minute ?? 0), Number(second ?? 0)] + if (mo < 1 || mo > 12) cannotRead(text, `month ${mo} does not exist`) + if (d < 1 || d > daysInMonth(y, mo)) cannotRead(text, `day ${d} does not exist in ${year}-${month}`) + if (h > 23 || mi > 59 || s > 59) cannotRead(text, 'time out of range') + const start = instantOf(y, mo, d, h, mi, s, offset, tz, text) + if (!endOfDay || hour !== undefined) return start + const next = new Date(Date.UTC(y, mo - 1, d + 1)) + const nextStart = instantOf(next.getUTCFullYear(), next.getUTCMonth() + 1, next.getUTCDate(), 0, 0, 0, offset, tz, text) + return nextStart - 1 +} + +// The epoch of those wall-clock parts: in `offset` when the date states one, in `tz` +// otherwise. Anything Date.parse refuses — or an offset outside the real range — is an +// error rather than a NaN: a NaN binds as NULL, matches no row, and prints an empty report. +function instantOf(y, mo, d, h, mi, s, offset, tz, text) { + const date = `${y}-${pad(mo)}-${pad(d)}T${pad(h)}:${pad(mi)}:${pad(s)}` + if (offset !== undefined) { + const instant = Date.parse(`${date}${offset}`) + if (!Number.isFinite(instant)) cannotRead(text, `offset ${offset}`) + return instant + } + const guess = Date.UTC(y, mo - 1, d, h, mi, s) + let instant = guess + for (let pass = 0; pass < 2; pass += 1) { + const local = localParts(tz, instant) + const asUtc = Date.UTC(local.year, local.month - 1, local.day, local.hour, local.minute, local.second) + instant = guess - (asUtc - instant) + } + if (!Number.isFinite(instant)) cannotRead(text, `zone ${tz}`) + return instant +} + +const count = value => (Number.isSafeInteger(Number(value)) && Number(value) > 0 ? Number(value) : 0) + +// Nearest-rank percentile of an ascending array. +export function percentile(sorted, p) { + if (sorted.length === 0) return 0 + const rank = Math.ceil((p / 100) * sorted.length) - 1 + return sorted[Math.min(sorted.length - 1, Math.max(0, rank))] +} + +const sum = (rows, key) => rows.reduce((total, row) => total + row[key], 0) +const promptOf = row => row.input + row.cacheRead + row.cacheWrite + +function readRows(dbPath, { from, to, bot }) { + const db = new DatabaseSync(dbPath, { readOnly: true }) + try { + db.exec('PRAGMA busy_timeout = 5000') + const where = [] + const params = [] + if (from !== null) { where.push('c.time >= ?'); params.push(from) } + if (to !== null) { where.push('c.time <= ?'); params.push(to) } + const sql = `SELECT c.session, c.time, c.provider, c.model, c.kind, c.input, c.cache_read, c.cache_write, c.output, o.name AS bot + FROM calls c LEFT JOIN owners o ON o.session = c.session + ${where.length > 0 ? `WHERE ${where.join(' AND ')}` : ''} + ORDER BY c.session, c.time, c.key` + const rows = db.prepare(sql).all(...params).map(row => ({ + session: String(row.session), + time: Number(row.time), + provider: String(row.provider ?? ''), + model: String(row.model ?? ''), + kind: String(row.kind ?? ''), + input: count(row.input), + cacheRead: count(row.cache_read), + cacheWrite: count(row.cache_write), + output: count(row.output), + bot: row.bot === null || row.bot === undefined ? null : String(row.bot), + })) + if (bot === null) return rows + const needle = bot.toLowerCase() + return rows.filter(row => (row.bot ?? '').toLowerCase() === needle || row.session.toLowerCase().startsWith(needle)) + } finally { + db.close() + } +} + +function totals(rows) { + const input = sum(rows, 'input') + const cacheRead = sum(rows, 'cacheRead') + const cacheWrite = sum(rows, 'cacheWrite') + const output = sum(rows, 'output') + const prompts = rows.map(promptOf).sort((a, b) => a - b) + const prompt = input + cacheRead + cacheWrite + return { + calls: rows.length, + input, + cacheRead, + cacheWrite, + output, + prompt, + promptPerCall: { + p50: percentile(prompts, 50), + p90: percentile(prompts, 90), + p99: percentile(prompts, 99), + max: prompts.length === 0 ? 0 : prompts[prompts.length - 1], + }, + cacheReadShare: prompt === 0 ? 0 : cacheRead / prompt, + } +} + +// A Session's calls are appended, so the prompt difference between one call and the next +// is what that turn added. A smaller prompt means a compaction, a checkpoint or a new part: +// the turn after it does not grow the old prompt, so that crossing starts a new run and is +// not a delta. Reported deltas are therefore comparable, and the boundaries are counted. +function growthOf(rows) { + let previous = null + let resets = 0 + const points = [] + const deltas = [] + for (const row of rows) { + const prompt = promptOf(row) + let delta = previous === null ? null : prompt - previous + if (delta !== null && delta < 0) { delta = null; resets += 1 } + points.push({ time: row.time, prompt, delta }) + if (delta !== null) deltas.push(delta) + previous = prompt + } + deltas.sort((a, b) => a - b) + return { + points, + deltas: { + count: deltas.length, + median: percentile(deltas, 50), + p90: percentile(deltas, 90), + resets, + }, + } +} + +function groupBy(rows, key) { + const groups = new Map() + for (const row of rows) { + const name = key(row) + const group = groups.get(name) ?? [] + group.push(row) + groups.set(name, group) + } + return groups +} + +const dayKey = tz => (time) => { + const local = localParts(tz, time) + return `${local.year}-${String(local.month).padStart(2, '0')}-${String(local.day).padStart(2, '0')}` +} + +export function buildReport(rows, { db, from, to, tz }) { + const bots = [...groupBy(rows, row => row.bot ?? row.session)] + .map(([bot, group]) => ({ bot, ...totals(group) })) + .sort((a, b) => b.prompt - a.prompt) + const sessions = [...groupBy(rows, row => row.session)] + .map(([session, group]) => { + const sorted = [...group].sort((a, b) => a.time - b.time) + const growth = growthOf(sorted) + return { + session, + bot: sorted[0].bot ?? session, + first: sorted[0].time, + last: sorted[sorted.length - 1].time, + ...totals(sorted), + growth: growth.deltas, + points: growth.points, + } + }) + .sort((a, b) => b.prompt - a.prompt) + const days = [...groupBy(rows, row => dayKey(tz)(row.time))] + .map(([day, group]) => ({ day, ...totals(group) })) + .sort((a, b) => a.day.localeCompare(b.day)) + const pooled = sessions.flatMap(session => session.points).map(point => point.delta).filter(delta => delta !== null).sort((a, b) => a - b) + return { + db, from, to, tz, ...totals(rows), bots, sessions, days, + growthAll: { count: pooled.length, median: percentile(pooled, 50), p90: percentile(pooled, 90), resets: sessions.reduce((total, session) => total + session.growth.resets, 0) }, + } +} + +// --------------------------------------------------------------------------- +// Printing. + +function table(title, columns, rows) { + const cells = rows.map(row => columns.map(column => String(column.value(row)))) + const widths = columns.map((column, index) => Math.max(column.label.length, ...cells.map(row => row[index].length))) + const line = values => values.map((value, index) => (columns[index].right ? value.padStart(widths[index]) : value.padEnd(widths[index]))).join(' ').trimEnd() + const out = [title, '', line(columns.map(column => column.label)), line(widths.map(width => '-'.repeat(width)))] + for (const row of cells) out.push(line(row)) + return out.join('\n') +} + +const pct = share => `${(share * 100).toFixed(1)}%` +const utc = time => new Date(time).toISOString().replace('.000Z', 'Z') + +function printText(report) { + const window = `${report.from === null ? 'start' : utc(report.from)} .. ${report.to === null ? 'end' : utc(report.to)}` + console.log(`ledger: ${report.db}`) + console.log(`window: ${window} (days in ${report.tz})`) + console.log(`calls: ${report.calls}`) + console.log('') + console.log(table('per Bot', [ + { label: 'bot', value: row => row.bot }, + { label: 'calls', value: row => row.calls, right: true }, + { label: 'fresh input', value: row => row.input, right: true }, + { label: 'cache read', value: row => row.cacheRead, right: true }, + { label: 'cache write', value: row => row.cacheWrite, right: true }, + { label: 'output', value: row => row.output, right: true }, + { label: 'prompt', value: row => row.prompt, right: true }, + { label: 'cache read share', value: row => pct(row.cacheReadShare), right: true }, + ], report.bots)) + console.log('') + console.log('per call prompt (fresh input + cache read + cache write, nearest-rank)') + console.log(` all calls: p50 ${report.promptPerCall.p50} p90 ${report.promptPerCall.p90} p99 ${report.promptPerCall.p99} max ${report.promptPerCall.max}`) + console.log('') + const top = report.sessions.slice(0, Math.max(0, report.top)) + if (top.length > 0) { + console.log(table('top Sessions by prompt', [ + { label: 'session', value: row => row.session }, + { label: 'bot', value: row => row.bot }, + { label: 'calls', value: row => row.calls, right: true }, + { label: 'prompt', value: row => row.prompt, right: true }, + { label: 'fresh input', value: row => row.input, right: true }, + { label: 'cache read', value: row => row.cacheRead, right: true }, + ], top)) + console.log('') + } + if (report.days.length > 0) { + console.log(table(`per day (${report.tz})`, [ + { label: 'day', value: row => row.day }, + { label: 'calls', value: row => row.calls, right: true }, + { label: 'fresh input', value: row => row.input, right: true }, + { label: 'cache read', value: row => row.cacheRead, right: true }, + { label: 'cache write', value: row => row.cacheWrite, right: true }, + { label: 'output', value: row => row.output, right: true }, + { label: 'prompt', value: row => row.prompt, right: true }, + ], report.days)) + console.log('') + } + const growth = report.sessions.slice(0, Math.max(0, report.growth)) + for (const session of growth) { + const rows = session.points.map((point, index) => ({ + index, + time: utc(point.time), + prompt: point.prompt, + delta: point.delta === null ? '(first or compaction)' : `+${point.delta}`, + })) + console.log(table(`prompt growth: ${session.session} (${session.bot}) — median delta ${session.growth.median}, p90 ${session.growth.p90}, ${session.growth.resets} compaction boundary(ies)`, [ + { label: 'call', value: row => row.index, right: true }, + { label: 'time', value: row => row.time }, + { label: 'prompt', value: row => row.prompt, right: true }, + { label: 'delta', value: row => row.delta, right: true }, + ], rows)) + console.log('') + } +} + +function main() { + const flags = parseArgs(process.argv.slice(2)) + const dbPath = flags.db ?? join(process.env.DSH_HOME ?? join(homedir(), '.dsh'), 'usage.sqlite') + if (!existsSync(dbPath)) die(`no ledger at ${dbPath} (pass --db )`) + const from = flags.from === null ? null : parseInstant(flags.from, flags.tz, false) + const to = flags.to === null ? null : parseInstant(flags.to, flags.tz, true) + if (from !== null && to !== null && from > to) die(`--from is after --to`) + const rows = readRows(dbPath, { from, to, bot: flags.bot }) + const report = { ...buildReport(rows, { db: dbPath, from, to, tz: flags.tz }), top: flags.top, growth: flags.growth } + if (flags.json) { + const sessions = report.sessions.map(({ points, ...session }) => session) + console.log(JSON.stringify({ ...report, sessions }, null, 2)) + return + } + printText(report) +} + +if (process.argv[1] !== undefined && import.meta.url === pathToFileURL(resolve(process.argv[1])).href) main() diff --git a/core/test/token-report.test.js b/core/test/token-report.test.js new file mode 100644 index 000000000..59fdcf848 --- /dev/null +++ b/core/test/token-report.test.js @@ -0,0 +1,204 @@ +import assert from 'node:assert/strict' +import { spawnSync } from 'node:child_process' +import { mkdtempSync, readFileSync, rmSync } from 'node:fs' +import { tmpdir } from 'node:os' +import { dirname, join } from 'node:path' +import { DatabaseSync } from 'node:sqlite' +import { test } from 'node:test' +import { fileURLToPath } from 'node:url' + +const ROOT = join(dirname(fileURLToPath(import.meta.url)), '..', '..') +const SCRIPT = join(ROOT, 'core', 'dev', 'token-report.mjs') +const REPORT = join(ROOT, 'docs', 'reports', '2026-10-23-token-spend.md') + +const at = minutes => Date.UTC(2026, 9, 20, 10, minutes) + +// The ledger's schema as src/host/usage.js creates it. One Bot with a cache-read-heavy +// turn, a Bot with none, and a third Session with no owners row. +const calls = [ + // session-dev, owned by Dev: three turns, then a compaction shrinks the prompt. + ['session-dev', at(0), 'turn', 100, 1000, 10, 5], + ['session-dev', at(1), 'turn', 200, 1000, 0, 7], + ['session-dev', at(2), 'turn', 50, 900, 0, 9], + ['session-dev', at(3), 'turn', 5, 0, 0, 2], + // session-reviewer, owned by Reviewer: no cache reads at all. + ['session-reviewer', at(0), 'turn', 10, 0, 0, 3], + // session-unowned: no owners row, so it must appear under its Session id. + ['session-unowned', at(0), 'turn', 7, 30, 1, 2], +] +const owners = [ + ['session-dev', 'session-dev', 'Dev'], + ['session-reviewer', 'session-reviewer', 'Reviewer'], +] + +function fixture(extra = []) { + const dir = mkdtempSync(join(tmpdir(), 'token-report-')) + const path = join(dir, 'usage.sqlite') + const db = new DatabaseSync(path) + try { + db.exec(` + CREATE TABLE calls (key TEXT PRIMARY KEY, session TEXT NOT NULL, time INTEGER NOT NULL, provider TEXT NOT NULL, model TEXT NOT NULL, kind TEXT NOT NULL, live INTEGER NOT NULL, input INTEGER NOT NULL, cache_read INTEGER NOT NULL, cache_write INTEGER NOT NULL, output INTEGER NOT NULL); + CREATE TABLE owners (session TEXT PRIMARY KEY, owner TEXT NOT NULL, name TEXT NOT NULL);`) + const put = db.prepare('INSERT INTO calls (key, session, time, provider, model, kind, live, input, cache_read, cache_write, output) VALUES (?, ?, ?, ?, ?, ?, 0, ?, ?, ?, ?)') + for (const [index, [session, time, kind, input, cacheRead, cacheWrite, output]] of [...calls, ...extra].entries()) { + put.run(`${session}:${index}`, session, time, 'test', 'test-model', kind, input, cacheRead, cacheWrite, output) + } + const owner = db.prepare('INSERT INTO owners (session, owner, name) VALUES (?, ?, ?)') + for (const row of owners) owner.run(...row) + } finally { + db.close() + } + return { path, dir } +} + +function run(path, ...args) { + const result = spawnSync(process.execPath, [SCRIPT, '--db', path, ...args], { encoding: 'utf8' }) + return result +} + +test('the report matches hand-computed sums, with cache reads kept apart', () => { + const { path, dir } = fixture() + try { + const result = run(path, '--json', '--tz', 'UTC') + assert.equal(result.status, 0, result.stderr) + const report = JSON.parse(result.stdout) + assert.equal(report.calls, 6) + assert.deepEqual( + { input: report.input, cacheRead: report.cacheRead, cacheWrite: report.cacheWrite, output: report.output, prompt: report.prompt }, + { input: 372, cacheRead: 2930, cacheWrite: 11, output: 28, prompt: 3313 }, + ) + // 5, 10, 38, 950, 1110, 1200 — nearest rank. + assert.deepEqual(report.promptPerCall, { p50: 38, p90: 1200, p99: 1200, max: 1200 }) + + const dev = report.bots.find(row => row.bot === 'Dev') + assert.deepEqual( + { calls: dev.calls, input: dev.input, cacheRead: dev.cacheRead, cacheWrite: dev.cacheWrite, output: dev.output, prompt: dev.prompt }, + { calls: 4, input: 355, cacheRead: 2900, cacheWrite: 10, output: 23, prompt: 3265 }, + ) + // Cache reads are never folded into fresh input: the two columns stay the numbers above. + assert.equal(dev.input, 355) + assert.equal(dev.cacheRead, 2900) + assert.equal(dev.input + dev.cacheRead + dev.cacheWrite, dev.prompt) + + // An unowned Session appears under its Session id, not dropped. + const unowned = report.bots.find(row => row.bot === 'session-unowned') + assert.deepEqual({ input: unowned.input, cacheRead: unowned.cacheRead, prompt: unowned.prompt }, { input: 7, cacheRead: 30, prompt: 38 }) + + const day = report.days.find(row => row.day === '2026-10-20') + assert.equal(day.calls, 6) + + // Growth is measured between comparable calls: the compaction (1110 → 5) starts a + // new run instead of contributing a large negative delta. + const session = report.sessions.find(row => row.session === 'session-dev') + assert.deepEqual(session.growth, { count: 1, median: 90, p90: 90, resets: 2 }) + assert.equal(report.growthAll.resets, 2) + } finally { + rmSync(dir, { recursive: true, force: true }) + } +}) + +test('the window, the Bot filter and a missing ledger', () => { + const { path, dir } = fixture() + try { + const windowed = run(path, '--json', '--tz', 'UTC', '--from', '2026-10-20T10:01', '--to', '2026-10-20T10:02') + assert.equal(windowed.status, 0, windowed.stderr) + const window = JSON.parse(windowed.stdout) + assert.equal(window.calls, 2) + assert.equal(window.input, 250) + + const byName = JSON.parse(run(path, '--json', '--bot', 'dev').stdout) + assert.equal(byName.calls, 4) + const bySession = JSON.parse(run(path, '--json', '--bot', 'session-uno').stdout) + assert.equal(bySession.calls, 1) + + const missing = join(dir, 'nope.sqlite') + const absent = run(missing) + assert.notEqual(absent.status, 0) + assert.match(absent.stderr, new RegExp(`no ledger at ${missing.replace(/[.*+?^${}()|[\]\\]/g, '\\$&')}`)) + + const badDate = run(path, '--from', 'yesterday') + assert.notEqual(badDate.status, 0) + assert.match(badDate.stderr, /cannot read "yesterday" as a date/) + + const backwards = run(path, '--from', '2026-10-21', '--to', '2026-10-20') + assert.notEqual(backwards.status, 0) + } finally { + rmSync(dir, { recursive: true, force: true }) + } +}) + +test('an impossible date is an error, never an empty report', () => { + const { path, dir } = fixture() + try { + // Each of these used to reach Date.parse or Date.UTC and come back NaN or normalised, + // which printed "calls 0" and exited 0 — the one thing this report must never do. + for (const [flag, value] of [ + ['--from', '2026-13-01Z'], + ['--from', '2026-02-31'], + ['--to', '2026-02-31'], + ['--from', '2026-11-02T10:00+99:00'], + ['--to', '2026-01-01T24:00'], + ]) { + const result = run(path, flag, value) + assert.notEqual(result.status, 0, `${flag} ${value} exited 0`) + assert.match(result.stderr, /cannot read .* as a date/, `${flag} ${value}: ${result.stderr}`) + assert.equal(result.stdout, '', `${flag} ${value} printed a report`) + } + const valid = run(path, '--json', '--from', '2026-02-28', '--to', '2026-03-01') + assert.equal(valid.status, 0, valid.stderr) + } finally { + rmSync(dir, { recursive: true, force: true }) + } +}) + +test('a day a zone falls back is 25 hours, and --to covers all of it', () => { + // 2025-11-02 in America/New_York is 25 hours: it starts at 04:00Z (EDT) and ends at + // 05:00Z the next day (EST). 15:00Z is 10:00 EST, after the fall-back at 06:00Z. + const { path, dir } = fixture([ + ['session-dst', Date.parse('2025-11-02T15:00:00Z'), 'turn', 10, 0, 0, 1], + ['session-dst', Date.parse('2025-11-02T17:30:00Z'), 'turn', 10, 0, 0, 1], + ]) + try { + const day = JSON.parse(run(path, '--json', '--tz', 'America/New_York', '--from', '2025-11-02', '--to', '2025-11-02').stdout) + // The bound itself, not just "the two values differ": local 23:59:59.999 on the 2nd. + assert.equal(day.to, 1762145999999) + assert.equal(new Date(day.to).toISOString(), '2025-11-03T04:59:59.999Z') + assert.equal(day.calls, 2) + assert.deepEqual(day.days.map(row => [row.day, row.calls]), [['2025-11-02', 2]]) + + // The day before it ends 25 hours earlier, and holds none of them. + const earlier = JSON.parse(run(path, '--json', '--tz', 'America/New_York', '--to', '2025-11-01').stdout) + assert.equal(earlier.to, 1762055999999) + assert.equal(earlier.to - day.to, -90_000_000) + assert.equal(earlier.calls, 0) + + // And a bare --to on a normal day still ends at that day's last millisecond. + const ordinary = JSON.parse(run(path, '--json', '--tz', 'UTC', '--from', '2026-10-20', '--to', '2026-10-20').stdout) + assert.equal(ordinary.calls, 6) + } finally { + rmSync(dir, { recursive: true, force: true }) + } +}) + +// Every number in the committed report is a table row whose last cell names where it came +// from: the ledger, a formula over the ledger, or that it was not measured. +const PROVENANCE = /^(ledger|derived: .+|not measured)$/ + +test('every row of the committed report carries its provenance', () => { + const lines = readFileSync(REPORT, 'utf8').split(/\r?\n/) + const rows = [] + let header = null + for (const line of lines) { + const cells = line.startsWith('|') ? line.split('|').slice(1, -1).map(cell => cell.trim()) : null + if (cells === null) { header = null; continue } + if (header === null) { header = cells; continue } + if (cells.every(cell => /^:?-{3,}:?$/.test(cell))) continue + assert.equal(header.at(-1), 'Source', `a table starting with ${header[0]} has no Source column`) + rows.push({ header, cells }) + } + assert.ok(rows.length > 0, 'the report has no tables') + for (const row of rows) { + assert.match(row.cells.at(-1), PROVENANCE, `no provenance: | ${row.cells.join(' | ')} |`) + assert.equal(row.cells.length, row.header.length, `a row has ${row.cells.length} cells, its table ${row.header.length}: | ${row.cells.join(' | ')} |`) + } +}) diff --git a/docs/reports/2026-10-23-token-spend.md b/docs/reports/2026-10-23-token-spend.md new file mode 100644 index 000000000..cd35fad2f --- /dev/null +++ b/docs/reports/2026-10-23-token-spend.md @@ -0,0 +1,189 @@ +# Token spend per Bot turn + +Measured 2026-10-23 from this host's usage ledger, for [#799](https://github.com/ThinkFlowLab/FlyBot/issues/799) — the measuring half of [#796](https://github.com/ThinkFlowLab/FlyBot/issues/796). This report changes nothing that is sent to a model: no prompt, notice, roster, memory or tool-output edit. Its purpose is a number that a later saving can be compared against. + +The ledger already existed (`core/src/host/usage.js`, one row per billed attempt at `$DSH_HOME/usage.sqlite`). What was missing was a reader outside the Usage page; that is `core/dev/token-report.mjs`, and the commands below reproduce every table. + +## Sample + +| Item | Value | Source | +| --- | --- | --- | +| Ledger snapshot | a copy of `$DSH_HOME/usage.sqlite` (data file plus `-wal` and `-shm`) taken before reading | ledger | +| Window | 2026-10-20T07:34:24.425Z .. 2026-10-23T02:06:18.388Z | ledger | +| Billed attempts | 16,407 | ledger | +| Sessions with calls | 71 | ledger | +| Bots (owners) named in the ledger | 79, of which 26 have calls in the window | ledger | +| Cache writes | 0 in every row — this provider reports none, so that column proves nothing here | ledger | + +Reading a live ledger twice gives two different answers: a Bot's own turn writes rows while the report runs. The snapshot above is a file copy, so the numbers are stable, and they will not equal a later run. + +## Method + +Fresh input, cache read and cache write are never added into one another. `prompt` is their sum and is always its own column, because a cached token and a fresh input token are not the same cost and a saving that only moves tokens between the columns would otherwise look real ([#796](https://github.com/ThinkFlowLab/FlyBot/issues/796)). + +Percentiles are nearest-rank: the ascending value at `ceil(p/100 × n) - 1`, so the p99 of a small sample is its maximum. Percentiles are computed per call over every attempt in the window. + +Growth is measured inside one Session, between consecutive calls, and only within a run: a smaller prompt means a compaction, a checkpoint or a new part, so that crossing starts a new run and contributes no delta. `resets` counts those boundaries. + +```sh +# 1. Snapshot the live ledger (read it only after copying all three files). +mkdir -p /tmp/token-report && cp "$DSH_HOME"/usage.sqlite* /tmp/token-report/ + +# 2. Every table below. +node core/dev/token-report.mjs --db /tmp/token-report/usage.sqlite --tz Asia/Shanghai --top 10 + +# 3. The same numbers as JSON, which is what the committed test asserts against a fixture. +node core/dev/token-report.mjs --db /tmp/token-report/usage.sqlite --tz Asia/Shanghai --json +``` + +A missing `--db` is an error that names the path, never an empty table: an empty report is what a broken path looks like. + +## 1. Totals + +| Measure | Value | Source | +| --- | --- | --- | +| Calls | 16,407 | ledger | +| Fresh input | 77,271,661 | ledger | +| Cache read | 2,040,613,888 | ledger | +| Cache write | 0 | ledger | +| Output | 9,387,044 | ledger | +| Prompt | 2,117,885,549 | derived: fresh input + cache read + cache write | +| Cache read share of prompt | 96.4% | derived: cache read / prompt | + +## 2. Per Bot + +Sorted by prompt. `fresh input` is what was billed as input, not the prompt. + +| Bot | Calls | Fresh input | Cache read | Cache write | Output | Prompt | Cache read share | Source | +| --- | --- | --- | --- | --- | --- | --- | --- | --- | +| Dev | 3,183 | 8,787,133 | 430,347,136 | 0 | 1,688,487 | 439,134,269 | 98.0% | ledger | +| Reviewer | 2,860 | 9,573,425 | 379,113,088 | 0 | 1,650,023 | 388,686,513 | 97.5% | ledger | +| Chief | 1,964 | 13,328,314 | 223,369,344 | 0 | 1,302,937 | 236,697,658 | 94.4% | ledger | +| Dev2 | 1,315 | 4,287,480 | 188,972,416 | 0 | 727,043 | 193,259,896 | 97.8% | ledger | +| Maintainer | 1,415 | 2,932,025 | 180,925,184 | 0 | 797,996 | 183,857,209 | 98.4% | ledger | +| Dev4 | 1,042 | 3,501,801 | 145,925,120 | 0 | 548,749 | 149,426,921 | 97.7% | ledger | +| Dev3 | 1,012 | 2,711,898 | 138,261,632 | 0 | 558,353 | 140,973,530 | 98.1% | ledger | +| Triage | 1,122 | 6,168,230 | 123,720,320 | 0 | 778,220 | 129,888,550 | 95.3% | ledger | +| SelfTest | 623 | 3,042,507 | 67,570,560 | 0 | 410,561 | 70,613,067 | 95.7% | ledger | +| Backend | 610 | 13,655,841 | 51,881,216 | 0 | 262,757 | 65,537,057 | 79.2% | ledger | +| FlyBot 实现 Lead | 485 | 5,504,028 | 41,257,728 | 0 | 229,462 | 46,761,756 | 88.2% | ledger | +| Reviewer2 | 304 | 875,004 | 41,567,872 | 0 | 160,956 | 42,442,876 | 97.9% | ledger | +| Release | 141 | 1,018,807 | 10,018,304 | 0 | 83,230 | 11,037,111 | 90.8% | ledger | +| Ops | 111 | 469,060 | 7,176,192 | 0 | 47,229 | 7,645,252 | 93.9% | ledger | +| Docs | 74 | 253,671 | 4,759,040 | 0 | 62,428 | 5,012,711 | 94.9% | ledger | +| QA | 95 | 727,859 | 3,807,104 | 0 | 45,222 | 4,534,963 | 84.0% | ledger | +| Inbox | 15 | 136,289 | 1,116,672 | 0 | 20,257 | 1,252,961 | 89.1% | ledger | +| Reviewer Lead | 13 | 71,253 | 586,496 | 0 | 8,106 | 657,749 | 89.2% | ledger | +| Architect | 12 | 101,114 | 206,976 | 0 | 3,681 | 308,090 | 67.2% | ledger | +| UI | 5 | 16,773 | 31,488 | 0 | 526 | 48,261 | 65.2% | ledger | +| Research Lead | 1 | 32,767 | 0 | 0 | 16 | 32,767 | 0.0% | ledger | +| Frontend | 1 | 15,303 | 0 | 0 | 263 | 15,303 | 0.0% | ledger | +| Security | 1 | 15,274 | 0 | 0 | 58 | 15,274 | 0.0% | ledger | +| Scout | 1 | 15,273 | 0 | 0 | 84 | 15,273 | 0.0% | ledger | +| Data | 1 | 15,266 | 0 | 0 | 200 | 15,266 | 0.0% | ledger | +| Performance | 1 | 15,266 | 0 | 0 | 200 | 15,266 | 0.0% | ledger | + +The Bots with one or five calls are freshly created tree members: their Sessions have not yet grown, which is why their cache read share is zero or small rather than a property of how they work. + +## 3. Per-call prompt + +Over all 16,407 attempts: p50 **129,242**, p90 **210,628**, p99 **244,885**, max 282,000. + +| Statistic | Prompt tokens per call | Source | +| --- | --- | --- | +| p50 | 129,242 | ledger | +| p90 | 210,628 | ledger | +| p99 | 244,885 | ledger | +| max | 282,000 | ledger | + +## 4. Top Sessions by prompt + +A Session is a part of one Bot's conversation; the top ones are the long-running chats, not the ones with the most calls per unit of time. + +| Session | Bot | Calls | Prompt | Fresh input | Cache read | Source | +| --- | --- | --- | --- | --- | --- | --- | +| session-a7e7bb0b-e497-46ff-aeee-c23b8ceaf7fb | Chief | 1,495 | 182,599,188 | 8,045,460 | 174,553,728 | ledger | +| session-8e806e1f-a606-485e-96b6-696b8d6ddcf5 | Dev | 953 | 142,729,431 | 2,474,967 | 140,254,464 | ledger | +| session-7c0d0937-9ca9-44c4-9bdd-f8324b0d8814 | Reviewer | 932 | 136,893,497 | 1,732,921 | 135,160,576 | ledger | +| session-c8657b99-1f73-40e2-bec5-0461b541122c | Dev2 | 837 | 125,441,718 | 3,462,966 | 121,978,752 | ledger | +| session-5bfa0d6a-bcfb-4d77-90fa-522eeec31de4 | Dev4 | 838 | 121,480,013 | 3,194,189 | 118,285,824 | ledger | +| session-172bbf6c-5e9b-410f-b726-359e917f9086 | Maintainer | 733 | 99,600,738 | 1,519,074 | 98,081,664 | ledger | +| session-8bb2d67d-78dc-41a2-a911-aaae21dc6049 | Dev | 619 | 87,689,234 | 1,607,698 | 86,081,536 | ledger | +| session-ecb1913f-13ee-41de-a5bb-42cab93d5241 | Dev3 | 590 | 80,668,216 | 1,788,600 | 78,879,616 | ledger | +| session-efe31685-4244-4431-b4ac-a338dd4d5ef9 | Dev | 583 | 80,128,667 | 1,987,739 | 78,140,928 | ledger | +| session-282f65cb-759c-40cd-bb8b-7691aa8d38d0 | Dev2 | 477 | 67,783,503 | 789,839 | 66,993,664 | ledger | + +## 5. Per day + +Days are in `Asia/Shanghai` (`--tz`), not UTC. 2026-10-20 starts at 15:34 local, which is why it has 486 calls. + +| Day | Calls | Fresh input | Cache read | Cache write | Output | Prompt | Source | +| --- | --- | --- | --- | --- | --- | --- | --- | +| 2026-10-20 | 486 | 2,341,141 | 39,095,680 | 0 | 302,233 | 41,436,821 | ledger | +| 2026-10-21 | 5,595 | 33,897,488 | 614,389,504 | 0 | 3,203,008 | 648,286,992 | ledger | +| 2026-10-22 | 10,295 | 40,987,551 | 1,385,137,024 | 0 | 5,864,278 | 1,426,124,575 | ledger | +| 2026-10-23 | 31 | 45,481 | 1,991,680 | 0 | 17,525 | 2,037,161 | ledger | + +The 2026-10-23 row is 2 hours long; it is the start of the day, not a drop in spend. + +## 6. Prompt growth per Session + +Across every Session, between comparable calls: 15,653 deltas, median **+804** tokens, p90 **+3,021**, with 683 compaction or new-part boundaries excluded (`resets`). + +| Measure | Deltas | Median delta | p90 delta | Source | +| --- | --- | --- | --- | --- | +| All Sessions, comparable calls | 15,653 | 804 | 3,021 | derived: consecutive turn prompts in one Session, split where the prompt falls | +| Compaction boundaries excluded | 683 | not applicable | not applicable | derived: a prompt smaller than the previous call in the same Session | + +The per-Session curve, for the Sessions with the most prompt: + +| Session | Bot | Calls | Deltas | Median delta | p90 delta | Resets | Source | +| --- | --- | --- | --- | --- | --- | --- | --- | +| session-a7e7bb0b-e497-46ff-aeee-c23b8ceaf7fb | Chief | 1,495 | 1,382 | 1,142 | 3,426 | 112 | derived: consecutive turn prompts in one Session | +| session-8e806e1f-a606-485e-96b6-696b8d6ddcf5 | Dev | 953 | 935 | 754 | 2,738 | 17 | derived: consecutive turn prompts in one Session | +| session-7c0d0937-9ca9-44c4-9bdd-f8324b0d8814 | Reviewer | 932 | 916 | 872 | 2,603 | 15 | derived: consecutive turn prompts in one Session | +| session-c8657b99-1f73-40e2-bec5-0461b541122c | Dev2 | 837 | 825 | 687 | 2,348 | 11 | derived: consecutive turn prompts in one Session | +| session-5bfa0d6a-bcfb-4d77-90fa-522eeec31de4 | Dev4 | 838 | 828 | 711 | 2,577 | 9 | derived: consecutive turn prompts in one Session | +| session-172bbf6c-5e9b-410f-b726-359e917f9086 | Maintainer | 733 | 715 | 740 | 2,416 | 17 | derived: consecutive turn prompts in one Session | +| session-8bb2d67d-78dc-41a2-a911-aaae21dc6049 | Dev | 619 | 611 | 752 | 2,424 | 7 | derived: consecutive turn prompts in one Session | +| session-ecb1913f-13ee-41de-a5bb-42cab93d5241 | Dev3 | 590 | 582 | 660 | 2,364 | 7 | derived: consecutive turn prompts in one Session | + +Each delta is the prompt growth of one turn, so a median of ~800 tokens per turn against a p50 prompt of ~129,000 tokens says where the spend is: a turn costs its whole history again, not the ~800 tokens it adds. Whether a given saving helps is a question about the other ~128,000. + +## 7. Composition: fixed overhead / history / tool results / task + +**Not measured on this host.** The ledger stores the prompt total and its three columns; it does not store the request, so it cannot split the prompt into the group notice, the roster, the memory, the earlier turns, the tool results and the current task. That split needs one dumped request body per sampled turn and one ablated replay per category through `core/dev/llm-tap.mjs` with a real provider call, which needs a provider key and dumped bodies — neither exists on this host (no `llm-tap` log or body directory, and the provider key is not readable by this Bot). No number is printed for a category rather than showing an estimate as if it were measured. + +| Category | What it is | How it would be measured | Source | +| --- | --- | --- | --- | +| Fixed overhead | system prompt, group notice, member roster, speaking order, tree block, injected memory | one replay with the block removed, provider-reported prompt difference | not measured | +| History | every earlier turn of the Session, re-read on each call | one replay with the first half of the turns removed, provider-reported prompt difference | not measured | +| Tool results | GitHub JSON, test logs, file reads carried in the transcript | one replay with tool results truncated to a fixed size, provider-reported prompt difference | not measured | +| Task | the current instruction and its attachments | one replay with the instruction and attachments removed, provider-reported prompt difference | not measured | +| Character share of any category | where the characters sit in one dumped body | count characters per message role in the dumped body | not measured | + +What it would take: + +```sh +# 1. Run a Session through the tap with bodies saved. +node core/dev/llm-tap.mjs /tmp/tap.jsonl /tmp/bodies + +# 2. For each category, send the same body once with the category removed and once unchanged. +# Each variant is a real provider call; the ledger reports its prompt. +``` + +Until that exists, the safest reading of the measured columns is that history re-read is 96.4% of the prompt and therefore the largest single thing being paid for; where the remaining 3.6% sits among fixed overhead, tool results and the task is not known from this ledger. + +## What this report does not say + +- It proposes no saving. `#796` owns the decision about which saving to take; this issue owns the number to compare it against. +- It does not compare models or providers. The 20 Bots moved from `volc` to `opencsitool` during the window, so a per-model split would compare two partial samples, not two policies. +- Cache read tokens are counted at face value, as the ledger stores them. Their price is not applied: the ledger has no cost column, and every provider route prices them differently. + +## Provenance + +- `ledger` — a column the ledger stores, summed or listed here. +- `derived: ` — computed from ledger columns by the formula named in the row. +- `not measured` — no number exists for it in this sample; the row says what would produce one. + +Every row of every table above carries its provenance, and `core/test/token-report.test.js` fails if a row stops carrying it. diff --git a/docs/subsystems/ds-bot-core.md b/docs/subsystems/ds-bot-core.md index 01919a653..2dabda38c 100644 --- a/docs/subsystems/ds-bot-core.md +++ b/docs/subsystems/ds-bot-core.md @@ -41,6 +41,7 @@ holds. Task bookkeeping does not imply runtime execution or tool permission. | `patches/ds-bot/` | Ordered patch topics. | | `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/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). | ## Entry points @@ -79,6 +80,21 @@ real `dev/bench.sh` bench: actual DSH sessions, the scripted mock model, real sh tool writes and test runs, and the task API lifecycle to `accepted`. It is a manual, CI-optional smoke, still deterministic and token-free, not a real-model trial. +## Token report + +The usage ledger (`src/host/usage.js`) is read outside the Usage page by +`core/dev/token-report.mjs` (#799): per Bot, per Session and per day it prints calls, fresh +input, cache read, cache write, output and their sum as a separate `prompt` column, the +per-call prompt percentiles (nearest rank), the top Sessions by prompt, and each Session's +prompt growth between consecutive calls. A prompt that shrinks inside a Session is a +compaction, a checkpoint or a new part, so it starts a new run instead of counting as a +negative delta. Fresh input and cache read are never summed into one figure. It opens the +ledger read-only, defaults `--db` to `$DSH_HOME/usage.sqlite`, and exits non-zero naming the +path when it is missing. The report it produced and its sample are in +[docs/reports/2026-10-23-token-spend.md](../../docs/reports/2026-10-23-token-spend.md); +`core/test/token-report.test.js` asserts hand-computed sums on a fixture ledger, the +missing-`--db` exit, and that every row of that report still carries its provenance. + ## Common mistakes - Hand-editing `ds-bot/` or `client.js`. diff --git a/patches/ds-bot/files/dev/token-report.mjs b/patches/ds-bot/files/dev/token-report.mjs new file mode 100644 index 000000000..0afbd8920 --- /dev/null +++ b/patches/ds-bot/files/dev/token-report.mjs @@ -0,0 +1,364 @@ +// Reads the usage ledger into the numbers #796 asks for: per Bot, per Session, per day, +// and the prompt a Session grows by from one call to the next. It is a report, not a +// change to what is sent: it opens the ledger read-only and prints. +// +// node dev/token-report.mjs [--db ] [--from ] [--to ] [--tz ] +// [--bot ] [--top ] [--growth ] [--json] +// +// `--db` defaults to `$DSH_HOME/usage.sqlite` (see src/host/usage.js). A missing file is an +// error, never an empty table: an empty report is exactly what a broken path looks like. +// +// Fresh input, cache read and cache write are kept apart in every total. A cache read is +// not a fresh input token and summing them hides which one moved (`#796`). `prompt` is the +// sum of the three and is printed as its own column, never used as the input figure. +// +// `--from` / `--to` take `YYYY-MM-DD` or `YYYY-MM-DDTHH:MM[:SS]`, read in `--tz` +// (default UTC) unless they carry `Z` or an offset. A bare `--to` date ends at the end of +// that day in `--tz`. `--bot` matches a Bot name (case-insensitive) or a Session id +// prefix. `--top` is how many Sessions the "top by prompt" table shows (default 10) and +// `--growth` how many carry the per-call growth table (default 5, 0 turns it off). +// +// Percentiles are nearest-rank: the sorted value at `ceil(p/100 * n) - 1`, so a p99 of a +// small sample is its maximum. The report prints that definition too. +import { DatabaseSync } from 'node:sqlite' +import { existsSync, readFileSync } from 'node:fs' +import { homedir } from 'node:os' +import { join, resolve } from 'node:path' +import { pathToFileURL } from 'node:url' + +const USAGE = 'usage: node dev/token-report.mjs [--db ] [--from ] [--to ] [--tz ] [--bot ] [--top ] [--growth ] [--json]' + +function die(message) { + console.error(`token-report: ${message}`) + process.exit(1) +} + +function parseArgs(argv) { + const flags = { db: null, from: null, to: null, tz: 'UTC', bot: null, top: 10, growth: 5, json: false } + for (let index = 0; index < argv.length; index += 1) { + const arg = argv[index] + const value = () => { + const next = argv[index + 1] + if (next === undefined || next.startsWith('--')) die(`${arg} needs a value`) + index += 1 + return next + } + switch (arg) { + case '--db': flags.db = value(); break + case '--from': flags.from = value(); break + case '--to': flags.to = value(); break + case '--tz': flags.tz = value(); break + case '--bot': flags.bot = value(); break + case '--top': flags.top = Number(value()); break + case '--growth': flags.growth = Number(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}`) + } + } + for (const key of ['top', 'growth']) { + if (!Number.isSafeInteger(flags[key]) || flags[key] < 0) die(`--${key} must be a whole number`) + } + return flags +} + +// The local wall-clock parts of an instant in a zone, and the epoch of those parts read +// as UTC (that difference is the zone's offset at that instant). +function localParts(tz, time) { + let format + try { + format = new Intl.DateTimeFormat('en-CA', { + timeZone: tz, year: 'numeric', month: '2-digit', day: '2-digit', + hour: '2-digit', minute: '2-digit', second: '2-digit', hourCycle: 'h23', + }) + } catch { + die(`unknown time zone ${tz}`) + } + const part = Object.fromEntries(format.formatToParts(new Date(time)).map(({ type, value }) => [type, value])) + return { year: Number(part.year), month: Number(part.month), day: Number(part.day), hour: Number(part.hour), minute: Number(part.minute), second: Number(part.second) } +} + +const DATE = /^(\d{4})-(\d{2})-(\d{2})(?:[T ](\d{2}):(\d{2})(?::(\d{2}))?)?(Z|[+-]\d{2}:\d{2})?$/ + +const daysInMonth = (year, month) => new Date(Date.UTC(year, month, 0)).getUTCDate() +const pad = value => String(value).padStart(2, '0') +const cannotRead = (text, why) => die(`cannot read ${JSON.stringify(text)} as a date${why === undefined ? '' : ` (${why})`}`) + +// An instant from a date in the report's zone; `endOfDay` turns a bare date into the last +// millisecond of that day. Two passes settle a zone whose offset itself depends on the +// instant (a DST boundary). The next day is a calendar step, not 24 hours: the day a zone +// falls back is 25 hours long, so adding a day in milliseconds stays inside the same one. +function parseInstant(text, tz, endOfDay) { + const match = DATE.exec(text) + if (match === null) cannotRead(text, 'expected YYYY-MM-DD or YYYY-MM-DDTHH:MM[:SS]') + const [, year, month, day, hour, minute, second, offset] = match + const [y, mo, d] = [Number(year), Number(month), Number(day)] + const [h, mi, s] = [Number(hour ?? 0), Number(minute ?? 0), Number(second ?? 0)] + if (mo < 1 || mo > 12) cannotRead(text, `month ${mo} does not exist`) + if (d < 1 || d > daysInMonth(y, mo)) cannotRead(text, `day ${d} does not exist in ${year}-${month}`) + if (h > 23 || mi > 59 || s > 59) cannotRead(text, 'time out of range') + const start = instantOf(y, mo, d, h, mi, s, offset, tz, text) + if (!endOfDay || hour !== undefined) return start + const next = new Date(Date.UTC(y, mo - 1, d + 1)) + const nextStart = instantOf(next.getUTCFullYear(), next.getUTCMonth() + 1, next.getUTCDate(), 0, 0, 0, offset, tz, text) + return nextStart - 1 +} + +// The epoch of those wall-clock parts: in `offset` when the date states one, in `tz` +// otherwise. Anything Date.parse refuses — or an offset outside the real range — is an +// error rather than a NaN: a NaN binds as NULL, matches no row, and prints an empty report. +function instantOf(y, mo, d, h, mi, s, offset, tz, text) { + const date = `${y}-${pad(mo)}-${pad(d)}T${pad(h)}:${pad(mi)}:${pad(s)}` + if (offset !== undefined) { + const instant = Date.parse(`${date}${offset}`) + if (!Number.isFinite(instant)) cannotRead(text, `offset ${offset}`) + return instant + } + const guess = Date.UTC(y, mo - 1, d, h, mi, s) + let instant = guess + for (let pass = 0; pass < 2; pass += 1) { + const local = localParts(tz, instant) + const asUtc = Date.UTC(local.year, local.month - 1, local.day, local.hour, local.minute, local.second) + instant = guess - (asUtc - instant) + } + if (!Number.isFinite(instant)) cannotRead(text, `zone ${tz}`) + return instant +} + +const count = value => (Number.isSafeInteger(Number(value)) && Number(value) > 0 ? Number(value) : 0) + +// Nearest-rank percentile of an ascending array. +export function percentile(sorted, p) { + if (sorted.length === 0) return 0 + const rank = Math.ceil((p / 100) * sorted.length) - 1 + return sorted[Math.min(sorted.length - 1, Math.max(0, rank))] +} + +const sum = (rows, key) => rows.reduce((total, row) => total + row[key], 0) +const promptOf = row => row.input + row.cacheRead + row.cacheWrite + +function readRows(dbPath, { from, to, bot }) { + const db = new DatabaseSync(dbPath, { readOnly: true }) + try { + db.exec('PRAGMA busy_timeout = 5000') + const where = [] + const params = [] + if (from !== null) { where.push('c.time >= ?'); params.push(from) } + if (to !== null) { where.push('c.time <= ?'); params.push(to) } + const sql = `SELECT c.session, c.time, c.provider, c.model, c.kind, c.input, c.cache_read, c.cache_write, c.output, o.name AS bot + FROM calls c LEFT JOIN owners o ON o.session = c.session + ${where.length > 0 ? `WHERE ${where.join(' AND ')}` : ''} + ORDER BY c.session, c.time, c.key` + const rows = db.prepare(sql).all(...params).map(row => ({ + session: String(row.session), + time: Number(row.time), + provider: String(row.provider ?? ''), + model: String(row.model ?? ''), + kind: String(row.kind ?? ''), + input: count(row.input), + cacheRead: count(row.cache_read), + cacheWrite: count(row.cache_write), + output: count(row.output), + bot: row.bot === null || row.bot === undefined ? null : String(row.bot), + })) + if (bot === null) return rows + const needle = bot.toLowerCase() + return rows.filter(row => (row.bot ?? '').toLowerCase() === needle || row.session.toLowerCase().startsWith(needle)) + } finally { + db.close() + } +} + +function totals(rows) { + const input = sum(rows, 'input') + const cacheRead = sum(rows, 'cacheRead') + const cacheWrite = sum(rows, 'cacheWrite') + const output = sum(rows, 'output') + const prompts = rows.map(promptOf).sort((a, b) => a - b) + const prompt = input + cacheRead + cacheWrite + return { + calls: rows.length, + input, + cacheRead, + cacheWrite, + output, + prompt, + promptPerCall: { + p50: percentile(prompts, 50), + p90: percentile(prompts, 90), + p99: percentile(prompts, 99), + max: prompts.length === 0 ? 0 : prompts[prompts.length - 1], + }, + cacheReadShare: prompt === 0 ? 0 : cacheRead / prompt, + } +} + +// A Session's calls are appended, so the prompt difference between one call and the next +// is what that turn added. A smaller prompt means a compaction, a checkpoint or a new part: +// the turn after it does not grow the old prompt, so that crossing starts a new run and is +// not a delta. Reported deltas are therefore comparable, and the boundaries are counted. +function growthOf(rows) { + let previous = null + let resets = 0 + const points = [] + const deltas = [] + for (const row of rows) { + const prompt = promptOf(row) + let delta = previous === null ? null : prompt - previous + if (delta !== null && delta < 0) { delta = null; resets += 1 } + points.push({ time: row.time, prompt, delta }) + if (delta !== null) deltas.push(delta) + previous = prompt + } + deltas.sort((a, b) => a - b) + return { + points, + deltas: { + count: deltas.length, + median: percentile(deltas, 50), + p90: percentile(deltas, 90), + resets, + }, + } +} + +function groupBy(rows, key) { + const groups = new Map() + for (const row of rows) { + const name = key(row) + const group = groups.get(name) ?? [] + group.push(row) + groups.set(name, group) + } + return groups +} + +const dayKey = tz => (time) => { + const local = localParts(tz, time) + return `${local.year}-${String(local.month).padStart(2, '0')}-${String(local.day).padStart(2, '0')}` +} + +export function buildReport(rows, { db, from, to, tz }) { + const bots = [...groupBy(rows, row => row.bot ?? row.session)] + .map(([bot, group]) => ({ bot, ...totals(group) })) + .sort((a, b) => b.prompt - a.prompt) + const sessions = [...groupBy(rows, row => row.session)] + .map(([session, group]) => { + const sorted = [...group].sort((a, b) => a.time - b.time) + const growth = growthOf(sorted) + return { + session, + bot: sorted[0].bot ?? session, + first: sorted[0].time, + last: sorted[sorted.length - 1].time, + ...totals(sorted), + growth: growth.deltas, + points: growth.points, + } + }) + .sort((a, b) => b.prompt - a.prompt) + const days = [...groupBy(rows, row => dayKey(tz)(row.time))] + .map(([day, group]) => ({ day, ...totals(group) })) + .sort((a, b) => a.day.localeCompare(b.day)) + const pooled = sessions.flatMap(session => session.points).map(point => point.delta).filter(delta => delta !== null).sort((a, b) => a - b) + return { + db, from, to, tz, ...totals(rows), bots, sessions, days, + growthAll: { count: pooled.length, median: percentile(pooled, 50), p90: percentile(pooled, 90), resets: sessions.reduce((total, session) => total + session.growth.resets, 0) }, + } +} + +// --------------------------------------------------------------------------- +// Printing. + +function table(title, columns, rows) { + const cells = rows.map(row => columns.map(column => String(column.value(row)))) + const widths = columns.map((column, index) => Math.max(column.label.length, ...cells.map(row => row[index].length))) + const line = values => values.map((value, index) => (columns[index].right ? value.padStart(widths[index]) : value.padEnd(widths[index]))).join(' ').trimEnd() + const out = [title, '', line(columns.map(column => column.label)), line(widths.map(width => '-'.repeat(width)))] + for (const row of cells) out.push(line(row)) + return out.join('\n') +} + +const pct = share => `${(share * 100).toFixed(1)}%` +const utc = time => new Date(time).toISOString().replace('.000Z', 'Z') + +function printText(report) { + const window = `${report.from === null ? 'start' : utc(report.from)} .. ${report.to === null ? 'end' : utc(report.to)}` + console.log(`ledger: ${report.db}`) + console.log(`window: ${window} (days in ${report.tz})`) + console.log(`calls: ${report.calls}`) + console.log('') + console.log(table('per Bot', [ + { label: 'bot', value: row => row.bot }, + { label: 'calls', value: row => row.calls, right: true }, + { label: 'fresh input', value: row => row.input, right: true }, + { label: 'cache read', value: row => row.cacheRead, right: true }, + { label: 'cache write', value: row => row.cacheWrite, right: true }, + { label: 'output', value: row => row.output, right: true }, + { label: 'prompt', value: row => row.prompt, right: true }, + { label: 'cache read share', value: row => pct(row.cacheReadShare), right: true }, + ], report.bots)) + console.log('') + console.log('per call prompt (fresh input + cache read + cache write, nearest-rank)') + console.log(` all calls: p50 ${report.promptPerCall.p50} p90 ${report.promptPerCall.p90} p99 ${report.promptPerCall.p99} max ${report.promptPerCall.max}`) + console.log('') + const top = report.sessions.slice(0, Math.max(0, report.top)) + if (top.length > 0) { + console.log(table('top Sessions by prompt', [ + { label: 'session', value: row => row.session }, + { label: 'bot', value: row => row.bot }, + { label: 'calls', value: row => row.calls, right: true }, + { label: 'prompt', value: row => row.prompt, right: true }, + { label: 'fresh input', value: row => row.input, right: true }, + { label: 'cache read', value: row => row.cacheRead, right: true }, + ], top)) + console.log('') + } + if (report.days.length > 0) { + console.log(table(`per day (${report.tz})`, [ + { label: 'day', value: row => row.day }, + { label: 'calls', value: row => row.calls, right: true }, + { label: 'fresh input', value: row => row.input, right: true }, + { label: 'cache read', value: row => row.cacheRead, right: true }, + { label: 'cache write', value: row => row.cacheWrite, right: true }, + { label: 'output', value: row => row.output, right: true }, + { label: 'prompt', value: row => row.prompt, right: true }, + ], report.days)) + console.log('') + } + const growth = report.sessions.slice(0, Math.max(0, report.growth)) + for (const session of growth) { + const rows = session.points.map((point, index) => ({ + index, + time: utc(point.time), + prompt: point.prompt, + delta: point.delta === null ? '(first or compaction)' : `+${point.delta}`, + })) + console.log(table(`prompt growth: ${session.session} (${session.bot}) — median delta ${session.growth.median}, p90 ${session.growth.p90}, ${session.growth.resets} compaction boundary(ies)`, [ + { label: 'call', value: row => row.index, right: true }, + { label: 'time', value: row => row.time }, + { label: 'prompt', value: row => row.prompt, right: true }, + { label: 'delta', value: row => row.delta, right: true }, + ], rows)) + console.log('') + } +} + +function main() { + const flags = parseArgs(process.argv.slice(2)) + const dbPath = flags.db ?? join(process.env.DSH_HOME ?? join(homedir(), '.dsh'), 'usage.sqlite') + if (!existsSync(dbPath)) die(`no ledger at ${dbPath} (pass --db )`) + const from = flags.from === null ? null : parseInstant(flags.from, flags.tz, false) + const to = flags.to === null ? null : parseInstant(flags.to, flags.tz, true) + if (from !== null && to !== null && from > to) die(`--from is after --to`) + const rows = readRows(dbPath, { from, to, bot: flags.bot }) + const report = { ...buildReport(rows, { db: dbPath, from, to, tz: flags.tz }), top: flags.top, growth: flags.growth } + if (flags.json) { + const sessions = report.sessions.map(({ points, ...session }) => session) + console.log(JSON.stringify({ ...report, sessions }, null, 2)) + return + } + printText(report) +} + +if (process.argv[1] !== undefined && import.meta.url === pathToFileURL(resolve(process.argv[1])).href) main() diff --git a/patches/ds-bot/files/test/token-report.test.js b/patches/ds-bot/files/test/token-report.test.js new file mode 100644 index 000000000..59fdcf848 --- /dev/null +++ b/patches/ds-bot/files/test/token-report.test.js @@ -0,0 +1,204 @@ +import assert from 'node:assert/strict' +import { spawnSync } from 'node:child_process' +import { mkdtempSync, readFileSync, rmSync } from 'node:fs' +import { tmpdir } from 'node:os' +import { dirname, join } from 'node:path' +import { DatabaseSync } from 'node:sqlite' +import { test } from 'node:test' +import { fileURLToPath } from 'node:url' + +const ROOT = join(dirname(fileURLToPath(import.meta.url)), '..', '..') +const SCRIPT = join(ROOT, 'core', 'dev', 'token-report.mjs') +const REPORT = join(ROOT, 'docs', 'reports', '2026-10-23-token-spend.md') + +const at = minutes => Date.UTC(2026, 9, 20, 10, minutes) + +// The ledger's schema as src/host/usage.js creates it. One Bot with a cache-read-heavy +// turn, a Bot with none, and a third Session with no owners row. +const calls = [ + // session-dev, owned by Dev: three turns, then a compaction shrinks the prompt. + ['session-dev', at(0), 'turn', 100, 1000, 10, 5], + ['session-dev', at(1), 'turn', 200, 1000, 0, 7], + ['session-dev', at(2), 'turn', 50, 900, 0, 9], + ['session-dev', at(3), 'turn', 5, 0, 0, 2], + // session-reviewer, owned by Reviewer: no cache reads at all. + ['session-reviewer', at(0), 'turn', 10, 0, 0, 3], + // session-unowned: no owners row, so it must appear under its Session id. + ['session-unowned', at(0), 'turn', 7, 30, 1, 2], +] +const owners = [ + ['session-dev', 'session-dev', 'Dev'], + ['session-reviewer', 'session-reviewer', 'Reviewer'], +] + +function fixture(extra = []) { + const dir = mkdtempSync(join(tmpdir(), 'token-report-')) + const path = join(dir, 'usage.sqlite') + const db = new DatabaseSync(path) + try { + db.exec(` + CREATE TABLE calls (key TEXT PRIMARY KEY, session TEXT NOT NULL, time INTEGER NOT NULL, provider TEXT NOT NULL, model TEXT NOT NULL, kind TEXT NOT NULL, live INTEGER NOT NULL, input INTEGER NOT NULL, cache_read INTEGER NOT NULL, cache_write INTEGER NOT NULL, output INTEGER NOT NULL); + CREATE TABLE owners (session TEXT PRIMARY KEY, owner TEXT NOT NULL, name TEXT NOT NULL);`) + const put = db.prepare('INSERT INTO calls (key, session, time, provider, model, kind, live, input, cache_read, cache_write, output) VALUES (?, ?, ?, ?, ?, ?, 0, ?, ?, ?, ?)') + for (const [index, [session, time, kind, input, cacheRead, cacheWrite, output]] of [...calls, ...extra].entries()) { + put.run(`${session}:${index}`, session, time, 'test', 'test-model', kind, input, cacheRead, cacheWrite, output) + } + const owner = db.prepare('INSERT INTO owners (session, owner, name) VALUES (?, ?, ?)') + for (const row of owners) owner.run(...row) + } finally { + db.close() + } + return { path, dir } +} + +function run(path, ...args) { + const result = spawnSync(process.execPath, [SCRIPT, '--db', path, ...args], { encoding: 'utf8' }) + return result +} + +test('the report matches hand-computed sums, with cache reads kept apart', () => { + const { path, dir } = fixture() + try { + const result = run(path, '--json', '--tz', 'UTC') + assert.equal(result.status, 0, result.stderr) + const report = JSON.parse(result.stdout) + assert.equal(report.calls, 6) + assert.deepEqual( + { input: report.input, cacheRead: report.cacheRead, cacheWrite: report.cacheWrite, output: report.output, prompt: report.prompt }, + { input: 372, cacheRead: 2930, cacheWrite: 11, output: 28, prompt: 3313 }, + ) + // 5, 10, 38, 950, 1110, 1200 — nearest rank. + assert.deepEqual(report.promptPerCall, { p50: 38, p90: 1200, p99: 1200, max: 1200 }) + + const dev = report.bots.find(row => row.bot === 'Dev') + assert.deepEqual( + { calls: dev.calls, input: dev.input, cacheRead: dev.cacheRead, cacheWrite: dev.cacheWrite, output: dev.output, prompt: dev.prompt }, + { calls: 4, input: 355, cacheRead: 2900, cacheWrite: 10, output: 23, prompt: 3265 }, + ) + // Cache reads are never folded into fresh input: the two columns stay the numbers above. + assert.equal(dev.input, 355) + assert.equal(dev.cacheRead, 2900) + assert.equal(dev.input + dev.cacheRead + dev.cacheWrite, dev.prompt) + + // An unowned Session appears under its Session id, not dropped. + const unowned = report.bots.find(row => row.bot === 'session-unowned') + assert.deepEqual({ input: unowned.input, cacheRead: unowned.cacheRead, prompt: unowned.prompt }, { input: 7, cacheRead: 30, prompt: 38 }) + + const day = report.days.find(row => row.day === '2026-10-20') + assert.equal(day.calls, 6) + + // Growth is measured between comparable calls: the compaction (1110 → 5) starts a + // new run instead of contributing a large negative delta. + const session = report.sessions.find(row => row.session === 'session-dev') + assert.deepEqual(session.growth, { count: 1, median: 90, p90: 90, resets: 2 }) + assert.equal(report.growthAll.resets, 2) + } finally { + rmSync(dir, { recursive: true, force: true }) + } +}) + +test('the window, the Bot filter and a missing ledger', () => { + const { path, dir } = fixture() + try { + const windowed = run(path, '--json', '--tz', 'UTC', '--from', '2026-10-20T10:01', '--to', '2026-10-20T10:02') + assert.equal(windowed.status, 0, windowed.stderr) + const window = JSON.parse(windowed.stdout) + assert.equal(window.calls, 2) + assert.equal(window.input, 250) + + const byName = JSON.parse(run(path, '--json', '--bot', 'dev').stdout) + assert.equal(byName.calls, 4) + const bySession = JSON.parse(run(path, '--json', '--bot', 'session-uno').stdout) + assert.equal(bySession.calls, 1) + + const missing = join(dir, 'nope.sqlite') + const absent = run(missing) + assert.notEqual(absent.status, 0) + assert.match(absent.stderr, new RegExp(`no ledger at ${missing.replace(/[.*+?^${}()|[\]\\]/g, '\\$&')}`)) + + const badDate = run(path, '--from', 'yesterday') + assert.notEqual(badDate.status, 0) + assert.match(badDate.stderr, /cannot read "yesterday" as a date/) + + const backwards = run(path, '--from', '2026-10-21', '--to', '2026-10-20') + assert.notEqual(backwards.status, 0) + } finally { + rmSync(dir, { recursive: true, force: true }) + } +}) + +test('an impossible date is an error, never an empty report', () => { + const { path, dir } = fixture() + try { + // Each of these used to reach Date.parse or Date.UTC and come back NaN or normalised, + // which printed "calls 0" and exited 0 — the one thing this report must never do. + for (const [flag, value] of [ + ['--from', '2026-13-01Z'], + ['--from', '2026-02-31'], + ['--to', '2026-02-31'], + ['--from', '2026-11-02T10:00+99:00'], + ['--to', '2026-01-01T24:00'], + ]) { + const result = run(path, flag, value) + assert.notEqual(result.status, 0, `${flag} ${value} exited 0`) + assert.match(result.stderr, /cannot read .* as a date/, `${flag} ${value}: ${result.stderr}`) + assert.equal(result.stdout, '', `${flag} ${value} printed a report`) + } + const valid = run(path, '--json', '--from', '2026-02-28', '--to', '2026-03-01') + assert.equal(valid.status, 0, valid.stderr) + } finally { + rmSync(dir, { recursive: true, force: true }) + } +}) + +test('a day a zone falls back is 25 hours, and --to covers all of it', () => { + // 2025-11-02 in America/New_York is 25 hours: it starts at 04:00Z (EDT) and ends at + // 05:00Z the next day (EST). 15:00Z is 10:00 EST, after the fall-back at 06:00Z. + const { path, dir } = fixture([ + ['session-dst', Date.parse('2025-11-02T15:00:00Z'), 'turn', 10, 0, 0, 1], + ['session-dst', Date.parse('2025-11-02T17:30:00Z'), 'turn', 10, 0, 0, 1], + ]) + try { + const day = JSON.parse(run(path, '--json', '--tz', 'America/New_York', '--from', '2025-11-02', '--to', '2025-11-02').stdout) + // The bound itself, not just "the two values differ": local 23:59:59.999 on the 2nd. + assert.equal(day.to, 1762145999999) + assert.equal(new Date(day.to).toISOString(), '2025-11-03T04:59:59.999Z') + assert.equal(day.calls, 2) + assert.deepEqual(day.days.map(row => [row.day, row.calls]), [['2025-11-02', 2]]) + + // The day before it ends 25 hours earlier, and holds none of them. + const earlier = JSON.parse(run(path, '--json', '--tz', 'America/New_York', '--to', '2025-11-01').stdout) + assert.equal(earlier.to, 1762055999999) + assert.equal(earlier.to - day.to, -90_000_000) + assert.equal(earlier.calls, 0) + + // And a bare --to on a normal day still ends at that day's last millisecond. + const ordinary = JSON.parse(run(path, '--json', '--tz', 'UTC', '--from', '2026-10-20', '--to', '2026-10-20').stdout) + assert.equal(ordinary.calls, 6) + } finally { + rmSync(dir, { recursive: true, force: true }) + } +}) + +// Every number in the committed report is a table row whose last cell names where it came +// from: the ledger, a formula over the ledger, or that it was not measured. +const PROVENANCE = /^(ledger|derived: .+|not measured)$/ + +test('every row of the committed report carries its provenance', () => { + const lines = readFileSync(REPORT, 'utf8').split(/\r?\n/) + const rows = [] + let header = null + for (const line of lines) { + const cells = line.startsWith('|') ? line.split('|').slice(1, -1).map(cell => cell.trim()) : null + if (cells === null) { header = null; continue } + if (header === null) { header = cells; continue } + if (cells.every(cell => /^:?-{3,}:?$/.test(cell))) continue + assert.equal(header.at(-1), 'Source', `a table starting with ${header[0]} has no Source column`) + rows.push({ header, cells }) + } + assert.ok(rows.length > 0, 'the report has no tables') + for (const row of rows) { + assert.match(row.cells.at(-1), PROVENANCE, `no provenance: | ${row.cells.join(' | ')} |`) + assert.equal(row.cells.length, row.header.length, `a row has ${row.cells.length} cells, its table ${row.header.length}: | ${row.cells.join(' | ')} |`) + } +})