diff --git a/docs/ops/measurement-maintenance.md b/docs/ops/measurement-maintenance.md index d6a7865eb..eb95cb053 100644 --- a/docs/ops/measurement-maintenance.md +++ b/docs/ops/measurement-maintenance.md @@ -151,7 +151,8 @@ SELECT pg_size_pretty(pg_total_relation_size('measurements')) AS total, ## The nightly check Since v1.43.7 the same queue also runs by itself at 03:40 (Europe/Berlin). -That run names no steps and changes nothing: vacuuming the table is +That run names no steps and changes nothing beyond dropping a retired index +(next section): vacuuming the table is autovacuum's job, which migration 0412 starts at 5 % dead rows instead of Postgres's 20 %. The check reads the table's live and dead rows and warns (`maintenance_autovacuum_behind` on the wide event) when there are at least @@ -185,6 +186,63 @@ FROM pg_stat_user_tables WHERE relname = 'measurements'; applies to pages written after the migration; a `VACUUM FULL` after the upgrade applies it to the whole table. +## Retired indexes + +An index the schema no longer declares has to leave the database too, and on +`measurements` the obvious migration is the wrong one. A plain `DROP INDEX` +needs an exclusive lock on the table; `DROP INDEX CONCURRENTLY` blocks nobody +but waits, without limit, for every transaction already running on the +table. A migration runs at boot, so either one waits for whatever holds the +table (a `pg_dump`, a long backfill, a `VACUUM FULL`); past the container's +start period the container is replaced with the migration half done, and the +next boot stops at `P3009` until someone runs `prisma migrate resolve`. + +So an index is retired in two halves (v1.43.8, migration 0416, for +`measurements_user_id_type_measured_at_idx`): + +1. The migration tries a plain `DROP INDEX IF EXISTS` inside a `DO` block with + a two-second `lock_timeout` and catches the timeout + (`EXCEPTION WHEN lock_not_available`). When nothing holds the table the + index is gone at once; otherwise the migration still succeeds and the + index stays. The longest the table's other statements can wait behind the + attempt is those two seconds. A new database and Prisma's shadow database + always take the lock, so the migration history ends without the index, + exactly as the schema does, and `prisma migrate dev` / `migrate diff` see + no drift and generate nothing. +2. The index name goes into `RETIRED_MEASUREMENT_INDEXES` in + `src/lib/jobs/measurement-maintenance.ts`. Every run of this job, the + nightly 03:40 check included, drops each name still present with + `DROP INDEX CONCURRENTLY IF EXISTS`, waiting at most 60 seconds for its + locks. A run that runs out of time leaves the index (possibly marked + invalid, which the next drop finishes), sets + `maintenance_retired_index_pending` on the wide event with a warning, and + the next night tries again. The index costs writes until then, as it did + before the release; nothing reads it. + +Until the job has run, the database holds one index the schema does not +declare. Nothing compares the two at runtime, and the only place they are +compared, a `migrate diff` against the migration history, never sees it. To +check by hand: + +```sql +SELECT indexname FROM pg_indexes + WHERE tablename = 'measurements' + AND indexname = 'measurements_user_id_type_measured_at_idx'; +``` + +No row: it is gone. To drop it now rather than at night, start a run from the +admin card (any steps), or run the same statement yourself: + +```sql +SET lock_timeout = '60s'; +DROP INDEX CONCURRENTLY IF EXISTS "measurements_user_id_type_measured_at_idx"; +``` + +For the next large index, follow the same two halves. +`src/__tests__/migration-lock-timeout-guard.test.ts` refuses a +`DROP INDEX CONCURRENTLY` in any migration and requires every retired name to +have a migration that bounds its wait and catches the timeout. + ## "could not resize shared memory segment" Up to v1.42.0 the run could stop at once with `could not resize shared memory diff --git a/prisma/migrations/0416_drop_measurements_type_prefix_index/migration.sql b/prisma/migrations/0416_drop_measurements_type_prefix_index/migration.sql index ff86f6c2c..62339c211 100644 --- a/prisma/migrations/0416_drop_measurements_type_prefix_index/migration.sql +++ b/prisma/migrations/0416_drop_measurements_type_prefix_index/migration.sql @@ -1,4 +1,4 @@ --- Drop `measurements_user_id_type_measured_at_idx`. +-- Retire `measurements_user_id_type_measured_at_idx`. -- -- `(user_id, type, measured_at)` is the leading part of the unique key -- `(user_id, type, measured_at, source, sleep_stage)`, and live reads have @@ -8,10 +8,28 @@ -- seeded table). The index cost every write to the densest table in the -- schema and, on a bloated instance, more space than the table itself. -- --- `DROP INDEX CONCURRENTLY` takes no lock that blocks reads or writes: it --- waits for the transactions already using the index to finish and then --- removes it. It refuses to run inside a transaction block, and under --- `migrate deploy` it does so whenever the file holds any other statement --- (Prisma 7 on Postgres 16 reports 25001), so this file holds exactly this --- one statement. `IF EXISTS` makes a re-run a no-op. -DROP INDEX CONCURRENTLY IF EXISTS "measurements_user_id_type_measured_at_idx"; +-- This runs at boot, so it must not wait on the table. A plain `DROP INDEX` +-- needs ACCESS EXCLUSIVE on `measurements`, held for the instant the catalog +-- changes; `DROP INDEX CONCURRENTLY` blocks nobody but waits, without bound, +-- for every transaction on the table (a pg_dump, a backfill), long enough for +-- the container to be replaced mid-migration and the next boot to stop at +-- P3009. So the drop is tried once with a two-second lock wait (the most the +-- table's other statements can queue behind the request), and a timeout is +-- swallowed: the migration then succeeds with the index still there, and +-- the nightly measurement maintenance drops it with +-- `DROP INDEX CONCURRENTLY IF EXISTS` (`RETIRED_MEASUREMENT_INDEXES` in +-- `src/lib/jobs/measurement-maintenance.ts`). A fresh database and Prisma's +-- shadow database take the lock at once, so the migration history ends +-- without the index, as the schema does. The pattern, for the next large +-- index: docs/ops/measurement-maintenance.md, "Retired indexes". +-- +-- @retry-on-lock-timeout + +DO $migration$ +BEGIN + PERFORM set_config('lock_timeout', '2s', true); + DROP INDEX IF EXISTS "measurements_user_id_type_measured_at_idx"; +EXCEPTION WHEN lock_not_available THEN + RAISE NOTICE 'measurements_user_id_type_measured_at_idx is in use; the nightly measurement maintenance drops it'; +END +$migration$; diff --git a/src/__tests__/migration-lock-timeout-guard.test.ts b/src/__tests__/migration-lock-timeout-guard.test.ts index 45c7595bf..919e7661f 100644 --- a/src/__tests__/migration-lock-timeout-guard.test.ts +++ b/src/__tests__/migration-lock-timeout-guard.test.ts @@ -23,6 +23,8 @@ import { readdirSync, readFileSync, existsSync } from "node:fs"; import { join } from "node:path"; import { describe, expect, it } from "vitest"; +import { RETIRED_MEASUREMENT_INDEXES } from "@/lib/jobs/measurement-maintenance"; + import { RETRY_MARKER } from "../../scripts/migrate-deploy.mjs"; const MIGRATIONS_DIR = join(process.cwd(), "prisma", "migrations"); @@ -114,13 +116,14 @@ describe("concurrent index statements", () => { expect(found, found.join("\n")).toEqual([]); }); - it("sees the concurrent migrations there are", () => { - const concurrent = migrations() - .filter(({ sql }) => - /\bCONCURRENTLY\b/i.test(topLevelStatements(sql).join(";")), - ) - .map(({ name }) => name); - expect(concurrent).toContain("0416_drop_measurements_type_prefix_index"); + it("reads the statements there are", () => { + // No migration holds a concurrent statement since 0416 stopped dropping + // concurrently; the rule stands for the next one. A reader that stopped + // splitting statements would see none and pass, so it must see many. + const statements = migrations().flatMap(({ sql }) => + topLevelStatements(sql), + ); + expect(statements.length).toBeGreaterThan(1000); }); it("refuses a concurrent statement beside another one", () => { @@ -139,6 +142,58 @@ describe("concurrent index statements", () => { }); }); +/** + * `DROP INDEX CONCURRENTLY` blocks no reader or writer, but it waits without + * bound for every transaction on the table, and in a migration that wait is + * the boot's: a pg_dump or a backfill outlasts the container's start period, + * the half-applied migration is left on record, and the next boot stops at + * P3009. An index is retired instead by a bounded `DROP INDEX` that tolerates + * the timeout, finished by the nightly measurement maintenance (0416). + */ +function concurrentDropViolations(name: string, sql: string): string[] { + return topLevelStatements(sql).some((statement) => + /^DROP INDEX CONCURRENTLY\b/i.test(statement), + ) + ? [`${name}: DROP INDEX CONCURRENTLY waits on the table at boot`] + : []; +} + +describe("retired indexes", () => { + it("are never dropped concurrently in the boot path", () => { + const found = migrations().flatMap(({ name, sql }) => + concurrentDropViolations(name, sql), + ); + expect(found, found.join("\n")).toEqual([]); + }); + + it("are each dropped by a migration that bounds its wait and tolerates the timeout", () => { + expect(RETIRED_MEASUREMENT_INDEXES.length).toBeGreaterThan(0); + for (const index of RETIRED_MEASUREMENT_INDEXES) { + const owner = migrations().find(({ sql }) => + new RegExp(`DROP INDEX IF EXISTS "${index}"`).test(sql), + ); + expect(owner, index).toBeDefined(); + expect(owner?.sql).toMatch(/set_config\(\s*'lock_timeout'/); + expect(owner?.sql).toMatch(/EXCEPTION WHEN lock_not_available THEN/); + } + }); + + it("counter-check: refuses a concurrent drop, not one in a comment", () => { + expect( + concurrentDropViolations( + "a", + 'DROP INDEX CONCURRENTLY IF EXISTS "measurements_x_idx";', + ), + ).toHaveLength(1); + expect( + concurrentDropViolations( + "b", + '-- DROP INDEX CONCURRENTLY "x";\nDROP INDEX IF EXISTS "x";', + ), + ).toEqual([]); + }); +}); + describe("migration lock waits", () => { it("bounds lock waits where they take effect and marks only repeatable files", () => { const found = migrations().flatMap(({ name, sql }) => @@ -154,6 +209,7 @@ describe("migration lock waits", () => { expect(marked).toContain("0412_measurement_hot_updates"); expect(marked).toContain("0414_drop_medication_compliance_rollups"); expect(marked).toContain("0415_foreign_key_and_prefix_indexes"); + expect(marked).toContain("0416_drop_measurements_type_prefix_index"); }); it("catches each shape it exists to refuse", () => { diff --git a/src/lib/jobs/measurement-maintenance.ts b/src/lib/jobs/measurement-maintenance.ts index a5e4efa0f..144427b66 100644 --- a/src/lib/jobs/measurement-maintenance.ts +++ b/src/lib/jobs/measurement-maintenance.ts @@ -46,6 +46,15 @@ * before the first rebuild. * - Every step's size before and after, and its duration, are on the run's * wide event; the totals are job facts. + * + * Retired indexes. An index the schema no longer declares is dropped by the + * migration that retires it only when the lock is there at once (a `DO` + * block with a two-second `lock_timeout` that swallows the timeout), so the + * boot never waits on a long reader of the table. Where the migration had to + * leave it, every run of this job, the nightly tick included, drops it with + * `DROP INDEX CONCURRENTLY IF EXISTS` under a bounded lock wait and tries + * again the next night if the wait runs out. Runbook: + * `docs/ops/measurement-maintenance.md`, "Retired indexes". */ import { Client } from "pg"; import type { Job } from "pg-boss"; @@ -153,6 +162,22 @@ export function maintenanceSessionStatements(): string[] { }); } +/** + * Indexes on `measurements` the schema no longer declares, which a run drops + * when the migration that retired them could not. Each one's migration names + * it; `IF EXISTS` makes the drop a no-op once it is gone. + */ +export const RETIRED_MEASUREMENT_INDEXES: readonly string[] = [ + // 0416: a prefix of the unique key `(user_id, type, measured_at, source, + // sleep_stage)`, which plans every query it served at the same cost. + "measurements_user_id_type_measured_at_idx", +]; + +/** How long a run waits for the locks that drop a retired index. */ +export const RETIRED_INDEX_LOCK_TIMEOUT = "60s"; + +const LOCK_TIMEOUT_VALUE = /^\d{1,6}(ms|s)$/; + /** The only shape an index name may have before it is spliced into SQL. */ const INDEX_NAME = /^[a-z0-9_]{1,63}$/; @@ -162,7 +187,7 @@ const CONCURRENT_COPY = /_ccnew\d*$|_ccold\d*$/; const PURGE_QUEUE = "compaction-tombstone-purge"; export interface MaintenanceStep { - step: "vacuum" | "reindex" | "drop_invalid"; + step: "vacuum" | "reindex" | "drop_invalid" | "drop_retired"; target: string; bytesBefore: number; bytesAfter: number; @@ -336,6 +361,62 @@ async function dropInvalidCopies( } } +/** + * Drop every retired index still present. `DROP INDEX CONCURRENTLY` takes no + * lock that stops reads or writes, but it waits for every transaction that + * may use the index, so the wait is bounded for the statement and the + * session's own setting is put back after it. A timed-out drop may leave the + * index marked invalid; the next run's `IF EXISTS` drop finishes it. + */ +export async function dropRetiredIndexes( + db: MaintenanceConnection, + steps: MaintenanceStep[], + lockTimeout: string = RETIRED_INDEX_LOCK_TIMEOUT, +): Promise { + if (!LOCK_TIMEOUT_VALUE.test(lockTimeout)) { + throw new Error(`refusing lock timeout of unexpected shape`); + } + for (const name of RETIRED_MEASUREMENT_INDEXES) { + const bytesBefore = await indexBytes(db, name); + const { rows } = await db.query<{ present: boolean }>( + `SELECT to_regclass($1) IS NOT NULL AS present`, + [name], + ); + if (!rows[0]?.present) continue; + const { rows: setting } = await db.query<{ value: string }>( + `SELECT current_setting('lock_timeout') AS value`, + ); + const startedAt = Date.now(); + try { + await db.query(`SET lock_timeout = '${lockTimeout}'`); + await db.query(`DROP INDEX CONCURRENTLY IF EXISTS ${quoted(name)}`); + steps.push({ + step: "drop_retired", + target: name, + bytesBefore, + bytesAfter: 0, + durationMs: Date.now() - startedAt, + ok: true, + }); + } catch (err) { + logCaught("measurements.maintenance.drop_retired_failed", err); + steps.push({ + step: "drop_retired", + target: name, + bytesBefore, + bytesAfter: await indexBytes(db, name), + durationMs: Date.now() - startedAt, + ok: false, + error: errorText(err), + }); + } finally { + await db.query(`SELECT set_config('lock_timeout', $1, false)`, [ + setting[0]?.value ?? "0", + ]); + } + } +} + /** * The pass itself, on a connection the caller opened with * {@link MAINTENANCE_SESSION_OPTIONS}. Exported for the integration test. @@ -343,7 +424,7 @@ async function dropInvalidCopies( export async function runMeasurementMaintenance( db: MaintenanceConnection, payload: MaintenanceSteps, - options: { shouldStop?: () => boolean } = {}, + options: { shouldStop?: () => boolean; retiredLockTimeout?: string } = {}, ): Promise { const before = await relationSizes(db); const steps: MaintenanceStep[] = []; @@ -359,6 +440,10 @@ export async function runMeasurementMaintenance( indexBytesAfter: after.indexes, }); + // Every run, the nightly tick included: a retired index costs every write + // until it is gone, and the drop blocks no reader or writer. + await dropRetiredIndexes(db, steps, options.retiredLockTimeout); + if (!payload.vacuum && !payload.reindex) return summary("nothing_due"); // The queue table exists wherever a worker has started; a database without @@ -406,7 +491,10 @@ export async function runMeasurementMaintenance( if (payload.reindex) { await dropInvalidCopies(db, steps); const targets = (await measurementIndexes(db)).filter( - (index) => index.valid && !CONCURRENT_COPY.test(index.name), + (index) => + index.valid && + !CONCURRENT_COPY.test(index.name) && + !RETIRED_MEASUREMENT_INDEXES.includes(index.name), ); for (const index of targets) { if (options.shouldStop?.()) break; @@ -509,6 +597,15 @@ export async function handleMeasurementMaintenance( ); } } + const retiredLeft = result.steps.filter( + (s) => s.step === "drop_retired" && !s.ok, + ); + if (retiredLeft.length > 0) { + evt.addMeta("maintenance_retired_index_pending", true); + evt.addWarning( + `retired index ${retiredLeft.map((s) => s.target).join(", ")} could not be dropped within ${RETIRED_INDEX_LOCK_TIMEOUT} (a long transaction on measurements); the next nightly run tries again`, + ); + } evt.addMeta("maintenance_table_bytes_before", result.tableBytesBefore); evt.addMeta("maintenance_table_bytes_after", result.tableBytesAfter); evt.addMeta("maintenance_index_bytes_before", result.indexBytesBefore); diff --git a/tests/integration/retired-index-drop.test.ts b/tests/integration/retired-index-drop.test.ts new file mode 100644 index 000000000..4ac6bb800 --- /dev/null +++ b/tests/integration/retired-index-drop.test.ts @@ -0,0 +1,140 @@ +/** + * Retiring an index on `measurements` without the boot waiting on the table. + * + * Migration 0416 drops `measurements_user_id_type_measured_at_idx` only when + * the lock is there at once and otherwise leaves it, successfully; the + * nightly measurement maintenance drops what is left with + * `DROP INDEX CONCURRENTLY IF EXISTS` under a bounded lock wait. Proven here + * against Postgres, each with the transaction that used to hold the boot: + * the migration finishes while a reader holds the table and drops the index + * once it does not; the maintenance step gives up within its wait, puts the + * session's lock timeout back, and drops the index on the next run. + */ +import { readFileSync } from "node:fs"; +import { join } from "node:path"; +import { Client } from "pg"; +import { afterEach, beforeEach, describe, expect, it } from "vitest"; + +import { + MAINTENANCE_SESSION_OPTIONS, + RETIRED_MEASUREMENT_INDEXES, + runMeasurementMaintenance, +} from "@/lib/jobs/measurement-maintenance"; + +const INDEX = "measurements_user_id_type_measured_at_idx"; +const MIGRATION = readFileSync( + join( + process.cwd(), + "prisma/migrations/0416_drop_measurements_type_prefix_index/migration.sql", + ), + "utf8", +); + +function connect(options?: string): Client { + const url = new URL(process.env.DATABASE_URL ?? ""); + url.searchParams.delete("schema"); + return new Client({ connectionString: url.toString(), options }); +} + +async function present(db: Client): Promise { + const { rows } = await db.query<{ present: boolean }>( + `SELECT to_regclass($1) IS NOT NULL AS present`, + [INDEX], + ); + return rows[0].present; +} + +let db: Client; +let holder: Client; + +beforeEach(async () => { + db = connect(MAINTENANCE_SESSION_OPTIONS); + holder = connect(); + await db.connect(); + await holder.connect(); + // The state on an instance that has not run 0416 yet. + await db.query( + `CREATE INDEX IF NOT EXISTS "${INDEX}" ON "measurements" ("user_id", "type", "measured_at")`, + ); +}); + +afterEach(async () => { + await holder.query("ROLLBACK").catch(() => {}); + await holder.end(); + await db.query(`DROP INDEX IF EXISTS "${INDEX}"`); + await db.end(); +}); + +describe("migration 0416", () => { + it("finishes while a reader holds the table and leaves the index", async () => { + await holder.query("BEGIN"); + await holder.query(`SELECT count(*) FROM "measurements"`); + + const startedAt = Date.now(); + await db.query(MIGRATION); + + expect(Date.now() - startedAt).toBeLessThan(10_000); + expect(await present(db)).toBe(true); + }); + + it("counter-check: drops the index when nothing holds the table", async () => { + await db.query(MIGRATION); + expect(await present(db)).toBe(false); + // And again, as a retried boot would. + await db.query(MIGRATION); + }); +}); + +describe("the maintenance step for a retired index", () => { + it("names the index the migration retires", () => { + expect(RETIRED_MEASUREMENT_INDEXES).toContain(INDEX); + }); + + it("gives up within its wait, restores the session, and drops it on the next run", async () => { + await holder.query("BEGIN"); + await holder.query( + `LOCK TABLE "measurements" IN SHARE UPDATE EXCLUSIVE MODE`, + ); + + const blocked = await runMeasurementMaintenance( + db, + { vacuum: false, reindex: false }, + { retiredLockTimeout: "300ms" }, + ); + expect(blocked.outcome).toBe("nothing_due"); + expect(blocked.steps).toEqual([ + expect.objectContaining({ + step: "drop_retired", + target: INDEX, + ok: false, + error: expect.stringContaining("55P03"), + }), + ]); + // The session's own wait (five minutes) is back for the rest of the run. + const { rows } = await db.query<{ value: string }>( + `SELECT current_setting('lock_timeout') AS value`, + ); + expect(rows[0].value).toBe("5min"); + + await holder.query("ROLLBACK"); + const next = await runMeasurementMaintenance(db, { + vacuum: false, + reindex: false, + }); + expect(next.steps).toEqual([ + expect.objectContaining({ + step: "drop_retired", + target: INDEX, + ok: true, + }), + ]); + expect(await present(db)).toBe(false); + + // Gone: the run after that has nothing to do. + const after = await runMeasurementMaintenance(db, { + vacuum: false, + reindex: false, + }); + expect(after.steps).toEqual([]); + }); +});