Metrics and Slow Command Analysis

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.

// 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.

// 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).

// 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.