Baike.dev
Log in
Back to tool/Back to issues
#11361·neon

test_sql_regress/neon-rel-truncate is flaky due to vacuum instability

Author: alexanderlawCreated Mar 26, 2025Updated Aug 26, 2026
Labelst/buga/test/flakyc/computea/test/flaky/investigatedmigrated_to_jira

test_sql_regress/neon-rel-truncate is flaky due to vacuum instability

A recent failure of the test_sql_regress with the following diagnostics: https://neon-github-public-dev.s3.amazonaws.com/reports/pr-11252/13860385306/index.html#/testresult/c6137b6e8fd9a4d test_sql_regress[release-pg17-v2-4] / ARM64 / without-lfc

test_runner/regress/test_pg_regress.py:346: in test_sql_regress
    pg_bin.run(pg_regress_command, env=env_vars, cwd=runpath)
test_runner/fixtures/neon_fixtures.py:3064: in run
    raise subprocess.CalledProcessError(proc.returncode, proc.args)
E   subprocess.CalledProcessError: Command '['/tmp/neon/pg_install/build/v17/src/test/regress/pg_regress', '--use-existing', '--bindir=/tmp/neon/pg_install/v17/bin', '--dlpath=/tmp/neon/pg_install/build/v17/src/test/regress', '--schedule=/__w/neon/neon/test_runner/sql_regress/parallel_schedule', '--inputdir=/__w/neon/neon/test_runner/sql_regress']' returned non-zero exit status 1.

---
regress/regression.diffs 
diff -U3 /__w/neon/neon/test_runner/sql_regress/expected/neon-rel-truncate.out /tmp/test_output/test_sql_regress[release-pg17-v2-4]-1/regress/results/neon-rel-truncate.out
--- /__w/neon/neon/test_runner/sql_regress/expected/neon-rel-truncate.out	2025-03-14 16:13:16.364241388 +0000
+++ /tmp/test_output/test_sql_regress[release-pg17-v2-4]-1/regress/results/neon-rel-truncate.out	2025-03-14 16:27:19.105556403 +0000
@@ -37,9 +37,9 @@
 -- the insertion would find a higher-numbered block in the FSM and use that instead.
 insert into tt values (0);
 select ctid, * from tt;
- ctid  | i 
--------+---
- (0,1) | 0
+  ctid   | i 
+---------+---
+ (44,57) | 0
 (1 row)
 
 drop table tt;

---
repo/endpoints/ep-1/compute.log
2025-03-14T16:27:12.736141Z  INFO logging and tracing started
...
PG:2025-03-14 16:27:12.963 GMT [177676] LOG:  starting PostgreSQL 17.4 (e5e87b9f52d0eaeb83f3e2517bb9727aac37729b) on aarch64-unknown-linux-gnu, compiled by gcc (Debian 12.2.0-14) 12.2.0, 64-bit
...
there is nothing interesting below
PG:2025-03-14 16:27:14.922 GMT [177904] LOG:  [NEON_SMGR] [shard 2] libpagestore: connected to 'postgresql://no_user@localhost:15412' with protocol version 2
2025-03-14T16:27:17.740971Z ERROR  name="BatchSpanProcessor.Flush.ExportError" reason="Other(reqwest::Error { kind: Request, url: Url { scheme: \"http\", cannot_be_a_base: false, username: \"\", password: None, host: Some(Domain(\"localhost\")), port: Some(4318), path: \"/v1/traces\", query: None, fragment: None }, source: hyper_util::client::legacy::Error(Connect, ConnectError(\"tcp connect error\", Os { code: 99, kind: AddrNotAvailable, message: \"Cannot assign requested address\" })) })" Failed during the export process
PG:2025-03-14 16:27:19.162 GMT [178358] LOG:  [NEON_SMGR] [shard 0] libpagestore: connected to 'postgresql://no_user@localhost:15408' with protocol version 2
...

indicates that the neon-rel-truncate's expectation:

delete from tt;
vacuum tt;

-- This can be used to look at the FSM directly, if the 'pg_freespace' contrib module
-- is installed
--SELECT blkno, avail from generate_series(1, 450) blkno, pg_freespace('tt'::regclass, blkno) AS avail;

-- Insert a row again. It should go on block #0. If the FSM was not truncated,
-- the insertion would find a higher-numbered block in the FSM and use that instead.
insert into tt values (0);
select ctid, * from tt;

might fail (but not because of FSM not being truncated). There may be another reason for the failure: "vacuum tt" doesn't really process the table.

I've reproduced the failure locally with:

--- a/test_runner/sql_regress/parallel_schedule
+++ b/test_runner/sql_regress/parallel_schedule
@@ -6,6 +6,15 @@
 
 test: neon-cid
 test: neon-rel-truncate
+test: neon-rel-truncate
+test: neon-rel-truncate
+test: neon-rel-truncate
+test: neon-rel-truncate
+test: neon-rel-truncate
+test: neon-rel-truncate
+test: neon-rel-truncate
+test: neon-rel-truncate
+test: neon-rel-truncate
 test: neon-clog
 test: neon-test-utils
 test: neon-vacuum-full

And with some debug logging added, I can see that the ingest_xlog_smgr_truncate function (which is the test intended to test) is just not called when the difference is produced. With -DWAL_DEBUG and wal_debug=on, I got the following: The log messages for a bad case:

2025-03-26T09:57:39.614139Z  INFO logging and tracing started
...
PG:2025-03-26 09:58:00.211 GMT [1638346:444567] pg_regress/neon-rel-truncate LOG:  INSERT @ 0/4A062B8:  - neon/DELETE: xmax: 781, off: 108, infobits: [KEYS_UPDATED], flags: 0x00
PG:2025-03-26 09:58:00.211 GMT [1638346:444568] pg_regress/neon-rel-truncate STATEMENT:  delete from tt;
PG:2025-03-26 09:58:00.211 GMT [1638346:444569] pg_regress/neon-rel-truncate LOG:  INSERT @ 0/4A062E8:  - Transaction/COMMIT: 2025-03-26 02:58:00.21189-07
PG:2025-03-26 09:58:00.211 GMT [1638346:444570] pg_regress/neon-rel-truncate STATEMENT:  delete from tt;
PG:2025-03-26 09:58:00.211 GMT [1638346:444571] pg_regress/neon-rel-truncate LOG:  xlog flush request 0/4A062E8; write 0/4A047A0; flush 0/4A047A0
PG:2025-03-26 09:58:00.211 GMT [1638346:444572] pg_regress/neon-rel-truncate STATEMENT:  delete from tt;
PG:2025-03-26 09:58:00.213 GMT [1638346:444573] pg_regress/neon-rel-truncate LOG:  statement: vacuum tt;
PG:2025-03-26 09:58:00.214 GMT [1636592:181] compute_ctl:activity_monitor LOG:  execute s162: select count(*) from pg_stat_subscription where pid is not null;
PG:2025-03-26 09:58:00.216 GMT [1636592:182] compute_ctl:activity_monitor LOG:  execute s163: select count(*) from pg_stat_activity where backend_type = 'autovacuum worker'
PG:2025-03-26 09:58:00.499 GMT [1638346:444574] pg_regress/neon-rel-truncate LOG:  INSERT @ 0/4A063A8:  - Heap/INPLACE: off: 9
PG:2025-03-26 09:58:00.499 GMT [1638346:444575] pg_regress/neon-rel-truncate STATEMENT:  vacuum tt;
PG:2025-03-26 09:58:00.499 GMT [1638346:444576] pg_regress/neon-rel-truncate LOG:  INSERT @ 0/4A063F8:  - Transaction/INVALIDATION: ; inval msgs: catcache 55 catcache 54 relcache 16415
PG:2025-03-26 09:58:00.499 GMT [1638346:444577] pg_regress/neon-rel-truncate STATEMENT:  vacuum tt;
PG:2025-03-26 09:58:00.499 GMT [1638346:444578] pg_regress/neon-rel-truncate LOG:  INSERT @ 0/4A06458:  - Standby/INVALIDATIONS: ; inval msgs: catcache 55 catcache 54 relcache 16415
PG:2025-03-26 09:58:00.499 GMT [1638346:444579] pg_regress/neon-rel-truncate STATEMENT:  vacuum tt;
PG:2025-03-26 09:58:00.522 GMT [1636588:71] LOG:  xlog bg flush request write 0/4A06458; flush: 0/4A06458, current is write 0/4A062E8; flush 0/4A062E8
PG:2025-03-26 09:58:00.572 GMT [1636586:210] LOG:  xlog flush request 0/4A04C20; write 0/4A047A0; flush 0/4A047A0
PG:2025-03-26 09:58:00.572 GMT [1636586:211] CONTEXT:  writing block 402 of relation base/16384/16415
PG:2025-03-26 09:58:00.591 GMT [1638346:444580] pg_regress/neon-rel-truncate LOG:  statement: SELECT blkno, avail from generate_series(1, 450) blkno, pg_freespace('tt'::regclass, blkno) AS avail;
PG:2025-03-26 09:58:00.594 GMT [1638346:444581] pg_regress/neon-rel-truncate LOG:  INSERT @ 0/4A06490:  - Heap2/PRUNE_ON_ACCESS: , isCatalogRel: T, nplans: 0, nredirected: 0, ndead: 2, nunused: 0, dead: [14, 21] at character 57
PG:2025-03-26 09:58:00.594 GMT [1638346:444582] pg_regress/neon-rel-truncate STATEMENT:  SELECT blkno, avail from generate_series(1, 450) blkno, pg_freespace('tt'::regclass, blkno) AS avail;
PG:2025-03-26 09:58:00.594 GMT [1638346:444583] pg_regress/neon-rel-truncate LOG:  INSERT @ 0/4A064C8:  - Heap2/PRUNE_ON_ACCESS: , isCatalogRel: T, nplans: 0, nredirected: 0, ndead: 2, nunused: 0, dead: [28, 29] at character 57
PG:2025-03-26 09:58:00.594 GMT [1638346:444584] pg_regress/neon-rel-truncate STATEMENT:  SELECT blkno, avail from generate_series(1, 450) blkno, pg_freespace('tt'::regclass, blkno) AS avail;
PG:2025-03-26 09:58:00.610 GMT [1638346:444585] pg_regress/neon-rel-truncate LOG:  statement: insert into tt values (0);
PG:2025-03-26 09:58:00.612 GMT [1638346:444586] pg_regress/neon-rel-truncate LOG:  INSERT @ 0/4A06508:  - neon/INSERT: off: 57, flags: 0x08
PG:2025-03-26 09:58:00.612 GMT [1638346:444587] pg_regress/neon-rel-truncate STATEMENT:  insert into tt values (0);
PG:2025-03-26 09:58:00.612 GMT [1638346:444588] pg_regress/neon-rel-truncate LOG:  INSERT @ 0/4A06538:  - Transaction/COMMIT: 2025-03-26 02:58:00.612219-07
PG:2025-03-26 09:58:00.612 GMT [1638346:444589] pg_regress/neon-rel-truncate STATEMENT:  insert into tt values (0);
PG:2025-03-26 09:58:00.612 GMT [1638346:444590] pg_regress/neon-rel-truncate LOG:  xlog flush request 0/4A06538; write 0/4A06458; flush 0/4A06458
PG:2025-03-26 09:58:00.612 GMT [1638346:444591] pg_regress/neon-rel-truncate STATEMENT:  insert into tt values (0);
PG:2025-03-26 09:58:00.613 GMT [1638346:444592] pg_regress/neon-rel-truncate LOG:  statement: select ctid, * from tt;
...

