--- title: 'Metrics and Slow Command Analysis' source: 'https://academia.sh/en/courses/in-memory-stores/metrics-and-slow-command-analysis' course: 'In-Memory Stores and Caching Systems' language: en updated: '2026-08-23T07:00:43+00:00' license: 'CC BY-SA 4.0' --- # Metrics and Slow Command Analysis Performance diagnosis for a single-threaded in-memory store: counting the number of requests waiting behind one long-running command and the total delay, what splitting a scan by cursor gains and what it misses, and sweeping the slow command log's threshold. All four of the previous lesson's memory accountings leaned on a silent assumption: every access happens the moment its turn comes, no request waits on another. In most in-memory stores, that assumption breaks in a particular way, because commands are processed in order on a single thread. That order is what makes atomicity free: two commands never interleave, no lock is needed. The same order also brings a trap. However long a command takes, every request behind it waits that long. In a disk-based database, a slow query delays its own client; here it delays **every** client. This lesson counts that delay. ## What Waits Behind a Long Command The mechanism is single-queued and single-threaded. Requests arrive once every two work units, an ordinary command takes one unit; the load runs at half capacity (**CU15**). At one point, a maintenance command that scans the entire catalog cache interrupts, bringing 4,000 units of work in total. The same work is given once as a single command, then as commands split into parts. Total work is identical in every row. ```js // single-thread.mjs — single-threaded store: requests waiting behind a long command are counted const ARRIVAL = 2, REQUESTS = 3000, SCAN_START = 2000; // one request every 2 units, command cost 1 unit function run(totalWork, parts) { // scan work is split into `parts` commands const partCost = parts ? totalWork / parts : 0; const queue = []; // single queue, single thread, in order let arrived = 0, remainingParts = parts, scanArrival = parts ? SCAN_START : -1; let running = null, finishAt = 0; let waiting = 0, longest = 0, totalWaiting = 0, scanEnd = 0, processed = 0; for (let t = 0; processed < REQUESTS + parts && t < 200000; t += 1) { if (running && finishAt === t) { // 1) the running command finished if (running.scan) { scanEnd = t; if (remainingParts > 0) scanArrival = t; } running = null; processed += 1; } while (arrived < REQUESTS && (arrived + 1) * ARRIVAL === t) { // 2) normal request arrival queue.push({ arrival: t, cost: 1, scan: false }); arrived += 1; } if (remainingParts > 0 && scanArrival === t) { // scan part: the first by schedule, the rest queue.push({ arrival: t, cost: partCost, scan: true }); // when the previous one finishes remainingParts -= 1; scanArrival = -1; } if (running === null && queue.length > 0) { // 3) the first waiting command is taken running = queue.shift(); const w = t - running.arrival; if (w > 0) { waiting += 1; totalWaiting += w; longest = Math.max(longest, w); } finishAt = t + running.cost; } } return { partCost, waiting, longest, totalWaiting, scanEnd }; } console.log(`workload: ${REQUESTS} requests, one arrival every ${ARRIVAL} units, command cost 1 unit`); console.log(["scan", "part cost", "waiting requests", "longest wait", "total waiting", "scan end"].map((h, i) => (i === 0 ? h.padEnd(18) : h.padStart(18))).join("")); for (const [name, total, parts] of [ ["no scan", 0, 0], ["single command (4000)", 4000, 1], ["10 parts", 4000, 10], ["40 parts", 4000, 40], ["200 parts", 4000, 200], ]) { const r = run(total, parts); console.log(name.padEnd(18) + [r.partCost, r.waiting, r.longest, r.totalWaiting, r.scanEnd] .map((n) => String(n).padStart(18)).join("")); } ``` ``` workload: 3000 requests, one arrival every 2 units, command cost 1 unit scan part cost waiting requests longest wait total waiting scan end no scan 0 0 0 0 0 single command (4000) 4000 2001 3999 5999001 6001 10 parts 400 2007 786 1045801 8001 40 parts 100 2022 198 289501 8001 200 parts 20 2102 38 58681 8001 ``` The first row is the measurement's zero point: with no scan, no request waits, because the arrival rate is half the service rate. In the second row, a single command runs for 4,000 units, and 2,001 requests pile up behind it. The longest wait is 3,999 units; that is, a request that enters the queue right after the scan waits nearly four thousand units even though its own work takes one unit. Total waiting is 5,999,001 units. In the rows below, that same 4,000-unit job gets split into parts. When part cost drops from 4,000 to 400, the longest wait drops from 3,999 to 786, total waiting from 5,999,001 to 1,045,801. At 200 parts, the longest wait is 38 units, total waiting 58,681: less than one percent. Not a single unit of work went away; it only became **splittable**. The last column shows the cost. In the single command, the scan finishes at unit 6,001; split, at unit 8,001. A split scan gives up its own finish time to buy down everyone else's waiting. In a single-threaded store, this trade-off gets made anew for every long job: when the scan finishes usually concerns no one, the three thousand requests waiting in between concern everyone. ## What a Cursor Scan Misses Splitting is not free, and its cost is not only a delayed finish. A single command runs the entire scan while holding the thread, so it sees an unchanging snapshot of the key space. A cursor-driven scan gives up the thread between parts, and the key space changes in those gaps. The run below measures this on a 200,000-entry key space; after every part, two books get loaned out and their cache entries deleted. ```js // cursor-scan.mjs — same scan: as a single block, or cursor by cursor function keySpace(count) { // key list that preserves insertion order const store = new Map(); const keys = []; for (let i = 1; i <= count; i += 1) { const a = `book:${i}`; store.set(a, { shelf: i % 5, branch: (i % 3) + 1 }); keys.push(a); } return { store, keys }; } const COUNT = 200000, PART = 1000, DELETIONS = 2; // 2 deletions per part (books loaned out) function singleBlock() { // the command holds the thread start to finish const { store, keys } = keySpace(COUNT); let seen = 0, matched = 0; for (const a of keys) { seen += 1; if (store.get(a).shelf === 0) matched += 1; } return { name: "single block", longestBlock: seen, seen, matched, commands: 1, missed: 0 }; } function cursorScan() { // each part is its own command; others run in between const { store, keys } = keySpace(COUNT); const visited = new Set(); let p = 0, seen = 0, matched = 0, commands = 0, deleted = 0; while (p < keys.length) { const end = Math.min(p + PART, keys.length); for (let i = p; i < end; i += 1) { // this part's work const a = keys[i]; visited.add(a); seen += 1; if (store.get(a).shelf === 0) matched += 1; } p = end; commands += 1; for (let d = 0; d < DELETIONS && p < keys.length; d += 1) { // deletions happen between parts const pos = (deleted * 977) % p; // a key is deleted just ahead of the cursor store.delete(keys[pos]); keys.splice(pos, 1); // the list shifts: the cursor's entry gets skipped deleted += 1; } } const missed = keys.filter((a) => !visited.has(a)).length; // survived to the end but never seen return { name: `cursor (${PART})`, longestBlock: PART, seen, matched, commands, missed }; } console.log(`key space=${COUNT} part=${PART} deletions per part=${DELETIONS}`); console.log(["path", "commands", "longest block", "entries seen", "matched", "missed"] .map((h, i) => (i === 0 ? h.padEnd(16) : h.padStart(15))).join("")); for (const r of [singleBlock(), cursorScan()]) { console.log(r.name.padEnd(16) + [r.commands, r.longestBlock, r.seen, r.matched, r.missed] .map((n) => String(n).padStart(15)).join("")); } ``` ``` key space=200000 part=1000 deletions per part=2 path commands longest block entries seen matched missed single block 1 200000 200000 40000 0 cursor (1000) 200 1000 199602 39921 398 ``` The single block walks 200,000 entries without interruption and gives the exact count: 40,000 matches, zero missed entries. The cursor scan cuts the longest block to 1,000 entries — the same change that dropped waiting by two orders of magnitude in the previous measurement — but 398 entries never get seen. These entries survived for the whole scan; they were skipped because the list shifted whenever a key got deleted just ahead of the cursor. This is the real trade-off in a single-threaded store's diagnostic toolkit. An uninterrupted scan gives an **exact** answer and makes everyone wait; a cursor scan makes no one wait and gives an **approximate** answer. For a maintenance job, an approximate answer is usually enough; for a count report, it is not. ## The Slow Command Log's Threshold The measurements above were possible because they could see inside the mechanism. In a running store, which command took long is not directly visible; a **slow command log** is kept for this: commands whose duration stays above a threshold get written to a ring buffer holding the last N records. The log itself eats memory too, so the threshold decides two things at once: what gets seen, and how many bytes get held. The run below sweeps five thresholds against a 128-record ring (**CU16**). ```js // slow-command-log.mjs — threshold sweep: which threshold reveals the culprit, how many bytes the log holds const RING = 128, ENTRY_OVERHEAD = 16; // the log is a ring buffer: last 128 records function commands(count) { // deterministic mix, seed visible let seed = 20250731; const rand = () => ((seed = (seed * 1103515245 + 12345) % 2147483648) / 2147483648); return Array.from({ length: count }, (_, i) => { if (i === 1500) return { name: "scan", cost: 4000 }; // looking for the culprit const r = rand(); if (r < 0.95) return { name: "read", cost: 1 }; if (r < 0.99) return { name: "set-member", cost: 5 + Math.floor(rand() * 36) }; return { name: "sorted-range", cost: 200 }; }); } const stream = commands(3000); const entryBytes = (k, seq) => // log record: command name, cost, sequence Buffer.byteLength(JSON.stringify({ name: k.name, cost: k.cost, seq })) + ENTRY_OVERHEAD; console.log(`commands=${stream.length} ring=${RING} entries total work=` + `${stream.reduce((t, k) => t + k.cost, 0)} units`); console.log(["threshold", "logged", "left in ring", "bytes held", "scan in ring"] .map((h, i) => (i === 0 ? h.padEnd(8) : h.padStart(18))).join("")); for (const threshold of [1, 5, 20, 100, 1000]) { const ring = []; let logged = 0; stream.forEach((k, i) => { if (k.cost < threshold) return; // below the threshold: not logged logged += 1; ring.push({ ...k, seq: i, bytes: entryBytes(k, i) }); if (ring.length > RING) ring.shift(); // the oldest record drops }); const bytes = ring.reduce((t, k) => t + k.bytes, 0); const present = ring.some((k) => k.cost === 4000) ? "yes" : "no"; console.log(String(threshold).padEnd(8) + [logged, ring.length, bytes, present].map((n) => String(n).padStart(18)).join("")); } ``` ``` commands=3000 ring=128 entries total work=17267 units threshold logged left in ring bytes held scan in ring 1 3000 128 6593 no 5 159 128 7482 yes 20 108 108 6340 yes 100 40 40 2420 yes 1000 1 1 54 yes ``` The last column shows why threshold choice is a measurement decision. At threshold 1, the log records every command: 3,000 records get produced, but because the ring can hold only the last 128, the 4,000-unit scan has fallen out of the log. A log that records every command is a log that does not record the command being searched for. At threshold 5, the record count drops to 159, and the scan stays in the ring. At threshold 20, the record count falls below the ring's size (108), and no record gets lost anymore; the log holds 6,340 bytes. At threshold 1,000, a single record remains: the culprit is visible, but the sorted-range commands at 200 units each become invisible — even though they account for a quarter of the total 17,267 units of work. A usable threshold is the range that keeps the record count under the ring's size while leaving ordinary commands out. That range is read from the workload; it cannot be known in advance: the threshold gets set wide at first and narrowed if the record count exceeds the ring's size. The log's budget is in the same table — 128 records held at most 7,482 bytes — and that budget is what buys the problem becoming visible. ## Summary - In a single-threaded store, a long command does not delay only its own client: a single 4,000-unit command left 2,001 requests waiting behind it, the longest wait was 3,999 units, total waiting 5,999,001 units. - When the same job was split into 200 parts, the longest wait dropped to 38 units, total waiting to 58,681; the work done did not change, it only became splittable. - Splitting costs two things: the scan finished at unit 8,001 instead of 6,001, and 398 entries were never seen because of keys deleted just ahead of the cursor (0 in the single block). - In the slow command log, the threshold decides both what gets seen and how many bytes get held: at threshold 1, 3,000 records were produced, and the command being searched for fell out of the 128-record ring. - A usable threshold is one that keeps the record count under the ring's size; at threshold 20, 108 records, 6,340 bytes, and the culprit command stayed in the log. ## Next Step Every measurement in this course so far assumed that the store talks only to its own clients: the publisher was a recognized application, the scanning command was a maintenance job, the delay measured was the delay of its own workload. But every cost counted so far was paid without ever asking who sent the command. No barrier was ever raised against a command that deletes the entire key space, a sequence of writes that fills all of memory, or a connection that subscribes slowly and inflates the buffer. The next lesson takes on that gap: it measures how quickly an open-by-default setup gets found, what command restriction shuts off, and what cost network isolation comes with.