Reading Query Plans

Everything measured up to this point was work the application did itself: how many queries ran, how many bytes were carried, how many statements were sent. A query can pass every one of these metrics and still be slow.

A single query, in a single transaction, working with only the needed columns, can still take seconds — because the database decides for itself how that query will be executed. The Advanced SQL course introduced this decision as the query plan and read it directly from the database shell. This lesson reads the same decision from inside the application and builds a mechanism to catch the slow query under production conditions.

Measurement Data

For the gap between a scan and an index to be measurable, the relation needs to be large enough.

// generate.mjs — 50000 loan records, to make the scan-versus-index gap measurable
import { DatabaseSync } from "node:sqlite";
import { rmSync } from "node:fs";
rmSync("library.db", { force: true });

const db = new DatabaseSync("library.db");
db.exec(`
CREATE TABLE member (member_id INTEGER PRIMARY KEY, name TEXT NOT NULL);
CREATE TABLE book (book_id INTEGER PRIMARY KEY, title TEXT NOT NULL);
CREATE TABLE loan (loan_id INTEGER PRIMARY KEY, book_id INTEGER NOT NULL,
                   member_id INTEGER NOT NULL, pickup_date TEXT NOT NULL, return_date TEXT);`);
db.exec("BEGIN");
const u = db.prepare("INSERT INTO member VALUES (?,?)");
for (let i = 1; i <= 60; i++) u.run(i, `Member${i}`);
const k = db.prepare("INSERT INTO book VALUES (?,?)");
for (let i = 1; i <= 200; i++) k.run(i, `Book ${i}`);
const o = db.prepare("INSERT INTO loan VALUES (?,?,?,?,?)");
let seed = 20250727;                        // deterministic pseudo-random sequence
const next = (n) => { seed = (seed * 48271) % 2147483647; return seed % n; };
for (let i = 1; i <= 50000; i++) {
  const year = 2022 + next(4);
  const month = String(next(12) + 1).padStart(2, "0");
  const day = String(next(28) + 1).padStart(2, "0");
  o.run(i, next(200) + 1, next(60) + 1, `${year}-${month}-${day}`,
        next(5) === 0 ? null : `${year}-12-31`);
}
db.exec("COMMIT");
db.exec("ANALYZE");
console.log("loan:", db.prepare("SELECT count(*) AS n FROM loan").get().n,
            " open:", db.prepare("SELECT count(*) AS n FROM loan WHERE return_date IS NULL").get().n);

node generate.mjs

loan: 50000  open: 10006

The data is generated pseudo-randomly, but since the seed is fixed, the same rows come out on every run. The ANALYZE call collects the statistics introduced in the Advanced SQL course; the optimizer estimates selectivity from these statistics.

Reading the Plan from the Application

Just as the plan can be read in the database shell, it can also be read from the application connection. The wrapper below times every query and puts the one that crosses the threshold into the log, together with its plan.

// tracking.mjs — times every query, logs the one that crosses the threshold together with its plan
import { DatabaseSync } from "node:sqlite";

export function trackingConnection(file, thresholdMs) {
  const db = new DatabaseSync(file);
  const log = [];
  const fingerprint = (sql) => sql.replace(/\s+/g, " ").trim();
  return {
    log,
    query(sql, ...d) {
      const t = performance.now();
      const rows = db.prepare(sql).all(...d);
      const duration = performance.now() - t;
      if (duration >= thresholdMs) {
        const plan = db.prepare(`EXPLAIN QUERY PLAN ${sql}`).all(...d).map((p) => p.detail);
        log.push({ fingerprint: fingerprint(sql), duration, rows: rows.length, plan });
      }
      return rows;
    },
    run(sql) { db.exec(sql); },
    plan(sql, ...d) { return db.prepare(`EXPLAIN QUERY PLAN ${sql}`).all(...d).map((p) => p.detail); },
    duration(sql, ...d) {
      const t = performance.now();
      const n = db.prepare(sql).all(...d).length;
      return { duration: performance.now() - t, rows: n };
    },
  };
}

Two decisions sit in this design. The plan is taken only for a query that crosses the threshold; if it were taken for every query, the measurement would cost more than the work itself. And the plan is taken with the bound values the query actually runs with; this detail matters because different values can produce different plans.

The Same Query, Two Plans

// read-plan.mjs — the same query without an index and with one, with plan and duration
import { trackingConnection } from "./tracking.mjs";
const db = trackingConnection("library.db", 0);
const QUERY = "SELECT loan_id, pickup_date FROM loan WHERE member_id = ? AND return_date IS NULL";

const report = (label) => {
  const { duration, rows } = db.duration(QUERY, 17);
  console.log(`${label}`);
  for (const p of db.plan(QUERY, 17)) console.log(`  plan: ${p}`);
  console.log(`  rows=${rows}  duration=${duration.toFixed(2)} ms`);
};

report("without an index");
db.run("CREATE INDEX loan_member_open ON loan (member_id) WHERE return_date IS NULL");
report("after adding a partial index");
db.run("DROP INDEX loan_member_open");

node read-plan.mjs

without an index
  plan: SCAN loan
  rows=180  duration=1.29 ms
after adding a partial index
  plan: SEARCH loan USING INDEX loan_member_open (member_id=?)
  rows=180  duration=0.07 ms

The result is the same: 180 rows. The plan is different. Without an index it reads SCAN; all fifty thousand rows are read and the condition is applied to every one. With an index it reads SEARCH, and states which index is used with which condition.

The format of plan text varies by engine; the words SCAN and SEARCH here are SQLite’s own wording. The distinction that does not change is whether the plan reads an entire relation or goes straight to the rows it is looking for. The partial index introduced in the Relational Database Administration course was used here: the index covers only the records that have not been returned, taking up about a fifth of the fifty thousand rows.

The duration gap at this scale is roughly eighteen-fold. As the relation grows, the gap grows: a scan grows linearly with row count, an index search grows logarithmically.

How Phrasing Changes the Plan

An index existing does not mean it will be used. How a condition is phrased can disable the index.

// phrasing-difference.mjs — two phrasings of the same condition, under the same index
import { trackingConnection } from "./tracking.mjs";
const db = trackingConnection("library.db", 0);
db.run("CREATE INDEX IF NOT EXISTS loan_pickup ON loan (pickup_date)");

const phrasings = {
  "function applied": "SELECT count(*) AS n FROM loan WHERE substr(pickup_date,1,4) = '2024'",
  "range condition ": "SELECT count(*) AS n FROM loan WHERE pickup_date >= '2024-01-01' AND pickup_date < '2025-01-01'",
};

for (const [label, sql] of Object.entries(phrasings)) {
  const result = db.query(sql)[0].n;
  const { duration } = db.duration(sql);
  console.log(`${label}  result=${result}  duration=${duration.toFixed(2)} ms`);
  for (const p of db.plan(sql)) console.log(`  plan: ${p}`);
}
db.run("DROP INDEX loan_pickup");

node phrasing-difference.mjs

function applied  result=12574  duration=1.32 ms
  plan: SCAN loan USING COVERING INDEX loan_pickup
range condition   result=12574  duration=0.14 ms
  plan: SEARCH loan USING COVERING INDEX loan_pickup (pickup_date>? AND pickup_date<?)

Both queries returned the same number and used the same index, but one scanned the index while the other searched it. The reason is the function call in the first phrasing: the index is ordered by pickup_date values, not by substr(pickup_date,1,4) values. The optimizer cannot take advantage of the index’s order and reads the index from end to end.

The second phrasing expresses the same condition as a range. The Advanced SQL course called this kind of condition an index-friendly condition. The rule is simple: the indexed column must stand bare on one side of the condition. A function applied to the column, a type conversion, or a computation disables the index.

The COVERING INDEX phrase that appears in both plans is a second piece of information: since every column the query needs is in the index, the relation itself was never touched. This is the situation the Relational Database Administration course calls a covering index.

The Slow Query Log

Examining queries one by one is useful during development; in production, which query will be slow is not known in advance. For that, queries crossing the threshold are collected and grouped by query fingerprint. A fingerprint is the query text stripped of its bound values; a thousand calls of the same query running with different values collapse into a single row.

// slow-log.mjs — a mixed load is run, queries crossing the threshold are grouped by fingerprint
import { trackingConnection } from "./tracking.mjs";
const db = trackingConnection("library.db", 0.5);

for (let i = 0; i < 20; i++) {
  db.query("SELECT loan_id FROM loan WHERE loan_id = ?", (i * 37) % 50000 + 1);
  db.query("SELECT loan_id FROM loan WHERE member_id = ? AND return_date IS NULL", (i % 60) + 1);
  db.query("SELECT count(*) AS n FROM loan WHERE substr(pickup_date,1,4) = ?", String(2022 + (i % 4)));
}

const groups = new Map();
for (const entry of db.log) {
  const g = groups.get(entry.fingerprint) ?? { count: 0, total: 0, longest: 0, plan: entry.plan };
  g.count += 1; g.total += entry.duration; g.longest = Math.max(g.longest, entry.duration);
  groups.set(entry.fingerprint, g);
}

console.log(`queries over threshold: ${db.log.length} / 60`);
for (const [fingerprint, g] of [...groups].sort((a, b) => b[1].total - a[1].total)) {
  console.log(`\ntotal=${g.total.toFixed(1)} ms  calls=${g.count}  longest=${g.longest.toFixed(2)} ms`);
  console.log(`  ${fingerprint}`);
  for (const p of g.plan) console.log(`  plan: ${p}`);
}

node slow-log.mjs

queries over threshold: 40 / 60

total=32.6 ms  calls=20  longest=1.73 ms
  SELECT count(*) AS n FROM loan WHERE substr(pickup_date,1,4) = ?
  plan: SCAN loan

total=17.8 ms  calls=20  longest=1.11 ms
  SELECT loan_id FROM loan WHERE member_id = ? AND return_date IS NULL
  plan: SCAN loan

Forty of the sixty queries crossed the threshold; the twenty queries looking up by primary key never appeared. The log produced two fingerprints and sorted both by total duration.

Sorting by total duration is deliberate. Looking at the single longest call is misleading; a query that takes two milliseconds and is called a thousand times a second produces more load than one that takes ten milliseconds and is called once a minute. The Relational Database Administration course covered this distinction as the difference between a symptom and a cause.

What the Plan Does Not Say

A plan is a prediction, not a measurement. Three limits are worth keeping in mind.

A plan is based on statistics. If the statistics are stale, the optimizer mispredicts selectivity and picks the wrong plan; refreshing statistics is maintenance work in systems where relation size changes fast.

A plan can change with the bound value. A scan might be chosen for a common value, an index search for a rare one. For that reason, the plan should be taken with the values the query actually runs with.

A plan does not give a duration. In every measurement above, the plan and the duration were printed together; the plan says why something is slow, the duration says how slow. A diagnosis is only complete when the two are read together.

Summary

• The query plan can be read from the application connection; taking a plan only for a query that crosses the threshold is cheaper than taking it for every query.
• The same query produced a SCAN plan without an index and a SEARCH plan with a partial index, and the duration dropped from 1.29 ms to 0.07 ms.
• The function-applied phrasing of the same condition scanned the index, the range phrasing searched it; the indexed column must stand bare on one side of the condition.
• The slow query log groups entries by query fingerprint, stripped of bound values, and sorts them by total duration; what is sought is not the single longest call but the fingerprint producing the most load.
• A plan is a prediction tied to statistics and the bound value; it does not give duration, and a diagnosis is complete only when the plan and the duration are read together.

Next Step

All the queries in this lesson asked for the entire result set. Applications show most lists piece by piece, and the offset–limit pair introduced in the SQL Fundamentals course is the best-known way to do it. It is short to write, its plan is simple, and it is fast on early pages. On deep pages, its cost grows together with the number of skipped rows, and that growth is invisible just from looking at the query text. The next lesson pulls the same list with increasing offset values, measures the cost, compares it with a key-based approach, and covers which interface constraint each of the two approaches brings.