For a good case:

PG:2025-03-26 09:57:46.904 GMT [1637670:444517] pg_regress/neon-rel-truncate LOG:  statement: vacuum tt;
PG:2025-03-26 09:57:46.906 GMT [1637670:444518] pg_regress/neon-rel-truncate LOG:  INSERT @ 0/2E2B1B8:  - Heap2/PRUNE_VACUUM_SCAN: snapshotConflictHorizon: 753, isCatalogRel: F, nplans: 0, nredirected: 0, ndead: 0, nunused: 226, unused: [1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35, 36, 37, 38, 39, 40, 41, 42, 43, 44, 45, 46, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62, 63, 64, 65, 66, 67, 68, 69, 70, 71, 72, 73, 74, 75, 76, 77, 78, 79, 80, 81, 82, 83, 84, 85, 86, 87, 88, 89, 90, 91, 92, 93, 94, 95, 96, 97, 98, 99, 100, 101, 102, 103, 104, 105, 106, 107, 108, 109, 110, 111, 112, 113, 114, 115, 116, 117, 118, 119, 120, 121, 122, 123, 124, 125, 126, 127, 128, 129, 130, 131, 132, 133, 134, 135, 136, 137, 138, 139, 140, 141, 142, 143, 144, 145, 146, 147, 148, 149, 150, 151, 152, 153, 154, 155, 156, 157, 158, 159, 160, 161, 162, 163, 164, 165, 166, 167, 168, 169, 170, 171, 172, 173, 174, 175, 176, 177, 178, 179, 180, 181, 182, 183, 184, 185, 186, 187, 188, 189, 190, 191, 192, 193, 194, 195, 196, 197, 198, 199, 200, 201, 202, 203, 204, 205, 206, 207, 208, 209, 210, 211, 212, 213, 214, 215, 216, 217, 218, 219, 220, 221, 222, 223, 224, 225, 226]
PG:2025-03-26 09:57:46.906 GMT [1637670:444519] pg_regress/neon-rel-truncate CONTEXT:  while scanning block 0 of relation "public.tt"
PG:2025-03-26 09:57:46.906 GMT [1637670:444520] pg_regress/neon-rel-truncate STATEMENT:  vacuum tt;
PG:2025-03-26 09:57:46.906 GMT [1637670:444521] pg_regress/neon-rel-truncate LOG:  INSERT @ 0/2E2B1F8:  - Heap2/VISIBLE: snapshotConflictHorizon: 0, flags: 0x03
PG:2025-03-26 09:57:46.906 GMT [1637670:444522] pg_regress/neon-rel-truncate CONTEXT:  while scanning block 0 of relation "public.tt"
PG:2025-03-26 09:57:46.906 GMT [1637670:444523] pg_regress/neon-rel-truncate STATEMENT:  vacuum tt;
...
(~2700 (447230 - 444523) messages in between related to vacuuming tt)
...
PG:2025-03-26 09:57:47.588 GMT [1637670:447230] pg_regress/neon-rel-truncate LOG:  INSERT @ 0/2E3DB38:  - Heap2/PRUNE_VACUUM_SCAN: snapshotConflictHorizon: 753, isCatalogRel: F, nplans: 0, nredirected: 0, ndead: 0, nunused: 2, unused: [8, 108]
PG:2025-03-26 09:57:47.588 GMT [1637670:447231] pg_regress/neon-rel-truncate CONTEXT:  while scanning block 442 of relation "public.tt"
PG:2025-03-26 09:57:47.588 GMT [1637670:447232] pg_regress/neon-rel-truncate STATEMENT:  vacuum tt;
PG:2025-03-26 09:57:47.588 GMT [1637670:447233] pg_regress/neon-rel-truncate LOG:  INSERT @ 0/2E3DB78:  - Heap2/VISIBLE: snapshotConflictHorizon: 0, flags: 0x03
PG:2025-03-26 09:57:47.588 GMT [1637670:447234] pg_regress/neon-rel-truncate CONTEXT:  while scanning block 442 of relation "public.tt"
PG:2025-03-26 09:57:47.588 GMT [1637670:447235] pg_regress/neon-rel-truncate STATEMENT:  vacuum tt;
PG:2025-03-26 09:57:47.589 GMT [1637670:447236] pg_regress/neon-rel-truncate LOG:  INSERT @ 0/2E3DBA8:  - Standby/LOCK: xid 754 db 16384 rel 16397
PG:2025-03-26 09:57:47.589 GMT [1637670:447237] pg_regress/neon-rel-truncate CONTEXT:  while truncating relation "public.tt" to 0 blocks
PG:2025-03-26 09:57:47.589 GMT [1637670:447238] pg_regress/neon-rel-truncate STATEMENT:  vacuum tt;
PG:2025-03-26 09:57:47.592 GMT [1637670:447239] pg_regress/neon-rel-truncate LOG:  xlog flush request 0/2E3ACE0; write 0/2E3A000; flush 0/2E3A000
PG:2025-03-26 09:57:47.592 GMT [1637670:447240] pg_regress/neon-rel-truncate CONTEXT:  writing block 349 of relation base/16384/16397<200b>     while truncating relation "public.tt" to 0 blocks
PG:2025-03-26 09:57:47.592 GMT [1637670:447241] pg_regress/neon-rel-truncate STATEMENT:  vacuum tt;
...
PG:2025-03-26 09:57:47.934 GMT [1637670:447263] pg_regress/neon-rel-truncate LOG:  statement: insert into tt values (0);
PG:2025-03-26 09:57:47.934 GMT [1637670:447264] pg_regress/neon-rel-truncate LOG:  INSERT @ 0/2E3DE30:  - XLOG/FPI:
PG:2025-03-26 09:57:47.934 GMT [1637670:447265] pg_regress/neon-rel-truncate STATEMENT:  insert into tt values (0);
PG:2025-03-26 09:57:47.934 GMT [1637670:447266] pg_regress/neon-rel-truncate LOG:  INSERT @ 0/2E3DE70:  - neon/INSERT+INIT: off: 1, flags: 0x08
PG:2025-03-26 09:57:47.934 GMT [1637670:447267] pg_regress/neon-rel-truncate STATEMENT:  insert into tt values (0);

Source: neondatabase/neon

View original on GitHubView discussion on GitHub