Bottleneck Analysis

The previous lesson’s report reduced the result to a single sentence: p99 37.59 ms, threshold 20, fail. That sentence reports a defect but does not say where it is. The same number could come from a computation in the application layer, a query in the database, or the size of the response, and the fix for each of the three is different. This lesson takes on tying the result to a layer.

Layer Share

A request’s total duration is measured at the client and is a single number. The bottleneck is wherever consumes most of that duration; finding it requires splitting the duration inside the request. The server reads three clocks on every request: before the query, after the query, after the computation, and after the response is written. The gaps between them are the database, application and transfer layers’ durations.

These three numbers alone are not enough, because every layer does some work on every request. What matters is the difference: a baseline run carrying no defect is taken on the same harness, and each layer’s duration is read as its difference from the baseline. Layer share is a layer’s difference divided by the client’s difference.

NF6 (assumption) — to attribute a result to one layer, that layer’s share must be at least 0.50; otherwise the result counts as unattributable. Rationale: below a share of 0.50, even completely eliminating that layer removes less than half the symptom, and the fix decision cannot be defended. The threshold is scanned below.

The decision’s owner is a budget: attribution decides which team and which work the fix goes to. A wrong attribution does not just waste time, it leaves the defect in place. The Performance Anti-Patterns and Monitoring course built ten diagnoses running from symptom to cause; the question asked here comes before that: which layer the result belongs to.

Harness

The loan endpoint runs in five modes. baseline does an indexed query and a small response; db does the same query unindexed; app runs a computation round in the application layer; net serializes and writes a 4,000-row page fetched once at startup on every response; mixed re-fetches the same page from the database on every request. All four are tuned to give the same symptom.

// library/server.mjs — loan endpoint, five modes. Every request measures three layers'
// duration separately: database (query), application (computation), transfer (serialization + writing the response).
// Arguments: <port> <mode baseline|db|app|net|mixed>
import { createServer } from "node:http";
import { DatabaseSync } from "node:sqlite";

const MEMBER = 500, START = 55000, ROUNDS = 29000, ROW = 4000;   // catalog size, computation rounds, page rows
const port = Number(process.argv[2]), mode = process.argv[3];

if (Number.isInteger(port) === false || ["baseline", "db", "app", "net", "mixed"].includes(mode) === false) {
  console.log("usage: node library/server.mjs <port> baseline|db|app|net|mixed");
} else {
  const db = new DatabaseSync(":memory:");
  db.exec("CREATE TABLE loan(id INTEGER PRIMARY KEY, member_no TEXT, book_no TEXT, day INT)");
  if (mode !== "db") db.exec("CREATE INDEX loan_member ON loan(member_no)");
  db.exec("BEGIN");
  const fill = db.prepare("INSERT INTO loan(member_no, book_no, day) VALUES(?,?,?)");
  for (let i = 0; i < START; i += 1) fill.run(`U-${i % MEMBER}`, `K-${i % 9000}`, i % 400);
  db.exec("COMMIT");

  const count = db.prepare("SELECT COUNT(*) AS n FROM loan WHERE member_no = ?");
  const fetch = db.prepare("SELECT id, book_no, day FROM loan LIMIT ?");
  const cache = mode === "net" ? fetch.all(ROW) : [];   // in net mode the page is fetched once at startup
  let requests = 0, dbTime = 0, appTime = 0, netTime = 0, bytes = 0, scan = 0, computed = 0;

  createServer((req, res) => {
    const u = new URL(req.url, "http://local");
    if (u.pathname === "/metrics") {
      res.writeHead(200, { "content-type": "application/json" });
      res.end(JSON.stringify({ requests, dbTime, appTime, netTime, bytes, scan, computed })); return;
    }
    requests += 1;
    const member = u.searchParams.get("member") ?? "U-1";
    const t0 = performance.now();
    const n = count.get(member).n;                    // database layer
    const page = mode === "mixed" ? fetch.all(ROW) : cache;
    scan += mode === "db" ? START : Math.ceil(Math.log2(START));
    const t1 = performance.now();
    let summary = "";                                 // application layer
    if (mode === "app") for (let k = 0; k < ROUNDS; k += 1) { summary = `${member}/${(n + k) % 97}`; computed += 1; }
    const t2 = performance.now();
    const body = JSON.stringify({ member, loan: n, summary, page });   // transfer layer
    dbTime += t1 - t0; appTime += t2 - t1; bytes += body.length;
    res.writeHead(200, { "content-type": "application/json" });
    res.on("finish", () => { netTime += performance.now() - t2; });
    res.end(body);
  }).listen(port);
}

The generator excludes the first second from the measurement and reads the server counters once more at the start of that window, so that both the client and the server side describe the same interval.

// library/measure.mjs — open-loop generator; reads the client duration and the server's
// layer counters. Arguments: <port> <mode> <target rate> <duration s>
import { Agent, request } from "node:http";

const WARMUP = 1;   // the first second is not counted: JIT and cache warm-up
const [port, mode, rate, duration] = process.argv.slice(2).map((x, i) => (i === 1 ? x : Number(x)));
const agent = new Agent({ keepAlive: true, maxSockets: 8192 });
const percentile = (d, p) => { const t = [...d].sort((a, b) => a - b);
  return t[Math.min(t.length - 1, Math.floor((p / 100) * t.length))]; };
let seq = 0;

function oneRequest(samples, sec) {
  const start = performance.now(), i = seq++;
  return new Promise((done) => {
    const r = request({ port, path: `/loan?member=U-${i % 500}`, agent }, (y) => {
      y.resume(); y.on("end", () => { samples.push({ ms: performance.now() - start, sec }); done(); });
    });
    r.on("error", () => { samples.push({ ms: performance.now() - start, sec }); done(); });
    r.end();
  });
}

const metrics = () => new Promise((done) => {
  request({ port, path: "/metrics", agent }, (y) => { let g = "";
    y.on("data", (p) => { g += p; }); y.on("end", () => done(JSON.parse(g))); }).end();
});

if (Number.isInteger(port) === false) {
  console.log("usage: node library/measure.mjs <port> <mode> <target rate> <duration>");
} else {
  const samples = [], inFlight = [];
  let debt = 0, lastT = 0, m1 = null;
  const start = performance.now();
  while (performance.now() - start < duration * 1000) {
    const t = (performance.now() - start) / 1000;
    if (m1 === null && t >= WARMUP) m1 = await metrics();     // the warm-up window closes here
    debt += rate * (t - lastT); lastT = t;
    while (debt >= 1) { debt -= 1; inFlight.push(oneRequest(samples, t)); }
    await new Promise((c) => setTimeout(c, 5));
  }
  await Promise.all(inFlight);
  const m2 = await metrics(), n = m2.requests - m1.requests;
  const d = samples.filter((r) => r.sec >= WARMUP).map((r) => r.ms);
  console.log(JSON.stringify({ mode, rate, samples: d.length,
    client: d.reduce((a, b) => a + b, 0) / d.length, p95: percentile(d, 95),
    db: (m2.dbTime - m1.dbTime) / n, app: (m2.appTime - m1.appTime) / n, net: (m2.netTime - m1.netTime) / n,
    bytes: (m2.bytes - m1.bytes) / n, scan: (m2.scan - m1.scan) / n }));
}
agent.destroy();

// library/attribution.mjs — computes layer shares against the baseline, ties attribution to
// a rule, and scans the share threshold. Argument: <jsonl>
import { readFileSync } from "node:fs";

const SHARE = 0.5;                                  // NF6: minimum share to attribute to one layer
const ACTUAL = { db: "database", app: "application", net: "transfer", mixed: "transfer" };
const LAYER = ["db", "app", "net"], NAME = { db: "database", app: "application", net: "transfer" };
const s = readFileSync(process.argv[2], "utf8").trim().split("\n").map((x) => JSON.parse(x));
const find = (k) => s.find((r) => r.mode === k);
const BASE = find("baseline"), MODE = ["db", "app", "net", "mixed"];
const fmt = (x, n = 3) => x.toFixed(n);
const pad = (x, n) => String(x).padStart(n);
const diff = (r) => ({ client: r.client - BASE.client, db: r.db - BASE.db, app: r.app - BASE.app, net: r.net - BASE.net });
const attribute = (r, threshold) => {               // if the largest share crosses the threshold, that layer
  const f = diff(r);
  const top = LAYER.reduce((a, k) => (f[k] > f[a] ? k : a), "db");
  return f[top] / f.client >= threshold ? NAME[top] : "unattributable";
};

console.log(`baseline: client ${fmt(BASE.client)} ms, db ${fmt(BASE.db)}, app ${fmt(BASE.app)}, transfer ${fmt(BASE.net)}, ` +
  `bytes ${Math.round(BASE.bytes)}`);
console.log("mode    client   p95   diff   db share  app share  transfer share  bytes    attribution");
for (const k of MODE) {
  const r = find(k), f = diff(r);
  console.log(k.padEnd(8) + pad(fmt(r.client, 2), 7) + pad(fmt(r.p95, 2), 6) + pad(fmt(f.client, 2), 7) +
    pad(fmt(f.db / f.client, 2), 9) + pad(fmt(f.app / f.client, 2), 10) + pad(fmt(f.net / f.client, 2), 14) +
    pad(Math.round(r.bytes), 9) + "  " + attribute(r, SHARE));
}

console.log("\nshare-threshold scan: the four modes' attribution (actual layer: db=database, " +
  "app=application, net and mixed=transfer)");
console.log("share threshold  correct /4  wrong /4  unattributable /4");
for (const e of [0.3, 0.5, 0.7, 0.8, 1.0]) {
  const a = MODE.map((k) => attribute(find(k), e));
  const correct = a.filter((x, i) => x === ACTUAL[MODE[i]]).length;
  const none = a.filter((x) => x === "unattributable").length;
  console.log(fmt(e, 1).padEnd(17) + pad(correct, 11) + pad(4 - correct - none, 10) + pad(none, 18));
}

# measure.sh — five runs: baseline and four modes, at the same target rate, each with a fresh server.
rm -f result.jsonl
for M in baseline db app net mixed; do
  node library/server.mjs 8854 $M & SERVER=$!
  sleep 1.2
  node library/measure.mjs 8854 $M 250 6 >> result.jsonl
  kill $SERVER
  wait $SERVER 2>/dev/null
done
node library/attribution.mjs result.jsonl

baseline: client 0.629 ms, db 0.032, app 0.000, transfer 0.108, bytes 56
mode    client   p95   diff   db share  app share  transfer share  bytes    attribution
db         2.11  3.45   1.48     0.98     -0.00         -0.06       56  database
app        1.49  2.60   0.86    -0.01      0.90         -0.03       63  application
net        1.51  2.74   0.88    -0.03     -0.00          0.98   160738  transfer
mixed      2.16  3.62   1.53     0.55     -0.00          0.35   160738  database

share-threshold scan: the four modes' attribution (actual layer: db=database, app=application, net and mixed=transfer)
share threshold  correct /4  wrong /4  unattributable /4
0.3                        3         1                 0
0.5                        3         1                 0
0.7                        3         0                 1
0.8                        3         0                 1
1.0                        0         0                 4

Same Symptom, Three Separate Layers

The first column is the decision itself, and it is the same across all four modes. In this run the client average ranges from 1.49 to 2.16 ms — about 45% higher at the top than at the bottom; p95 ranges from 2.60 to 3.62 ms across the four modes. A report that looks only at the client-side number cannot tell these four structures apart.

The share columns tell them apart. In db mode the database share is 0.98, in app mode the application share is 0.90, in net mode the transfer share is 0.98. Three modes give the same symptom and get attributed to three separate layers; their fixes are different too — adding an index, thinning the computation, shrinking the response.

None of the shares in this run exceed 1, but the measurement allows it: if the database difference came out larger than the client difference, that would show the baseline’s own noise growing relative to a small difference between two runs. The rule only looks at the largest share, so the attribution would not change; a share over 1 just means the reading is “the database explains the entire symptom,” nothing more.

When Attribution Is Wrong

The fourth row is where the rule breaks. In mixed mode the database share is 0.55, the transfer share is 0.35; the rule blames the database. The measurement is correct: time really is spent in the query, because the query reads 4,000 rows. The result is still wrong.

The evidence is in the last column, and it is independent of the run: mixed and net send the same 160,738 bytes per response. In net mode that page was fetched once at startup and cached, so the database share is near zero and the rule blames transfer. The difference between the two modes is not in the query, it is in the decision about the size of the response — and that decision is the same in both. Adding an index to the database in mixed mode changes nothing; the query does not need an index, it reads 4,000 rows regardless.

The rule is this: layer share says where the time went, not which decision produced it. The measurement that answers the second question is a run-independent quantity — bytes sent, rows read, records scanned. In this run db mode scans 55,000 rows per request, the others scan 16; net and mixed send 160,738 bytes per request, the others send 56 and 63. Wherever two layers give the same symptom, this is the measurement that tells them apart.

Share Threshold Scan

The second table shifts NF6’s 0.50. The table’s individual numbers are run-dependent — a share is drawn from measured duration differences and moves from run to run on this machine — but its direction is run-independent and the decision is made in that direction. At a low threshold all four modes get attributed to a layer and mixed gets a wrong attribution; as the threshold rises, the wrong attribution clears first, then the correct ones start falling under the threshold too and turn unattributable. In this run the turn starts at 0.7, where mixed drops out; the other three hold their attribution up to just under 1.0, since their own shares (0.98, 0.90, 0.98) sit close to the ceiling, and at exactly 1.0 none of them clears it either — in another run the turn could start a step earlier or later, because what crosses the threshold is the share itself.

This is the trade-off between the two error types. A low threshold blames an innocent layer; a high threshold cannot pin the defect on anyone, and the finding closes without becoming a record. NF6’s 0.50 does not clear the wrong attribution by itself — what clears it is not the threshold but reading the run-independent quantity.

Cost and the Class It Misses

The run-dependent side of the cost depends on the environment: five runs finished in under forty seconds on this machine. The run-independent side is countable — five server processes, five of every six seconds measured per run (the first second is set aside for warm-up), and every run reads four clocks per request, meaning instrumentation adds four extra measurements per request.

The class it misses can also be counted: this harness only splits duration inside the server. The residual between the client’s difference and the sum of the measured layers — about 14% of the difference in app mode — is written to no layer. Network round trip, event-loop wait and the operating system’s socket work stay there. In a system approaching saturation this residual grows and share-based attribution stops being usable; the metric to read then is not layer share but the previous lesson’s throughput–latency pair.

Summary

• Layer share is a layer’s difference from the baseline run divided by the client’s difference; the attribution rule requires the largest share to cross NF6’s 0.50.
• The same client-side symptom (average 1.49–2.16 ms) got attributed to three separate layers: database at a share of 0.98, application at 0.90, transfer at 0.98.
• Attribution is wrong in mixed mode: time really is spent in the query, but it sends the same 160,738 bytes as net; the cause is not the query, it is the decision about response size.
• The share-threshold scan shows the trade-off: as the threshold rises, the wrong attribution clears first, then correct attributions fall too and unattributable runs climb; which step the turn happens at is run-dependent.
• Layer share says where the time went; the run-independent quantity says which decision produced it (55,000 rows scanned, 160,738 bytes sent).

Next Step

Every number up to this point was read from a single run. This lesson’s baseline was taken once and every share was divided by it; the layer-share residual not fully summing to the client’s own difference — about 14% left over in app mode — shows that two runs of the same harness do not give the same number. And the harness excludes the first second from measurement altogether — the existence of a warm-up effect was assumed but its size was never measured. The next lesson puts the measurement itself to the test: how many runs warm-up lasts, how much variability exists between runs of the same structure, and how many runs a difference between two structures needs before it can be called meaningful.