Skip to content

Partition the two Query Store interval tables by day on first_execution_time, so retention drops a day instead of deleting its rows #5571

Closed

Description

@erikdarlingdata

Claude posting for Erik Darling.

The two Query Store interval tables are plain heaps, and retention removes their old rows with DELETE. On a large store this is the heaviest write the retention pass does. On the wide table it now fails on every pass (#5569). If each table is partitioned by day on first_execution_time, retention drops a whole day. It deletes no rows, makes no dead tuples and writes almost no WAL.

What happens today

Measured

On a store that monitors 43 SQL Server primaries, build 3.10.0-nightly.20261008.533, 10-08 about 14:10Z. All reads were read-only.

query_store_interval_wide query_store_interval_latest
Heap 91 GB 34 GB
Indexes 15 GB 15 GB
Live rows 88.2 M 97.9 M
Dead tuples 1.8 M 0.26 M
Rows per day (wide, measured 10-06) 7.2 to 8.0 M
Rows past the horizon now 15.6 M (oldest 09-27 13:05) 0 (oldest 09-26, horizon 09-23)
  • The wide purge has removed 0 rows since 10-06. It timed out on all 4 passes since then (The retention purge of the wide Query Store table times out on every pass on a large store and removes nothing #5569).
  • Reading the expired keys alone is expensive. An index-only scan of the expired rows on the wide table took 120.8 s. It read 530,743 pages, made 3,775,762 heap fetches and dirtied 491,320 pages (3.8 GB) to set hint bits. The DELETE then adds the row writes, the WAL and the vacuum.
  • The retention pass writes a lot of WAL. The whole pass wrote 6,790 MB at 13:09Z and 1,386 MB at 13:50Z. That is all tables, not only these two.

Why day partitions fit these two tables

  • A row never changes its partition. The upsert never rewrites server_id or first_execution_time. That is why its updates stay HOT (QueryStoreBackgroundIndexes, Plan regression day totals: each build reads the server's whole index slice on a large store #5507).
  • The upsert keeps working. PostgreSQL requires that a unique index on a partitioned table includes the partition key. first_execution_time is already in both unique indexes (ux_query_store_interval_wide, ux_query_store_interval_latest), so ON CONFLICT stays valid.
  • Retention becomes DROP TABLE (or DETACH PARTITION) of each expired day. That costs no row deletes, no dead tuples and no vacuum debt, and the time does not grow with the day's size.

Proposed shape

Upgrade path on a large store

  • A rewrite in a migration rung is not possible. The startup migration cancels after MigrationCommandTimeoutSeconds (300 s) of silence, and the wide table is 91 GB.
  • Proposed path, with no data copy:
    1. Create the partitioned parent.
    2. Attach the current table as one legacy partition for the range up to the switch day. First add a matching CHECK constraint NOT VALID and validate it in the background, because a validated constraint lets the attach skip its scan and hold its lock only briefly.
    3. New days go to new daily partitions.
    4. When the legacy partition's newest row is past the horizon (9 days for wide, 15 for latest), drop it in one statement.
  • Until then, the legacy partition still needs the The retention purge of the wide Query Store table times out on every pass on a large store and removes nothing #5569 row-capped purge.

Costs to check

Not in scope

Acceptance

  1. Retention removes expired days of both tables by dropping partitions. It runs no row DELETE on them, except on the legacy partition until that partition is dropped.
  2. No upsert is refused when a day's partition is missing.
  3. An upgrade of a store with a 91 GB wide table finishes within the migration silence limit, with no data copy.
  4. The reads that bound first_execution_time show partition pruning to the window's days, with an EXPLAIN on a large store for each one.
  5. The HOT live tests for both tables still pass.

Activity

  1. erikdarlingdata commented on Oct 8, 2026

    @erikdarlingdata
    OwnerAuthor

    Claude posting for Erik Darling.

    This is the baseline script for the partition change. It runs the shipped reads of both interval tables against a large store as it is today, before any partitions exist. The same script runs again on the partitioned copy, and the two results are compared.

    It also measures the one slow step of the upgrade. A background step checks every row of the old table once. Section 9 reads a 1% sample of the wide table, so 100 times its time estimates that check. The WAL it writes is recorded too.

    Nothing in it writes data. The session is read-only, and each statement stops at 120 seconds. Set sid, the two window times and the day start near the top first. Section 5 also needs a real database name and query id.

    Please paste back each plan's shape, buffers, planning time and execution time, and the results of sections 0 and 10.

    explain-5571.sql
    -- #5571 baseline: read-only EXPLAINs of the Query Store interval-table reads, on TODAY's unpartitioned tables.
    -- Run with psql on the large store. Nothing here writes. ASCII only. Needs no unmerged migration.
    -- Re-run the same file on the partitioned rehearsal copy and compare plan shape, buffers, planning time and
    -- "Subplans Removed".
    -- Margins copied from origin/dev QueryStoreIntervalWide.cs: PurgeEdgeMargin 26 h (1560 min),
    -- FirstExecUpperSlack 12 h (720 min), IntervalStartSlack 60 min, IntervalStartFirstExecMargin 25 h (1500 min);
    -- QueryStoreTopDaily.SkewSlack 60 min.
    -- Select lists are reduced to aggregates; the WHERE clauses are the shipped ones.
    \set ON_ERROR_STOP off
    \pset pager off
    \timing on
    -- Each statement runs on its own (no wrapping transaction), so a timeout in one does not abort the rest.
    SET default_transaction_read_only = on;
    SET statement_timeout = '120s';
    
    -- Fill these first. sid = a busy server_id. Windows are naive UTC: set them to the last 24 hours and today.
    \set sid 1
    \set win_start '''2026-10-07 14:00:00'''
    \set win_end   '''2026-10-08 14:00:00'''
    \set day_start '''2026-10-07 00:00:00'''
    
    -- 0. Shape facts (catalog only).
    SELECT c.relname, c.relkind, pg_size_pretty(pg_total_relation_size(c.oid)) AS total, c.reltuples::bigint
    FROM pg_class c JOIN pg_namespace n ON n.oid = c.relnamespace
    WHERE n.nspname = 'collect' AND c.relname IN ('query_store_interval_wide', 'query_store_interval_latest');
    SELECT indexrelid::regclass, indisvalid, pg_size_pretty(pg_relation_size(indexrelid))
    FROM pg_index WHERE indrelid IN ('collect.query_store_interval_wide'::regclass, 'collect.query_store_interval_latest'::regclass);
    SELECT tgname, tgrelid::regclass FROM pg_trigger
    WHERE tgrelid IN ('collect.query_store_interval_wide'::regclass, 'collect.query_store_interval_latest'::regclass) AND NOT tgisinternal;
    SELECT d.classid::regclass, d.objid, d.deptype FROM pg_depend d
    WHERE d.refobjid IN ('collect.query_store_interval_wide'::regclass, 'collect.query_store_interval_latest'::regclass)
    AND d.classid = 'pg_rewrite'::regclass;  -- views that would follow a RENAME (expect 0 rows)
    
    -- 1. Compose wide route (ComposeCompiler.cs:255): collection_time only, NO first_execution_time bound.
    EXPLAIN (ANALYZE, BUFFERS, SETTINGS, SUMMARY)
    SELECT count(*), sum(w.execution_count)
    FROM collect.query_store_interval_wide AS w
    JOIN collect.servers AS s ON s.server_id = w.server_id
    WHERE w.collection_time >= :win_start AND w.collection_time <= :win_end;
    
    -- 2. Read-gate floors (QueryStoreIntervalWide.cs:459, QueryStoreIntervalLatest.cs:350): unbounded MIN.
    EXPLAIN (ANALYZE, BUFFERS, SUMMARY) SELECT MIN(t.first_execution_time) FROM collect.query_store_interval_wide AS t WHERE t.server_id = :sid;
    EXPLAIN (ANALYZE, BUFFERS, SUMMARY) SELECT MIN(t.first_execution_time) FROM collect.query_store_interval_latest AS t WHERE t.server_id = :sid;
    
    -- 3. Viewer Query Store grid (ViewerDataService.QueryStore.cs:211) and MCP twin (DarlingDataReader.cs:2598).
    EXPLAIN (ANALYZE, BUFFERS, SUMMARY)
    SELECT database_name, query_id, sum(execution_count), sum(avg_cpu_time_us * execution_count)
    FROM collect.query_store_interval_wide
    WHERE server_id = :sid
    AND   collection_time >= :win_start AND collection_time <= :win_end
    AND   first_execution_time >= :win_start::timestamp - interval '1560 minutes'
    AND   first_execution_time <= :win_end::timestamp + interval '720 minutes'
    GROUP BY database_name, query_id;
    
    -- 4. Query trends, interval_start arm (ViewerDataService.QueryTrends.cs:365).
    EXPLAIN (ANALYZE, BUFFERS, SUMMARY)
    SELECT date_trunc('hour', interval_start_time_utc), sum(execution_count)
    FROM collect.query_store_interval_wide
    WHERE server_id = :sid
    AND   interval_start_time_utc >= :win_start AND interval_start_time_utc <= :win_end
    AND   interval_start_time_utc IS NOT NULL
    AND   first_execution_time >= :win_start::timestamp - interval '60 minutes'
    AND   first_execution_time <= :win_end::timestamp + interval '1500 minutes'
    GROUP BY 1;
    
    -- 5. MCP query history (DarlingMcpQueryStoreHistoryTools.cs:113). Fill a real database_name and query_id.
    \set dbname '''REPLACE_DB'''
    \set qid 0
    EXPLAIN (ANALYZE, BUFFERS, SUMMARY)
    SELECT count(*) FROM collect.query_store_interval_wide
    WHERE server_id = :sid AND database_name = :dbname AND query_id = :qid
    AND collection_time >= :win_start AND collection_time <= :win_end
    AND first_execution_time >= :win_start::timestamp - interval '1560 minutes'
    AND first_execution_time <= :win_end::timestamp + interval '720 minutes';
    
    -- 6. Daily top builder (QueryStoreTopDaily.cs:129).
    EXPLAIN (ANALYZE, BUFFERS, SUMMARY)
    SELECT w.database_name, w.query_id, sum(w.execution_count)
    FROM collect.query_store_interval_wide AS w
    WHERE w.server_id = :sid
    AND   w.collection_time >= :day_start::timestamp AND w.collection_time < :day_start::timestamp + interval '1 day'
    AND   w.first_execution_time >= :day_start::timestamp - interval '1560 minutes'
    AND   w.first_execution_time < :day_start::timestamp + interval '1 day' + interval '60 minutes'
    GROUP BY w.database_name, w.query_id;
    
    -- 7. PLAN_REGRESSION daily build (PlanRegressionDaily.cs:93), latest table.
    EXPLAIN (ANALYZE, BUFFERS, SUMMARY)
    SELECT l.plan_id, sum(l.execution_count)
    FROM collect.query_store_interval_latest AS l
    WHERE l.server_id = :sid
    AND   l.first_execution_time >= :day_start::timestamp - interval '1 day'
    AND   l.first_execution_time < :day_start::timestamp + interval '1 day'
    AND   l.last_execution_time >= :day_start::date
    AND   l.last_execution_time < :day_start::timestamp + interval '1 day'
    AND   l.collection_time >= :day_start::timestamp - interval '1 day'
    GROUP BY l.plan_id;
    
    -- 8. Analysis fact + drill-down reads (PgFactCollector.QueryPerf.cs:440, PgDrillDownCollector.Queries.cs:874):
    --    lower bounds only, so after partitioning they also scan future days and the DEFAULT partition.
    EXPLAIN (ANALYZE, BUFFERS, SUMMARY)
    SELECT count(*), sum(execution_count) FROM collect.query_store_interval_latest
    WHERE server_id = :sid
    AND last_execution_time >= :win_start
    AND collection_time >= :win_start::timestamp - interval '1 day'
    AND first_execution_time >= :win_start::timestamp - interval '1 day';
    
    -- 9. The planning cost alone, for the partition-count comparison (run each 5x, read "Planning Time").
    EXPLAIN (SUMMARY) SELECT count(*) FROM collect.query_store_interval_wide
    WHERE server_id = :sid AND first_execution_time >= :win_start::timestamp - interval '1560 minutes';
    EXPLAIN (SUMMARY) SELECT count(*) FROM collect.query_store_interval_latest
    WHERE server_id = :sid AND first_execution_time >= :win_start::timestamp - interval '1 day';
    
    -- 10. The VALIDATE cost proxy: heap read rate on a 1% block sample (not the whole 91 GB), and the WAL that
    --     setting hint bits writes when data checksums are on. Scale the time by 100 for the full VALIDATE.
    --     Note pg_current_wal_lsn() before and after.
    SELECT pg_current_wal_lsn();
    EXPLAIN (ANALYZE, BUFFERS, SUMMARY)
    SELECT count(*) FROM collect.query_store_interval_wide TABLESAMPLE SYSTEM (1)
    WHERE NOT (first_execution_time < now() AT TIME ZONE 'UTC' + interval '2 days');
    SELECT pg_current_wal_lsn();
    SHOW data_checksums;
    SHOW wal_log_hints;
  2. erikdarlingdata commented on Oct 8, 2026

    @erikdarlingdata
    OwnerAuthor

    Claude posting for Erik Darling.

    This is the runbook for the restored-copy test of the partition change. The copy is a restored snapshot of a large store, on a scratch instance. It is never the live store. The test has two steps. Step 1 is the upgrade path from 3.9 to 3.10 with the purge fix from #5572. Step 2 is the partition change.

    Before the service starts

    1. The scratch instance must have no outbound network except what its management access needs. The copy holds the real list of monitored servers and the real alert routes. With outbound network, the service collects from those servers and can send real alerts.
    2. On the copy, turn off collection and alert delivery as a second guard. Check the table names first with \dt config.*.
    UPDATE config.config_monitored_servers SET is_enabled = false;
    UPDATE config.config_notification_routes SET enabled = false;
    1. Turn on statement logging for the test (scratch instance only):
    ALTER SYSTEM SET log_min_duration_statement = 0;
    ALTER SYSTEM SET log_lock_waits = on;
    ALTER SYSTEM SET log_checkpoints = on;
    SELECT pg_reload_conf();
    1. Record the starting point:
    SELECT pg_current_wal_lsn();
    SELECT relname, n_live_tup, n_dead_tup, seq_scan, idx_scan FROM pg_stat_user_tables WHERE relname LIKE 'query_store_interval%';
    SELECT max(version) FROM collect.darling_schema_version;

    Step 1: upgrade from 3.9, and the purge fix

    Build: the head of PR #5572 (the sha comes with the message that sends this link). Start the service against the copy.

    Record:

    • the time of each migration rung (V166 to V170), from the service log and the statement log.
    • the time from start until migrations complete
    • the first retention pass, which runs right after start. Record it for each of the two interval tables.
    • for that pass: the time of each DELETE batch (from the statement log), the rows removed, and any "hit the command timeout" warning.
    • the pass's total time and the WAL it wrote (the LSN difference).

    Stop the service once the first retention pass ends. Record pg_stat_user_tables again.

    Step 2: the partition change

    Build: the head of the partition PR. It comes in a second message when it is ready.

    1. Turn on the debug line that shows the attach skipped its scan, for the rung only:
    ALTER SYSTEM SET log_min_messages = debug1;
    SELECT pg_reload_conf();
    1. Start the service. Record:
      • the time of each statement in rungs V171 and V172
      • the line "partition constraint for table ... is implied by existing constraints" for each of the two legacy tables (if it is missing, the attach scanned the table)
      • seq_scan on both _legacy tables before and after the rung (it must not change)
      • any lock wait.
    2. Set log_min_messages back to warning and reload.
    3. Leave the service running. After its 20-minute start delay, the background steps run. Record:
      • the arm step
      • the CHECK validation: its time and the WAL it writes
      • the promote step and its lock time
      • the daily partitions it creates
      • the ANALYZE time.
    4. Check the result:
    SELECT c.relname, pg_get_expr(c.relpartbound, c.oid) AS bound, pg_size_pretty(pg_total_relation_size(c.oid)) AS size
    FROM pg_inherits AS i JOIN pg_class AS c ON c.oid = i.inhrelid
    WHERE i.inhparent IN ('collect.query_store_interval_wide'::regclass, 'collect.query_store_interval_latest'::regclass)
    ORDER BY 1;
    SELECT count(*) FROM collect.query_store_interval_wide_default;
    SELECT count(*) FROM collect.query_store_interval_latest_default;
    1. Run the baseline script from this issue against the copy. Set its windows to times the copy holds. Paste its results next to the results from the live store.

    Tear the instance down afterwards.

  3. erikdarlingdata commented on Oct 8, 2026

    @erikdarlingdata
    OwnerAuthor

    Claude posting for Erik Darling.

    Baseline on today's unpartitioned tables is done. The slowest read is section 1, the Compose wide route, which has no first_execution_time bound: 53.0 s for one day. Every other read takes 0.1 to 2.0 s. The 1% sample in section 10 took 67.6 s and wrote 0.42 MB of its own WAL. Times 100 that is 1.9 h, but I think that overstates a sequential VALIDATE (see section 10).

    Setup:

    • Store: monitors 43 SQL Server primaries, build 3.10.0-nightly.20261008.533, 14:56 to 14:58Z.
    • Session: read-only. Each statement stopped at 120 s, and none reached it.
    • Inputs:
      • sid = the server with the most query_store rows in the last day.
      • win_start / win_end = 2026-10-07 14:00:00 / 2026-10-08 14:00:00.
      • day_start = 2026-10-07 00:00:00.
      • for section 5, the busiest query of that server's last day (database name and query id not shown here).

    Two changes to the script:

    • Section 9: each EXPLAIN runs 5 times, as its comment asks.
    • Section 10: its EXPLAIN adds WAL, so the hint-bit WAL is the statement's own. The LSN delta also counts every other writer on the store. It was 138 MB in the same 67 s, against the statement's 0.42 MB.

    0. Shape facts

    Table relkind Total reltuples
    query_store_interval_wide r 107 GB 88,101,800
    query_store_interval_latest r 49 GB 97,781,792
    • Indexes, all valid:
      • wide: ux_query_store_interval_wide 11 GB, idx_query_store_interval_wide_first_exec 1,769 MB, ix_query_store_interval_wide_server_first_exec 2,559 MB, ix_query_store_interval_wide_collection_time_brin 3,144 kB.
      • latest: ux_query_store_interval_latest 11 GB, idx_query_store_interval_latest_first_exec 1,913 MB, ix_query_store_interval_latest_server_first_exec 2,422 MB.
    • Triggers: one, trg_plan_regression_daily_late on the latest table (V168).
    • Views that depend on either table (pg_rewrite): 0 rows.

    1 to 9. The reads

    # Read Top scan Rows Shared hit / read Planning Execution
    1 Compose wide route, collection_time only Parallel Bitmap Heap Scan on wide, from the BRIN on collection_time. Lossy, 1,221,006 heap blocks. Hash Join to servers (43 rows) 8,457,483 (Rows Removed by Index Recheck 550,719) 13,068 / 1,208,543 (9.2 GB), dirtied 168,113 2.5 ms 52,990.6 ms
    2a Read-gate floor, wide MIN Index Only Scan on ix_query_store_interval_wide_server_first_exec, Heap Fetches 20,607 1 11,970 / 3,213 0.24 ms 1,805.7 ms
    2b Read-gate floor, latest MIN Index Only Scan on ix_query_store_interval_latest_server_first_exec, Heap Fetches 0 1 5 / 0 0.82 ms 0.086 ms
    3 Viewer Query Store grid Bitmap Heap Scan on wide, BitmapAnd of the BRIN and ix_…_wide_server_first_exec. Lossy, 59,244 blocks 413,809, giving 45,777 groups 37,067 / 26,250 0.98 ms 1,705.8 ms
    4 Query trends, interval_start arm Parallel Bitmap Heap Scan on wide, from ix_…_wide_server_first_exec. Exact, 60,451 blocks 423,062, giving 25 buckets 59,932 / 2,392 3.98 ms 354.1 ms
    5 MCP query history Index Scan on ux_query_store_interval_wide, collection_time as a Filter (27 removed) 24 42 / 11,382 0.30 ms 1,912.8 ms
    6 Daily top builder Bitmap Heap Scan on wide, BitmapAnd of the BRIN and ix_…_wide_server_first_exec. Lossy, 58,331 blocks 399,718, giving 44,655 groups 35,884 / 26,569 0.23 ms 1,996.5 ms
    7 PLAN_REGRESSION daily build (latest) Parallel Bitmap Heap Scan on latest, from ix_…_latest_server_first_exec (#5507) 403,423, giving 48,313 groups 10,553 / 29,695 1.09 ms 442.7 ms
    8 Analysis fact and drill-down (latest, lower bounds only) Parallel Bitmap Heap Scan on latest, from ix_…_latest_server_first_exec 422,976 32,809 / 8,306 1.99 ms 299.5 ms
    9 Planning only, 5 runs each Parallel Index Only Scan on ix_*_server_first_exec wide 2.147 (first), 0.112, 0.072, 0.113, 0.089 ms. latest 0.090, 0.097, 0.096, 0.091, 0.124 ms

    Notes on the reads:

    10. The VALIDATE cost proxy

    Value
    Plan Sample Scan, Sampling: system ('1'), 0 rows (Rows Removed by Filter 890,868)
    Pages shared hit 7,308, read 113,319 (885 MB), dirtied 195, written 13
    Read I/O time 66,839 ms
    WAL from the statement records 490, FPI 241, 419,830 bytes
    Execution 67,633.5 ms
    data_checksums on
    wal_log_hints off
    LSN before / after 13E7/EA8CA608 / 13E7/F32CA000, 144,701,944 bytes for the whole store in that time
    • Times 100, the sample gives 6,763 s (1.9 h) and about 42 MB of hint-bit WAL.
    • I think the time overstates a real VALIDATE.
      • TABLESAMPLE SYSTEM reads a random 1% of blocks. That's random I/O: 885 MB in 66.8 s, about 13 MB/s.
      • VALIDATE reads the heap in order.
      • On the same table, read 1's lossy bitmap scan read 9.2 GB in 53 s, about 175 MB/s with 3 processes.
      • At 100 to 175 MB/s, the 91 GB heap is about 9 to 15 minutes.
      • That's an estimate. The restored copy will time the real VALIDATE.
    • The WAL figure is likely right in size. 93% of the wide heap's pages are all-visible (relallvisible 11,135,869 of 11,946,817 pages), so few hint bits are left to set.
  4. erikdarlingdata commented on Oct 8, 2026

    @erikdarlingdata
    OwnerAuthor

    Claude posting for Erik Darling.

    This records a measured slow read, so the tracker shows it now. On a large store, the Custom Views read of the Query Store wide table took 53.0 s for a one-day window across all servers.

    This issue partitions by first_execution_time, which cannot prune a read with no first_execution_time bound. The restored-copy test for this issue runs the same read again after partitioning. If it is still slow and the fix belongs to the partition change, the fix goes into #5573. If it does not, the read gets its own issue.

    The numbers are from the baseline run above (section 1).

  5. erikdarlingdata commented on Oct 8, 2026

    @erikdarlingdata
    OwnerAuthor

    Claude posting for Erik Darling.

    Step 1 on the restored copy: the row-capped drain cleared the whole wide-table backlog in one pass. That was 16,457,626 rows in 330 batches over 22 min. No batch came near the timeout: the slowest was 10.9 s against 300 s. The 3.9 to 3.10 rungs V166 to V170 took about 1.2 s.

    Setup:

    • The copy: a restored snapshot of a store monitoring 43 SQL Server primaries, taken 10-08 12:47Z at schema 165 (3.9.x nightly). It runs on a scratch instance of the same size, never the live store. Its whole data directory was read once before the test, so the timings don't include first-touch snapshot reads.
    • The build: PR The Query Store interval tables' retention purge deletes in row-capped batches #5572's head cdbaa5997, the full service, started 16:15:01Z against the copy.
    • Guards:
      • outbound blocked except the instance's management agent, verified from the service account.
      • every monitored server, alert setting, notification channel and listener turned off in the copy's store.
      • a minimal config file.
    • Other settings: TimescaleDB background workers were 0 on the copy. That doesn't affect the service's own retention sweep. log_min_duration_statement = 0 was on for the statement times below.

    Upgrade

    The first retention pass

    Table Rows removed Batches Finished
    query_store_plan_map 38,325 1 16:17:07
    query_store_text 28,717 1 16:22:43
    query_plan_dim 409,367 32 16:41:41
    query_store_interval_latest 0 (oldest row 09-26, horizon 09-23) 1 16:41:41
    query_store_interval_wide 16,457,626 330 17:03:42
    • The pass's summary line: Retention purge: 89 table(s) purged, 16936418 row(s) deleted, 0 chunk(s) dropped, 0 failed, 2852324ms; store WAL during the purge's batches: 11185 MB, paced 1218s at 4.8 MB/s.
    • No timeouts: there were no "hit the command timeout" warnings, and 0 tables failed.

    The wide drain, from the statement log (the execute lines of the DELETE … WHERE ctid IN (SELECT ctid … ORDER BY first_execution_time LIMIT 50000) batches):

    Batches min p50 p95 max sum
    330 365 ms 3,137 ms 8,647 ms 10,855 ms 1,316.8 s
    • The rate: about 14 to 16 batches a minute, which is about 12,500 rows per second.
    • The result: the oldest row moved from 2026-09-27 13:05:08.887 to 2026-09-29 16:16:10.89, just above the cutoff 2026-09-29 16:16Z.
    • WAL for the whole run (16:05:52 to 17:04:58): 15 GB by LSN difference. The service's own figure is 11,185 MB during the purge's batches.

    After the pass (pg_stat_user_tables, counters since the copy started):

    Table n_live_tup n_dead_tup n_tup_del seq_scan idx_scan
    wide 71,247,429 17,817,193 16,457,626 0 361
    latest 0 0 0 4 2

    Notes:

    • The dead tuples: the wide table now carries 17.8 M of them until autovacuum runs. No autovacuum ran on it during the test.
    • The latest table's 4 seq scans: the background CREATE INDEX CONCURRENTLY scans the heap twice, which would explain 2. I haven't found the other 2.
    • One slower statement at start: a WITH src AS (…) read took 55.6 s, from 16:15:14. Its text is cut off in the log. My guess is the start-up module-map refresh that reads procedure_stats, but I haven't confirmed it.

    Next: step 2, the partition build 2043dd3b2, on the same copy.

  6. erikdarlingdata commented on Oct 8, 2026

    @erikdarlingdata
    OwnerAuthor

    Claude posting for Erik Darling.

    Copy step 2b: the re-check after review round 1

    The build is the #5573 branch at 0cd56725b, merged locally with the #5580 branch at ff545c527 (#5578). Nothing is pushed.

    Review round 1 changed how the two tables reach promotion. The arm step now reads the legacy table's newest first_execution_time under its lock. The hourly pass promotes, or re-arms when S is less than 12 hours away. VALIDATE retries hourly. ANALYZE moved off the sweep loop. The V171 and V172 rungs did not change.

    1. The read the arm step now takes under its lock (read-only)

    EXPLAIN (ANALYZE, BUFFERS) SELECT max(first_execution_time) FROM collect.query_store_interval_wide_legacy;
    EXPLAIN (ANALYZE, BUFFERS) SELECT max(first_execution_time) FROM collect.query_store_interval_latest_legacy;
    SELECT conname, convalidated, pg_get_constraintdef(oid) FROM pg_constraint WHERE conname IN ('ck_query_store_interval_wide_legacy_before', 'ck_query_store_interval_latest_legacy_before');

    Expected: a backward index scan of idx_query_store_interval_wide_first_exec_legacy, well under 5 seconds. A heap scan is a defect.

    2. From the service log after the restart

    • The arm or re-arm line with its S, and any warning that S moved past the usual bound.
    • VALIDATE's start and end, and the promote result.
    • Where ANALYZE ran. It must not appear inside a convergence step.

    If step 2 already promoted both tables, this shows only the hourly pass. Item 1 still times the read.

    3. #5578: start-up timings

    • The time from service start to the first collection.
    • The slowest statement in the first 5 minutes.

    The same two numbers from step 1's restart are the "before".

  7. erikdarlingdata commented on Oct 8, 2026

    @erikdarlingdata
    OwnerAuthor

    Claude posting for Erik Darling.

    Step 2 on the restored copy (2043dd3b2): both tables are partitioned and promoted.

    • The rungs: V171 took 1.10 s and V172 20 ms, and neither attach scanned its table.
    • VALIDATE: 388.8 s on the wide table (91 GB) and 200.0 s on the latest table.
    • Promote: 83 ms and 33 ms.
    • The baseline reads come out about the same as on the live store, with one exception: the first per-server MIN on the wide table. That one is slow because step 1's drain left dead index entries, not because of the partitions.

    Setup:

    • The copy: the same restored copy as step 1, at schema 170, after step 1's drain. Same guards as step 1, re-verified before this start.
    • The run: the service started at 17:14:25Z. log_min_messages = debug1 was on for the rungs only. TimescaleDB background workers were 0.

    Rungs (statement log)

    Rung Statement time Notes
    V171 (wide) 1,101.9 ms 1,019 ms of it was a wait for AccessExclusiveLock behind an autovacuum of the wide table. The deadlock-timeout path cancelled the autovacuum (canceling autovacuum task … while scanning block 826051), and the rung then ran in about 80 ms.
    V172 (latest) 20.5 ms
    • Store ready: Postgres store ready (schema v172, 2 migration(s) applied) at 17:14:27.351, 1.46 s after the config load.
    • No scan at attach: both attaches logged partition constraint for table "…_legacy" is implied by existing constraints.
    • seq_scan on the legacy tables didn't change across the rungs: wide 0 → 0, latest 4 → 4.
    • Risk on a live store (my inference, not tested): the rung waits for AccessExclusiveLock on the whole table. A long read holding AccessShareLock, such as the 50 s Compose read below, would hold the rung up, and the rung would block new reads while it waits. Here the only holder was an autovacuum, and PG cancelled it after about 1 s.

    First retention pass after the restart

    • wide_legacy: 438,004 rows in 9 batches. latest_legacy: 0.
    • The pass: 89 table(s) purged, 478949 row(s) deleted, … 0 failed, 200636ms, with 756 MB of WAL.

    Background steps

    Table Arm (S) VALIDATE Promote ANALYZE (parent) Ended
    wide 17:34:29, S = 2026-10-10 00:00:00 388.8 s (ended 17:40:58.119) 83 ms (2 day partitions + DEFAULT) 8.2 s 17:41:06, Done (promoted at 2026-10-10 00:00:00)
    latest 17:41:06, S = 2026-10-10 00:00:00 200.0 s (ended 17:44:26.482) 33 ms (2 day partitions + DEFAULT) 0.6 s 17:44:27, Done
    • The partitioned indexes: after promotion, the collection_time BRIN and both server_first_exec indexes report 0 leaf index(es) built and attached in 0.0s; parent valid.
    • The VALIDATE rate: 388.8 s for the 91 GB heap is about 240 MB/s. That's faster than the 9 to 15 min I estimated from section 10 of the baseline.

    Layout after promotion:

    Parent Child Bound Size
    wide _legacy FROM (MINVALUE) TO ('2026-10-10 00:00:00') 106 GB
    wide _p20261010, _p20261011 one day each 32 kB each
    wide _default DEFAULT 32 kB, 0 rows
    latest the same four the same bounds _legacy 48 GB, the rest 32 kB each, _default 0 rows

    The question from the review (does the legacy table hold any first_execution_time at or after S?):

    • No. max(first_execution_time) is 2026-10-08 12:47:11.383 on both legacy tables, the snapshot time.
    • A probe for >= '2026-10-10 00:00:00' returns 0 rows.
    • The MAX read is an Index Only Scan Backward using idx_query_store_interval_wide_first_exec_legacy, with 1 heap fetch, 5 buffers, 1.9 ms.

    Baseline script re-run on the copy (runbook 2.6)

    • Inputs: the same sid and the same section-5 database and query as on the live store. Section 9 runs each EXPLAIN 5 times.
    • The window had to move: the copy holds data only up to 12:47Z, so the window is 2026-10-07 12:00 to 2026-10-08 12:00 (live: 14:00 to 14:00). day_start is the same, 2026-10-07.
    • The cache isn't comparable: the live store's cache was the live working set, and the copy's was whatever the warm-up and steps 1 and 2 left.
    # Read Live, unpartitioned Copy, partitioned Partitions in the plan
    1 Compose wide route (collection_time only) 52,990.6 ms 48,344.5 ms Parallel Append over all 4: legacy by the BRIN bitmap (lossy, read 1,191,064), 3 empty partitions seq-scanned (24 buffers each)
    2a Read-gate floor, wide MIN 1,805.7 ms (Heap Fetches 20,607) 19,571.7 ms (Heap Fetches 854,535). Re-run: 14.9 ms, then 3.4 ms Merge Append over all 4
    2b Read-gate floor, latest MIN 0.086 ms 594.9 ms (5 buffers, all read from disk) Merge Append over all 4
    3 Viewer Query Store grid 1,705.8 ms 2,081.8 ms legacy only (pruned)
    4 Query trends, interval_start arm 354.1 ms 412.4 ms legacy only
    5 MCP query history 1,912.8 ms 1,856.7 ms legacy only
    6 Daily top builder 1,996.5 ms 1,850.4 ms legacy only
    7 PLAN_REGRESSION daily build (latest) 442.7 ms 1,799.9 ms (read 40,182, cold) legacy only
    8 Analysis fact (latest, lower bounds only) 299.5 ms 367.4 ms Parallel Append: legacy + 3 empty partitions
    9 Planning only, 5 runs wide 2.147, 0.112, 0.072, 0.113, 0.089 ms. Latest 0.090 to 0.124 ms wide 0.834, 0.334, 0.184, 0.141, 0.131 ms. Latest 0.109 to 0.193 ms
    10 1% sample, the VALIDATE proxy 67,633.5 ms 0.675 ms Subplans Removed: 1: the filter pruned the legacy partition, so this no longer measures anything. The real VALIDATE times are in the table above.

    Read 2a is the one finding: a drain leaves a one-time cost on the first per-server floor read, until autovacuum finishes. My inference is that this will happen on large field stores once #5572 ships.

    • The cause:
      • Step 1's drain deleted 16.5 M rows at the low end of every server's first_execution_time range.
      • The wide table's autovacuum had not finished: V171 cancelled one at 17:14:27, and another had been running 7 min 36 s at 17:52Z.
      • So the first MIN(first_execution_time) WHERE server_id = … walks the dead index entries, and makes a heap fetch for each.
    • Measured:
      • server A: 19.6 s, 854,535 heap fetches. Its re-run took 14.9 ms, then 3.4 ms, because the first walk marks the entries dead.
      • a second server: 4.2 s, 234,239 heap fetches.
      • n_dead_tup on wide_legacy: 17,629,020.
    • Not caused by the partitioning: the same walk happens on the unpartitioned table after a drain. Step 1 didn't run this read.
    • Why it matters:
      • The live store's 1.8 s and 20,607 heap fetches came from a purge that had been failing, so few rows had been deleted.
      • After the first successful drain on a large store, each server's first Query Store read through the read gate can pay seconds to tens of seconds once, until autovacuum completes on the wide table.
  8. erikdarlingdata commented on Oct 8, 2026

    @erikdarlingdata
    OwnerAuthor

    Claude posting for Erik Darling.

    Step 2b on the restored copy (a02dbfcb7, the #5573 + #5580 rehearsal merge): it built clean and started clean.

    Setup:

    • The copy: the same copy after step 2, with both tables partitioned and promoted.
    • The run: the service started at 18:01:01Z.
    • Guards: re-verified before the start (outbound blocked except the management agent, store config disabled, minimal config file).
    • One overlap: an autovacuum of query_store_interval_wide_legacy (from about 17:42Z, throttled) was running for this whole start.

    1. The read the arm step takes under its lock

    From step 2, on the same tables (issuecomment-6065843886):

    • Index Only Scan Backward using idx_query_store_interval_wide_first_exec_legacy.
    • 1 heap fetch, 5 buffers, 1.9 ms.
    • max(first_execution_time) = 2026-10-08 12:47:11.383 on both legacy tables, and 0 rows at or after S.
    • The latest table's read wasn't run separately.

    2. The service log after the restart

    18:01:02.420  Postgres store ready (schema v172, 0 migration(s) applied)
    18:03:27.566  Retention purge drained 286358 row(s) from collect.query_store_interval_wide_legacy in 6 batch(es) (cap 50000), cutoff 2026-09-29 18:01Z
    18:03:27.730  Retention purge: 91 table(s) purged, 318762 row(s) deleted, 0 chunk(s) dropped, 0 failed, 121605ms
    18:21:03.060  Query Store interval table collect.query_store_interval_wide: promotion step ended NothingToDo (already promoted).
    18:21:03.062  Query Store interval table collect.query_store_interval_latest: promotion step ended NothingToDo (already promoted).
    18:21:03.087  ... ix_query_store_interval_wide_collection_time_brin on partitioned ...: 0 leaf index(es) built and attached in 0.0s; parent valid.
    
    • Arm and re-arm: no arm, re-arm or "S moved" line. Both tables were already promoted at S = 2026-10-10 00:00:00, which is 30 h away, outside the 12 h re-arm window.
    • VALIDATE: no VALIDATE line, because both constraints were validated in step 2.
    • ANALYZE: no analyzed the parent line on this start, in a convergence step or anywhere else.
    • For comparison, step 2's run: ANALYZE ran in the promotion step, at 8.2 s for wide and 0.6 s for latest.

    3. #5578: start-up timings, three starts on the same copy

    Start Build First collection_log row after the start Module-map refresh (WITH src AS (… FROM collect.procedure_stats …), up AS (INSERT INTO collect.module_map …)
    16:15:01 cdbaa5997 (step 1) +69.9 s 55.6 s, starting at +13.6 s
    17:14:25 2043dd3b2 (step 2) +67.1 s 38.1 s, starting at +27.6 s (and 35.8 s at +268 s)
    18:01:01 a02dbfcb7 (2b) +25.1 s 60.4 s, starting at +147 s
    • The slowest statement in the first 5 minutes was this refresh in all three starts.
    • On 2b it moved off the start path: it began after the first collection and the first purge batches.
    • What "first collection" means here: every monitored server is disabled on the copy, so the first row is the first background collector (oversized_plan_sweep). It isn't a server collection.

    Where the refresh's 35 to 60 s goes:

  9. added a commit that references this issue on Oct 8, 2026
    92cdf50
  10. erikdarlingdata commented on Oct 8, 2026

    @erikdarlingdata
    OwnerAuthor

    Fixed by #5573, merged into dev. On the PostgreSQL store the two Query Store interval tables now hold one partition per day, so retention drops a whole expired day. The upgrade attaches the current table as a legacy partition and copies no data. It ships in 3.10. Claude posting for Erik Darling.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    enhancementNew feature or request

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions