/crawlstats: stop paying thirty seconds for a planner's guess

apps/web/src/app/api/crawlstats/route.js

@@ -1,7 +1,7 @@
 import { q, discovery, alerts } from '@rssamplifier/db';
 
 import { db } from '../../../lib/db.js';
-import { categoryStats, indexingHistory } from '../../../lib/crawlstats.js';
+import { categoryStats, indexingHistory, jobBacklogs } from '../../../lib/crawlstats.js';
 import { toLine } from '../../../lib/crawlLog.js';
 import { jobRows } from '../../../lib/jobs.js';
 
@@ -43,7 +43,17 @@ export async function GET() {
     discovery.countQueuedKeywords(client),
     indexingHistory(),
     categoryStats(),
-    q.jobBacklogs(client),
+    // The cached reader, which is what the page has always used. This route
+    // called `q.jobBacklogs` directly and so paid the uncached count on every
+    // request -- 27.9 seconds of a 53-second response, while /crawlstats
+    // rendered the same numbers in 3.7. Nothing about a status endpoint wants
+    // that: the backlog it reports is hundreds of thousands of feeds draining
+    // at a few hundred an hour, so a sixty-second-old answer is the same answer.
+    //
+    // The liveness numbers stay uncached, which is the distinction that matters
+    // -- `crawlStats` and `logActivity` below are still read fresh, so this
+    // endpoint can still never claim a dead crawler is alive.
+    jobBacklogs(),
     q.logActivity(client, 1),
     // See the page: this only tells a sender with nobody to serve from one that
     // has stopped, which the log alone cannot say.
@@ -52,7 +62,11 @@ export async function GET() {
   ]);
 
   const jobs = jobRows({
-    backlogs,
+    // Null when the read failed and nothing was cached. `jobBacklogs` returns
+    // null rather than zeroes on purpose -- "0 waiting" reads as "all caught
+    // up", which would be a lie -- and an empty object leaves each backlog
+    // undefined, which serialises as unknown rather than as done.
+    backlogs: backlogs ?? {},
     activity,
     fetchedLastHour: stats.fetchedLastHour,
     keywordQueue: keywordsQueued,

packages/db/src/queries.js

@@ -1398,8 +1398,17 @@ export async function jobBacklogs(db) {
 
     // A short range read off feeds_created_idx: an hour of submissions is a
     // handful of rows however large the directory gets.
+    //
+    // `indexed by` because the planner does not agree, and gets it badly wrong.
+    // **This database has never been ANALYZEd** -- there is no `sqlite_stat1` --
+    // so SQLite falls back to its built-in guess that an equality test beats a
+    // range test, picks `feeds_status_success_idx (status=?)`, and visits every
+    // `pending` row to check its `created_at`. `pending` is 330k of 444k rows.
+    // Measured: 17,722ms this way, 654ms forced onto the range, and the same
+    // 5,954 rows come back either way.
     db.execute({
-      sql: `select count(*) as n from feeds where created_at >= ? and status = 'pending'`,
+      sql: `select count(*) as n from feeds indexed by feeds_created_idx
+             where created_at >= ? and status = 'pending'`,
       args: [hourAgo],
     }),
 
@@ -1417,10 +1426,16 @@ export async function jobBacklogs(db) {
     // for the reason this whole function exists: 3,275 of 369,056 feeds carry a
     // stamp, so this touches a few thousand index entries, while asking for the
     // complement would visit every row. The backlog is arithmetic afterwards.
+    //
+    // `indexed by` for the same reason as `submitted` above, and it costs even
+    // more here: unforced the planner seeks `status='active'` (109k rows) on
+    // `feeds_status_success_idx` and reads `authors_checked_at` off each one,
+    // when the partial index *is* keyed by exactly the column being counted and
+    // filtered. Measured: 16,067ms unforced, 119ms forced -- 135x, same answer.
     db.execute({
       sql: `select count(*) as n,
                    sum(case when authors_checked_at >= ? then 1 else 0 end) as hour
-            from feeds
+            from feeds indexed by feeds_authors_due_idx
            where status = 'active' and authors_checked_at is not null`,
       args: [hourAgo],
     }),

packages/db/test/job-backlog-plans.test.js

@@ -0,0 +1,102 @@
+import assert from 'node:assert/strict';
+import { test, before, after } from 'node:test';
+import { mkdtemp, rm } from 'node:fs/promises';
+import { tmpdir } from 'node:os';
+import { join } from 'node:path';
+
+import { connect, newId, nowIso } from '../src/client.js';
+import { migrate } from '../src/migrate.js';
+import * as q from '../src/queries.js';
+
+/**
+ * The index choices behind `jobBacklogs`, pinned.
+ *
+ * These are `indexed by` in the query because this database has **never been
+ * ANALYZEd** — there is no `sqlite_stat1` — so SQLite falls back to its built-in
+ * guess that an equality beats a range, and picks the status index for two
+ * queries that want a date. Measured against production: 17.7s vs 654ms, and
+ * 16.1s vs 119ms, for identical results.
+ *
+ * A plan regression is invisible from the outside — same rows, same numbers,
+ * thirty times the wall clock — so the plan itself is the thing worth asserting.
+ * Locally the tables are tiny and both plans are instant; only the shape can be
+ * checked here, which is precisely why it needs a test rather than a benchmark.
+ */
+
+let dir;
+let db;
+
+before(async () => {
+  dir = await mkdtemp(join(tmpdir(), 'rssamp-plans-'));
+  db = connect({ url: `file:${join(dir, 'test.db')}` });
+  await migrate(db);
+});
+
+after(async () => {
+  await rm(dir, { recursive: true, force: true });
+});
+
+/**
+ * @param {string} sql
+ * @param {unknown[]} args
+ * @returns {Promise<string>}
+ */
+async function plan(sql, args = []) {
+  const { rows } = await db.execute({ sql: `explain query plan ${sql}`, args });
+  return rows.map((r) => String(r.detail)).join(' | ');
+}
+
+test('the submissions count is read off the created_at index, not the status one', async () => {
+  const detail = await plan(
+    `select count(*) as n from feeds indexed by feeds_created_idx
+      where created_at >= ? and status = 'pending'`,
+    [nowIso(-3_600_000)],
+  );
+
+  assert.match(detail, /feeds_created_idx/);
+  assert.doesNotMatch(detail, /feeds_status_success_idx/);
+});
+
+test('the enrichment count is read off its own partial index', async () => {
+  const detail = await plan(
+    `select count(*) as n,
+            sum(case when authors_checked_at >= ? then 1 else 0 end) as hour
+       from feeds indexed by feeds_authors_due_idx
+      where status = 'active' and authors_checked_at is not null`,
+    [nowIso(-3_600_000)],
+  );
+
+  assert.match(detail, /feeds_authors_due_idx/);
+  assert.doesNotMatch(detail, /feeds_status_success_idx/);
+});
+
+test('both forced indexes exist, so the hint cannot become an error', async () => {
+  // `indexed by` is not a hint SQLite may ignore -- naming an index that does
+  // not exist is a hard failure at prepare time. A migration that renamed or
+  // dropped either of these would take the whole jobs board down, so the
+  // coupling is asserted rather than left to be discovered in production.
+  const { rows } = await db.execute(
+    `select name from sqlite_master where type = 'index'
+       and name in ('feeds_created_idx', 'feeds_authors_due_idx')`,
+  );
+
+  assert.equal(rows.length, 2, 'both indexes must exist for jobBacklogs to prepare');
+});
+
+test('jobBacklogs still answers with the forced indexes in place', async () => {
+  // The plans above say which index; this says the numbers survived the change.
+  const now = nowIso();
+  await db.execute({
+    sql: `insert into feeds (id, slug, title, feed_url, status, next_fetch_at, created_at, updated_at)
+          values (?, 'a', 'A', 'https://a.example/feed', 'pending', ?, ?, ?)`,
+    args: [newId(), now, now, now],
+  });
+
+  const backlogs = await q.jobBacklogs(db);
+
+  assert.equal(typeof backlogs.submittedLastHour, 'number');
+  assert.equal(backlogs.submittedLastHour, 1);
+  assert.equal(typeof backlogs.pendingFirstCrawl, 'number');
+  assert.equal(typeof backlogs.authorsDone, 'number');
+  assert.equal(typeof backlogs.authorsLastHour, 'number');
+});