Monitoring and Alerting

Every decision in the previous lesson rested on a measurement: connection cost, queue time, concurrent transaction count, the share of requests that time out. None of these are visible on their own. Pool saturation is felt on the application side only as “the database is slow,” and it is usually looked for in the wrong place.

Monitoring’s job is to fill that gap: turning the system’s state into numbers continuously, not only at the moment of failure. This lesson covers which numbers to collect, how to read them, and when an alert is meaningful.

What a Query’s Duration Measures

The most basic magnitude is how long a statement takes; but “duration” is not a single number. The block below measures two queries on the same table. The timings depend on the machine and the filesystem; yours will come out different.

rm -f measurement.db

sqlite3 measurement.db <<'SQL'
CREATE TABLE loan(id INTEGER PRIMARY KEY, book_id INT NOT NULL, member_id INT NOT NULL,
                   branch_id INT NOT NULL, pickup TEXT NOT NULL, returned TEXT);
WITH RECURSIVE s(n) AS (SELECT 1 UNION ALL SELECT n+1 FROM s WHERE n<400000)
INSERT INTO loan(id,book_id,member_id,branch_id,pickup)
SELECT n,(n%400)+1,(n%900)+1,(n%3)+1,'2025-06-01' FROM s;
CREATE INDEX loan_member ON loan(member_id);
SQL

sqlite3 measurement.db <<'SQL'
.header on
.timer on
SELECT COUNT(*) AS indexed FROM loan WHERE member_id=42;
SELECT COUNT(*) AS scanned FROM loan WHERE pickup LIKE '2025-06-01';
SQL

indexed
445
Run Time: real 0.000 user 0.000057 sys 0.000036
scanned
400000
Run Time: real 0.013 user 0.012035 sys 0.001583

Three numbers say three different things. Wall-clock time (real) is the time elapsed between the query’s start and end — this is what the user waits for. CPU time (user and sys) is the time genuinely spent computing for that query.

In the second query, wall-clock time is close to CPU time: the query was busy the whole time it read four hundred thousand rows, waiting for nothing. This gives monitoring its single most useful rule: if wall-clock time is noticeably larger than CPU time, the difference is wait. The wait could be data coming from disk, a lock being released, the log being written to disk, or a response coming over the network. Monitoring that looks only at CPU time cannot see the most common causes of slowness.

Most engines surface this in more detail: which event each session is currently waiting on is recorded. Wait events are grouped into classes — lock wait, reading from a data file, writing the log to disk, waiting for the client to send data. The distribution across these classes names the bottleneck directly; guesses made without measuring are usually wrong.

Average, Distribution, and Total Impact

A single run’s duration is one number; what operating requires is the distribution of thousands of runs. The block below simulates a day’s workload: four different query shapes run with different call counts, and each run’s duration is recorded.

The member distribution is deliberately skewed: member number one is the library’s bulk loan account and has a large number of records. Timings depend on the environment; what matters is the relationship between the columns.

rm -f monitoring.db

node - <<'EOF'
const { DatabaseSync } = require("node:sqlite");
const db = new DatabaseSync("monitoring.db");
db.exec(`CREATE TABLE loan(id INTEGER PRIMARY KEY, book_id INT NOT NULL, member_id INT NOT NULL,
                            branch_id INT NOT NULL, pickup TEXT NOT NULL, returned TEXT)`);
// Member distribution is skewed: member number one is the library's bulk loan account.
const insert = db.prepare("INSERT INTO loan(book_id,member_id,branch_id,pickup) VALUES(?,?,?,?)");
db.exec("BEGIN");
for (let i = 1; i <= 200000; i++)
  insert.run(i % 400 + 1, i % 12 === 0 ? 1 : (i % 900) + 2, (i % 3) + 1, "2025-06-01");
db.exec("COMMIT");
db.exec("CREATE INDEX loan_member ON loan(member_id)");

const log = [];   // (signature, duration) for each run
const run = (signature, stmt, ...p) => {
  const t = process.hrtime.bigint();
  stmt.all(...p);
  log.push([signature, Number(process.hrtime.bigint() - t) / 1e6]);
};
const memberQuery = db.prepare("SELECT id,book_id,pickup FROM loan WHERE member_id=?");
const keyQuery = db.prepare("SELECT book_id,member_id FROM loan WHERE id=?");
const branchQuery = db.prepare("SELECT COUNT(*) c FROM loan WHERE branch_id=? AND returned IS NULL");
const reportQuery = db.prepare(
  "SELECT branch_id, COUNT(*) c FROM loan WHERE pickup>=? GROUP BY branch_id");

for (let i = 0; i < 2000; i++) run("member records", memberQuery, i % 12 === 0 ? 1 : i % 900 + 2);
for (let i = 0; i < 20000; i++) run("lookup by key", keyQuery, i % 200000 + 1);
for (let i = 0; i < 200; i++) run("branch count", branchQuery, (i % 3) + 1);
for (let i = 0; i < 20; i++) run("daily report", reportQuery, "2025-01-01");

const percentile = (arr, p) => arr[Math.min(arr.length - 1, Math.floor(arr.length * p))];
const totalTime = log.reduce((t, k) => t + k[1], 0);
console.log("signature       | calls | average  | p50   | p95   | p99   | total   | share");
console.log("----------------|-------|----------|-------|-------|-------|---------|------");
for (const signature of [...new Set(log.map((k) => k[0]))]) {
  const durations = log.filter((k) => k[0] === signature).map((k) => k[1]).sort((a, b) => a - b);
  const sum = durations.reduce((t, v) => t + v, 0);
  console.log(signature.padEnd(15) + " | " + String(durations.length).padStart(5) + " | " +
    (sum / durations.length).toFixed(3).padStart(8) + " | " + percentile(durations, 0.5).toFixed(2).padStart(5) +
    " | " + percentile(durations, 0.95).toFixed(2).padStart(5) + " | " + percentile(durations, 0.99).toFixed(2).padStart(5) +
    " | " + (sum.toFixed(0) + " ms").padStart(7) + " | %" +
    (100 * sum / totalTime).toFixed(1).padStart(4));
}
const THRESHOLD = 10;
const slow = log.filter((k) => k[1] > THRESHOLD);
const slowTime = slow.reduce((t, k) => t + k[1], 0);
console.log();
console.log("total runs: " + log.length + ", total time: " +
            totalTime.toFixed(0) + " ms");
console.log(THRESHOLD + " ms threshold exceeded by: " + slow.length + " runs, " +
            slowTime.toFixed(0) + " ms (%" + (100 * slowTime / totalTime).toFixed(1) + ")");
EOF

signature       | calls | average  | p50   | p95   | p99   | total   | share
----------------|-------|----------|-------|-------|-------|---------|------
member records  |  2000 |    0.560 |  0.08 |  5.62 |  5.81 | 1120 ms | %45.6
lookup by key   | 20000 |    0.003 |  0.00 |  0.00 |  0.00 |   62 ms | % 2.5
branch count    |   200 |    4.448 |  4.11 |  5.22 |  5.35 |  890 ms | %36.2
daily report    |    20 |   19.352 | 19.37 | 19.55 | 19.55 |  387 ms | %15.7

total runs: 22220, total time: 2459 ms
10 ms threshold exceeded by: 20 runs, 387 ms (%15.7)

The table gives three separate lessons about monitoring at once.

Average does not describe the distribution. The member records query’s average is a little above half a millisecond; its median is a seventh of that. The gap comes from the fact that one call in twelve goes to the bulk loan account. Average blends these two separate behaviors into a single number and describes neither correctly. Percentiles preserve the distinction: p50 is what the ordinary user sees, p95 and p99 describe the tail.

Slow is not the same as expensive. The daily report is the slowest query in a single run; it produces about a sixth of the total load. The member records query is fast on every run and produces almost half the total load. The first place to look when speeding up the system is not the query with the highest average duration, but the one with the highest call count times duration.

A threshold-based slow query log sees only one slice. The ten-millisecond threshold caught about fifteen percent of the workload; the remaining roughly eighty-five percent stayed invisible. A threshold is valuable for finding statements that are pathological on their own; it does not tell where the workload’s weight goes. For that, every run needs to be grouped by its query fingerprint — the statement text with its parameters stripped, which gathers every run of the same shape into a single line.

Measuring the Wait

A query’s own duration is not the whole of the response time. The block below measures this directly: the same update statement runs first on an idle system, then while another process is holding a lock on the same table. The second duration depends on how long the process holding the lock runs.

rm -f wait.db lock.flag

node - <<'EOF'
const { DatabaseSync } = require("node:sqlite");
const { spawn } = require("node:child_process");
const fs = require("node:fs");
const wait = (ms) => Atomics.wait(new Int32Array(new SharedArrayBuffer(4)), 0, 0, ms);

const db = new DatabaseSync("wait.db");
db.exec("PRAGMA busy_timeout=5000");
db.exec("CREATE TABLE loan(id INTEGER PRIMARY KEY, book_id INT, member_id INT, returned TEXT)");
const insert = db.prepare("INSERT INTO loan(book_id,member_id) VALUES(?,?)");
db.exec("BEGIN");
for (let i = 1; i <= 5000; i++) insert.run(i % 400, i % 250);
db.exec("COMMIT");

const write = () => {
  const t = process.hrtime.bigint();
  db.exec("BEGIN IMMEDIATE");
  db.prepare("UPDATE loan SET returned='2025-06-30' WHERE id=?").run(7);
  db.exec("COMMIT");
  return Number(process.hrtime.bigint() - t) / 1e6;
};
const uncontended = write();

// A second process holds a lock on the same table for 1200 ms.
const childCode = `
const { DatabaseSync } = require("node:sqlite");
const fs = require("node:fs");
const db = new DatabaseSync("wait.db");
db.exec("PRAGMA busy_timeout=5000");
db.exec("BEGIN IMMEDIATE");
db.prepare("UPDATE loan SET returned='2025-06-29' WHERE id=?").run(9);
fs.writeFileSync("lock.flag", "1");
Atomics.wait(new Int32Array(new SharedArrayBuffer(4)), 0, 0, 1200);
db.exec("COMMIT");
`;
spawn(process.execPath, ["-e", childCode], { stdio: "ignore" });
while (!fs.existsSync("lock.flag")) wait(10);

const contended = write();
console.log("uncontended write".padEnd(22) + ": " + uncontended.toFixed(1) + " ms");
console.log("same write under lock".padEnd(22) + ": " + contended.toFixed(1) + " ms");
console.log("share of the wait".padEnd(22) + ": %" +
            (100 * (contended - uncontended) / contended).toFixed(2));
fs.rmSync("lock.flag", { force: true });
EOF

uncontended write     : 0.3 ms
same write under lock : 1256.6 ms
share of the wait     : %99.98

Same statement, same row, same data; the duration grew by four orders of magnitude, and all of the growth came from waiting. No measurement collected about the statement itself can explain it: the query plan is the same, the number of rows read is the same, the CPU time is the same. The explanation lies only in the answer to “what was this session waiting for.”

In operation this gap shows up as: response time measured on the application side grows, while query durations on the database side are normal. The two sides point at each other. Monitoring wait events settles this argument — the time is being spent not on the side waiting for the lock, but in the long transaction holding it.

When an Alert Is Meaningful

Not every collected number should turn into an alert. A working alert satisfies three conditions.

It has a threshold, and the threshold is derived from a baseline. “Query time is high” is not an alert; “p95 is three times its normal value over the last hour” is. The baseline is obtained by measuring during a period known to be healthy.

It has a persistence condition. A momentary spike does not produce an alert; it has to hold for a given window. This is the same trade-off as the failover setting in the previous lesson: as sensitivity rises, the number of false alerts rises with it.

It corresponds to an action. If there is no work to do in response, the alert only produces noise and, over time, gets ignored. Alert fatigue is the most common failure mode in monitoring setups: among hundreds of alerts, the real one goes unnoticed.

A useful distinction for choosing which magnitudes to alert on is the difference between symptom and cause. A symptom is what the user feels: response time, error rate, the number of failed loan transactions. A cause is the internal state producing that symptom: replication lag, pool saturation, disk fullness, a long-running transaction. Alerts are built on symptoms — nobody is woken up when the user is unaffected. Causes are kept on dashboards; that is where to look once an alert arrives.

Outside this distinction there is one more class: situations that call for an alert even though the user is not yet affected. The disk having two days left before it fills up, backups not having run for three days, replication lag exceeding the recovery point objective. These point to a resource running out, and need to be addressed before an effect forms.

Finally, monitoring itself has a scope. Every lesson in this topic left behind a magnitude worth watching: the backup’s age and validation date, how long the recovery drill takes, replication lag, cluster member state, idle connection count in the pool, and queue time. An unmonitored guarantee is not a guarantee.

Summary

• The difference between wall-clock time and CPU time is wait; monitoring that looks only at CPU time cannot see the most common causes of slowness.
• Average hides skewed distributions; p50 describes the ordinary case, p95 and p99 describe the tail.
• Where the workload’s weight goes is found by grouping call count times duration by query fingerprint; the slowest query is usually not the most expensive one.
• A threshold-based slow query log catches pathological statements on its own but misses most of the total load.
• Lock wait never shows up in a statement’s own measurements; the time is spent in the transaction holding the lock, and it is found only by monitoring wait events.
• A meaningful alert has a threshold derived from a baseline, a persistence condition, and a corresponding action; alerts are built on symptoms, dashboards on causes.

Next Step

Monitoring shows what the system does under its ordinary load. Some work sits outside that ordinary load and deliberately stresses the system: importing an archive, loading a membership list from another institution, exporting a year’s loan records. This work moves millions of rows at once and takes hours when done with row-by-row writing habits. The next lesson covers bulk data loading: how the transaction boundary affects duration, the cost of indexes during load, comparing a prepared statement against an import command, and extracting bad rows without stopping the load.