Oregami
Repositories/oxedyne/daimond

oxedyne/daimond/dev/probe_latency.mjs

12.9 KiB, 1 run

created by r2519314175:51, which is this file's identity for as long as the history lasts, whatever it is later renamed to

download · who wrote it · its history

1// Where an agentic turn's wall clock actually goes, measured in the browser.
2//
3// The question this answers is the owner's: models that are fast elsewhere feel
4// slow in Daimond on tool-using work. That is a comparison, so what is wanted is
5// a number per STAGE per ROUND, not a list of things that could be slow.
6//
7// node dev/probe_latency.mjs [--rounds 12] [--tool file_list] [--wide 1] [--size 2048]
8//
9// Three instruments, none of which changes the engine:
10//
11// the FETCH clock. `window.fetch` is wrapped before the app loads, and the
12// response body is handed back through a proxy stream, so the moment each SSE
13// chunk reaches the page is recorded as well as the request's size and when it
14// went out. That is request-sent, first-byte and last-byte, per round.
15//
16// the EVENT clock. `DaimondApp.prototype.run_turn` is wrapped, so every
17// `AgentEvent` the engine emits is stamped as it crosses out of the wasm. Tool
18// dispatch is the gap between `tool_call` and `tool_result`; the wasm's own work
19// is what is left over when the fetch and the tools are taken out.
20//
21// the PROVIDER log. dev/latmock.mjs writes one line per request with the body
22// size, the bytes per role and the schema array, so prompt growth is measured
23// from what was SENT rather than estimated from the transcript.
24//
25// The mock's own latency defaults to zero, so a run measures what Daimond adds.
26
27import fs from 'node:fs';
28import path from 'node:path';
29import { spawn } from 'node:child_process';
30import { fileURLToPath } from 'node:url';
31import { open, newChat, connectMock, scratch } from './harness.mjs';
32
33const HERE = path.dirname(fileURLToPath(import.meta.url));
34
35const arg = (name, dflt) => {
36 const i = process.argv.indexOf('--' + name);
37 return i === -1 ? dflt : process.argv[i + 1];
38};
39const ROUNDS = Number(arg('rounds', 12));
40const TOOL = String(arg('tool', 'file_list'));
41const WIDE = Number(arg('wide', 1));
42const SIZE = Number(arg('size', 2048));
43const LABEL = String(arg('label', `${TOOL}-r${ROUNDS}-w${WIDE}`));
44// A REAL model, at a real provider, driven by a real task. The mock says what
45// Daimond's own overhead is; only this says what the whole thing costs, and the
46// two together say which of them the user is waiting on.
47const REAL = arg('real', '');
48const TASK = String(arg('task',
49 'Read each of these twelve files with file_read, one call per file, and reply with the total '
50 + 'number of characters across all of them. Read them one at a time, waiting for each result '
51 + 'before asking for the next. The files are '
52 + '%DIR%/f0.txt %DIR%/f1.txt %DIR%/f2.txt %DIR%/f3.txt %DIR%/f4.txt %DIR%/f5.txt '
53 + '%DIR%/f6.txt %DIR%/f7.txt %DIR%/f8.txt %DIR%/f9.txt %DIR%/f10.txt %DIR%/f11.txt'));
54const KEY = process.env.OPENROUTER_API_KEY || '';
55const REALURL = String(arg('realurl', 'https://openrouter.ai/api/v1/chat/completions'));
56const PORT = Number(process.env.LAT_PORT || 9906);
57const LOG = path.join(HERE, `latmock-${LABEL}.log`);
58const OUT = path.join(HERE, `latency-${LABEL}.json`);
59
60const log = (...a) => console.log(...a);
61
62// ── the provider fixture ────────────────────────────────────────────────
63try { fs.unlinkSync(LOG); } catch {}
64const mock = spawn(process.execPath, [path.join(HERE, 'latmock.mjs'), String(PORT), LOG], {
65 stdio: ['ignore', 'inherit', 'inherit'],
66 env: { ...process.env, LAT_KEEP_BODY: process.env.LAT_KEEP_BODY || '' },
67});
68const stop = () => { try { mock.kill('SIGTERM'); } catch {} };
69process.on('exit', stop);
70await new Promise(r => setTimeout(r, 500));
71
72// ── the page ────────────────────────────────────────────────────────────
73const s = await open({
74 name: 'lat',
75 // Before navigation, which is the only moment `fetch` can be wrapped ahead of
76 // the app: the engine takes its own reference to it when the module loads.
77 route: async (page) => {
78 await page.addInitScript(() => {
79 window.__lat = { fetches: [], events: [], t0: performance.now() };
80 const real = window.fetch.bind(window);
81 window.fetch = async function (input, init) {
82 const url = typeof input === 'string' ? input : (input && input.url) || '';
83 if (!/chat\/completions|v1\/messages/.test(url)) return real(input, init);
84 const body = (init && init.body) || (input && input.body) || '';
85 const rec = {
86 sent: performance.now(),
87 bytes: typeof body === 'string' ? new TextEncoder().encode(body).length : 0,
88 // A `Request` carries its body as a stream, so the size is taken from a
89 // clone and lands a tick later. Not awaited: the request must not wait
90 // on the instrument.
91
92 first: 0, last: 0, chunks: 0, bytesIn: 0,
93 };
94 window.__lat.fetches.push(rec);
95 if (!rec.bytes && input && typeof input.clone === 'function') {
96 try { input.clone().arrayBuffer().then(b => { rec.bytes = b.byteLength; }); }
97 catch (e) {}
98 }
99 const resp = await real(input, init);
100 rec.head = performance.now();
101 if (!resp.body) { rec.first = rec.last = rec.head; return resp; }
102 // The body is handed on through a proxy, so each chunk is stamped as
103 // it reaches the page rather than as the engine gets round to it.
104 const reader = resp.body.getReader();
105 const proxied = new ReadableStream({
106 async pull(ctrl) {
107 const { done, value } = await reader.read();
108 if (done) { rec.last = performance.now(); ctrl.close(); return; }
109 if (!rec.first) rec.first = performance.now();
110 rec.chunks += 1;
111 rec.bytesIn += value.byteLength;
112 ctrl.enqueue(value);
113 },
114 cancel(r) { try { reader.cancel(r); } catch (e) {} },
115 });
116 return new Response(proxied, {
117 status: resp.status, statusText: resp.statusText, headers: resp.headers,
118 });
119 };
120 });
121 },
122});
123
124if (REAL && !KEY) { console.error('--real needs OPENROUTER_API_KEY in the environment.'); process.exit(2); }
125await connectMock(s, REAL
126 ? { baseUrl: REALURL, model: REAL, apiKey: KEY }
127 : { baseUrl: `http://127.0.0.1:${PORT}/v1/chat/completions`, model: 'lat/fast' });
128await newChat(s);
129
130// The event clock, installed on the module the page has already loaded. Wrapped
131// here rather than in the init script because the wasm module is imported by the
132// app, and its class only exists once that import has resolved.
133await s.page.evaluate(async () => {
134 const m = await import('/pkg/oxedyne_daimond.js');
135 const proto = m.DaimondApp.prototype;
136 if (proto.__latWrapped) return;
137 proto.__latWrapped = true;
138 const inner = proto.run_turn;
139 proto.run_turn = function (msg, onEvent) {
140 window.__lat.turnStart = performance.now();
141 const sink = function (ev) {
142 try {
143 window.__lat.events.push({
144 t: performance.now(),
145 type: (ev && ev.type) || '',
146 name: (ev && ev.name) || '',
147 // The SIZE of what crossed, never the content: a result may be a
148 // file the user owns and this file is read by a person.
149 n: (ev && ev.content) ? String(ev.content).length : 0,
150 });
151 } catch (e) {}
152 // Stamped again after the page's own handler, so the cost of the page's
153 // rendering and journalling is separable from the engine's.
154 const r = onEvent(ev);
155 try {
156 const last = window.__lat.events[window.__lat.events.length - 1];
157 if (last) last.done = performance.now();
158 } catch (e) {}
159 return r;
160 };
161 return inner.call(this, msg, sink);
162 };
163});
164
165// ── the fixture files ───────────────────────────────────────────────────
166//
167// Written straight into OPFS rather than through a turn: seeding through the tool
168// loop is the very thing being measured, and twelve seeding turns would be twelve
169// turns of noise in the log.
170const SCRATCHDIR = await s.page.evaluate(async ({ size }) => {
171 const f = window.DaimondAttach.focus();
172 const dir = window.DaimondAttach.chatScratch(f.id);
173 const parts = dir.split('/');
174 let d = await navigator.storage.getDirectory();
175 for (const seg of parts) d = await d.getDirectoryHandle(seg, { create: true });
176 for (let i = 0; i < 12; i++) {
177 const h = await d.getFileHandle(`f${i}.txt`, { create: true });
178 const w = await h.createWritable();
179 await w.write('x'.repeat(size));
180 await w.close();
181 }
182 return dir;
183}, { size: SIZE });
184log(`seeded 12 files of ${SIZE} B in ${SCRATCHDIR}`);
185
186// ── the turn ────────────────────────────────────────────────────────────
187const spec = TOOL === 'file_list'
188 ? `file_list {"path":"${SCRATCHDIR}"}`
189 : `file_read {"path":"${SCRATCHDIR}/f%.txt"}`;
190// `%DIR%` is the chat's own scratch folder, which is the only place a chat may
191// write and the only place the fixture files can be. A task naming a bare
192// filename is refused by the fence before the tool runs, and the turn then
193// measures an apology rather than twelve reads.
194const directive = REAL ? TASK.replace(/%DIR%/g, SCRATCHDIR) : (WIDE > 1
195 ? `@latp ${ROUNDS} ${WIDE} ${spec}`
196 : `@lat ${ROUNDS} ${spec}`);
197log(`turn: ${directive}`);
198
199await s.page.fill('#chat-input', directive);
200const wall0 = Date.now();
201await s.page.click('#chat-send', { force: true });
202
203// Wait for the turn to finish: the send button stops offering Stop.
204const deadline = Date.now() + (REAL ? 600000 : 180000);
205while (Date.now() < deadline) {
206 const busy = await s.page.evaluate(() => {
207 const b = document.getElementById('chat-send');
208 if (!b) return false;
209 const t = (b.getAttribute('title') || '') + (b.className || '');
210 return /stop/i.test(t) || b.disabled;
211 });
212 if (!busy) break;
213 await s.page.waitForTimeout(120);
214}
215const wall = Date.now() - wall0;
216await s.page.waitForTimeout(600);
217
218const seen = await s.page.evaluate(() => window.__lat);
219await s.close();
220stop();
221
222// ── the report ──────────────────────────────────────────────────────────
223const provider = fs.existsSync(LOG)
224 ? fs.readFileSync(LOG, 'utf8').trim().split('\n').filter(Boolean).map(l => JSON.parse(l))
225 : [];
226
227const evs = seen.events || [];
228const fetches = seen.fetches || [];
229const rounds = [];
230for (let i = 0; i < fetches.length; i++) {
231 const f = fetches[i];
232 const nxt = fetches[i + 1];
233 const end = nxt ? nxt.sent : (f.last || f.head);
234 // The tool calls of this round: everything between this round's last byte and
235 // the next request going out.
236 // From THIS request going out to the next one, which is the whole round: a
237 // `tool_call` is emitted while the stream reader still has a `done` to
238 // collect, so a window opening at the last byte misses every call.
239 const win = evs.filter(e => e.t >= f.sent && e.t <= end);
240 let tools = 0, dispatch = [];
241 for (let k = 0; k < win.length; k++) {
242 if (win[k].type === 'tool_call') {
243 const done = win.slice(k + 1).find(e => e.type === 'tool_result');
244 if (done) { tools += done.t - win[k].t; dispatch.push({ name: win[k].name, ms: done.t - win[k].t, out: done.n }); }
245 }
246 }
247 const p = provider[i] || {};
248 rounds.push({
249 round: i + 1,
250 reqBytes: p.bodyB || f.bytes,
251 promptTok: Math.round((p.bodyB || f.bytes) / 4),
252 msgs: p.msgs || 0,
253 roleB: p.roleB || {},
254 toolsB: p.toolsB || 0,
255 ttfbMs: +( (f.first || f.head) - f.sent ).toFixed(1),
256 streamMs: +( (f.last || f.head) - (f.first || f.head) ).toFixed(1),
257 toolMs: +tools.toFixed(1),
258 // What the round cost that was neither the provider nor a tool: the wasm's
259 // own work, the page's rendering and the journal's writes.
260 gapMs: nxt ? +(nxt.sent - f.sent - ((f.first || f.head) - f.sent)
261 - ((f.last || f.head) - (f.first || f.head)) - tools).toFixed(1) : null,
262 roundMs: +(end - f.sent).toFixed(1),
263 dispatch,
264 });
265}
266
267const sum = (k) => rounds.reduce((a, r) => a + (r[k] || 0), 0);
268const report = {
269 label: LABEL, tool: TOOL, wide: WIDE, rounds: ROUNDS, fixtureBytes: SIZE, model: REAL || 'lat/fast',
270 wallMs: wall,
271 totals: {
272 ttfb: +sum('ttfbMs').toFixed(1),
273 stream: +sum('streamMs').toFixed(1),
274 tools: +sum('toolMs').toFixed(1),
275 gap: +rounds.reduce((a, r) => a + (r.gapMs || 0), 0).toFixed(1),
276 },
277 rounds,
278 events: evs,
279 fetches,
280};
281fs.writeFileSync(OUT, JSON.stringify(report, null, 1));
282
283log('');
284log(`round reqKB promptTok msgs ttfb stream tools gap round`);
285for (const r of rounds) {
286 log([
287 String(r.round).padStart(5),
288 (r.reqBytes / 1024).toFixed(1).padStart(7),
289 String(r.promptTok).padStart(10),
290 String(r.msgs).padStart(6),
291 r.ttfbMs.toFixed(0).padStart(6),
292 r.streamMs.toFixed(0).padStart(8),
293 r.toolMs.toFixed(0).padStart(7),
294 (r.gapMs == null ? '-' : r.gapMs.toFixed(0)).padStart(7),
295 r.roundMs.toFixed(0).padStart(8),
296 ].join(''));
297}
298log('');
299log(`wall ${wall} ms; ttfb ${report.totals.ttfb} ms, stream ${report.totals.stream} ms, ` +
300 `tools ${report.totals.tools} ms, gap ${report.totals.gap} ms`);
301log(`written ${OUT}`);
302log(`provider log ${LOG}`);