Subject: query hangs out

From: Антон Глушаков<[email-masked]>
Date: Tue, 20 May 2025 16:48:02 +0300

Hi.
I encountered a very strange behavior.
For any query (even a simple count(*) to one specific table (a small 30MB
table with 3 indexes, without any specific data types - everything is
standard out of the box vanilla Postgres) - the query hangs dead. Waited
more than 24 hours - the query did not complete).

Similarly, the vacuum process to the table hangs.
Only Kill -9 with a full restart helps

I get a backtrace, from it - I then examined the pg_multixact directory,
which at the time of the problem had swelled to 900MB and had several
thousand files.
I excluded long and inactive transactions, as well as prepared statements.

The workaround in the end was this - truncate the table (it was
successful), then vacuum freeze each DB, and after that the files from
pg_multixact disappeared.

What could it be? vacuum\freeze\mulitxact  settings are default.
At the same time, the value pg_database.datminmxid=1
Could the problem with the hang be related to the many old files in
pg_multixact ? (judging by the backtrace - yes)

postgresql 16.9

backtrace:
#0  0x00007f83840d3bfa in [email-masked] () from
/lib64/libc.so.6
#1  0x00007f83840d8847 in nanosleep () from /lib64/libc.so.6
#2  0x00000000005b416c in pg_usleep (microsec=1000) at ../port/pgsleep.c:50
#3  pg_usleep (microsec=1000) at ../port/pgsleep.c:41
#4  GetMultiXactIdMembers (from_pgupgrade=<optimized out>,
isLockOnly=<optimized out>, members=0x7ffd65135b40, multi=66664135) at
access/transam/multixact.c:1393
#5  GetMultiXactIdMembers (multi=66664135, members=0x7ffd65135b40,
from_pgupgrade=<optimized out>, isLockOnly=<optimized out>) at
access/transam/multixact.c:1225
#6  0x0000000000a99df9 in MultiXactIdGetUpdateXid.constprop.0
(xmax=<optimized out>, t_infomask=<optimized out>) at
access/heap/heapam.c:7073
#7  0x0000000000572355 in HeapTupleGetUpdateXid (tuple=0x7f8377fdceb0) at
access/heap/heapam.c:7114
#8  HeapTupleSatisfiesVacuumHorizon (htup=<optimized out>, buffer=496,
dead_after=0x7ffd65135c1c) at access/heap/heapam_visibility.c:1350
#9  0x0000000000577eee in heap_prune_satisfies_vacuum (buffer=496,
tup=0x7ffd65135c20, prstate=0x7ffd65135ec0) at access/heap/pruneheap.c:504
#10 heap_page_prune (relation=relation@entry=0x7f83738fed70,
buffer=buffer@entry=496, vistest=vistest@entry=0xd845f0
<GlobalVisDataRels.lto_priv.0>, old_snap_xmin=<optimized out>,
old_snap_ts=<optimized out>, nnewlpdead=nnewlpdead@entry=0x7ffd65136ad0,
off_loc=0x0)
    at access/heap/pruneheap.c:350
#11 0x0000000000578b91 in heap_page_prune_opt (relation=0x7f83738fed70,
buffer=496) at access/heap/pruneheap.c:208
#12 0x00000000005625cf in heapgetpage (sscan=sscan@entry=0x1038218,
block=block@entry=5) at access/heap/heapam.c:418
#13 0x0000000000563304 in heapgettup_pagemode (scan=scan@entry=0x1038218,
dir=ForwardScanDirection, nkeys=0, key=0x0) at access/heap/heapam.c:885
#14 0x00000000005637e4 in heap_getnextslot (sscan=0x1038218,
direction=<optimized out>, slot=0x1025410) at access/heap/heapam.c:1149
#15 0x0000000000727e8a in table_scan_getnextslot (slot=0x1025410,
direction=ForwardScanDirection, sscan=<optimized out>) at
executor/../../../src/include/access/tableam.h:1066
#16 SeqNext (node=0x1025280) at executor/nodeSeqscan.c:80
#17 0x000000000070bc41 in ExecProcNode (node=0x1025280) at
executor/../../../src/include/executor/executor.h:273
#18 fetch_input_tuple (aggstate=aggstate@entry=0x1024c88) at
executor/nodeAgg.c:562
#19 0x000000000070e313 in agg_retrieve_direct (aggstate=0x1024c88) at
executor/nodeAgg.c:2460
#20 ExecAgg (pstate=0x1024c88) at executor/nodeAgg.c:2180
#21 0x00000000006f8512 in ExecProcNode (node=0x1024c88) at
executor/../../../src/include/executor/executor.h:273
#22 ExecutePlan (execute_once=<optimized out>, dest=0x1073f50,
direction=<optimized out>, numberTuples=0, sendTuples=<optimized out>,
operation=CMD_SELECT, use_parallel_mode=<optimized out>,
planstate=0x1024c88, estate=0x1024a70) at executor/execMain.c:1670
#23 standard_ExecutorRun (queryDesc=0x1042660, direction=<optimized out>,
count=0, execute_once=<optimized out>) at executor/execMain.c:365
#24 0x00000000008c7cc5 in ExecutorRun (execute_once=<optimized out>,
count=0, direction=ForwardScanDirection, queryDesc=0x1042660) at
executor/execMain.c:309
#25 PortalRunSelect (portal=portal@entry=0xf96df0, forward=forward@entry=true,
count=0, count@entry=9223372036854775807, dest=dest@entry=0x1073f50) at
tcop/pquery.c:924
#26 0x00000000008c95c6 in PortalRun (portal=portal@entry=0xf96df0,
count=count@entry=9223372036854775807, isTopLevel=isTopLevel@entry=true,
run_once=run_once@entry=true, dest=dest@entry=0x1073f50,
altdest=altdest@entry=0x1073f50, qc=0x7ffd65136f90) at tcop/pquery.c:768
#27 0x00000000008ca650 in exec_simple_query (query_string=0xed8430 "select
count(*) from \"InboxState\";") at tcop/postgres.c:1274
#28 0x00000000008cc9df in PostgresMain (dbname=<optimized out>,
username=<optimized out>) at tcop/postgres.c:4637
#29 0x000000000083c244 in BackendRun (port=0xf2eb50, port=0xf2eb50) at
postmaster/postmaster.c:4464
#30 BackendStartup (port=0xf2eb50) at postmaster/postmaster.c:4192
#31 ServerLoop () at postmaster/postmaster.c:1782
#32 0x0000000000832c3d in PostmasterMain (argc=3, argv=0xe936d0) at
postmaster/postmaster.c:1466
#33 0x000000000051bf51 in main (argc=3, argv=0xe936d0) at main/main.c:198

---

From: Laurenz Albe <[email-masked]>
Date: Tue, 20 May 2025 17:25:50 +0200

On Tue, 2025-05-20 at 16:48 +0300, Антон Глушаков wrote:
> For any query (even a simple count(*) to one specific table (a small 30MB table with 3 indexes,
> without any specific data types - everything is standard out of the box vanilla Postgres) -
> the query hangs dead. Waited more than 24 hours - the query did not complete).
> 
> 
> I get a backtrace, from it - I then examined the pg_multixact directory, which at the time of
> the problem had swelled to 900MB and had several thousand files.
> The workaround in the end was this - truncate the table (it was successful), then vacuum freeze
> each DB, and after that the files from pg_multixact disappeared.
> 
> Could the problem with the hang be related to the many old files in pg_multixact ? (judging by the backtrace - yes)

I can't say for certain, but I have seen cases like that where index corruption sent
processes into an endless loop.  Next time you could try to rebuild the indexes.

Yours,
Laurenz Albe

---

From: Антон Глушаков<[email-masked]>
Date: Tue, 20 May 2025 18:43:36 +0300

Thanks for the advice.
I tried to remove all indexes and constraints from the table - it did not
help.
I have a copy of the data (before truncate) - I can test any hypothesis

вт, 20 мая 2025 г. в 18:25, Laurenz Albe <[email-masked]>:

> which at the time of
> successful), then vacuum freeze

---

From: Антон Глушаков<[email-masked]>
Date: Wed, 21 May 2025 12:06:54 +0300

The problem is with only one table.

As a result, I determined that the problem is on page 5 of the table (I
made SELECT ctid selections until it hangs).
Then I tried to delete rows by ctid (5, 0-100) from the table until I found
the problematic row.

Content through pageinspect:
# SELECT * FROM heap_page_items(get_raw_page('"InboxState"', 5)) where lp =
51;
-[ RECORD 1
]-------------------------------------------------------------------------------------------------------------------------------------------
lp          | 51
lp_off      | 3760
lp_flags    | 1
lp_len      | 100
t_xmin      | 136269917
t_xmax      | 66664135
t_field3    | 0
t_ctid      | (47,13)
t_infomask2 | 8203
t_infomask  | 4929
t_hoff      | 32
t_bits      | 1111011000000000
t_oid       |
t_data      |
\x3e8a7c00000000000100000090877a16b4b308dd9460898784c4af2dab692693d29bdf78bcf5153401000000fd55f20f44ec08dd9460f88969b943ab3cd8020000000000

I couldn't delete it in the standard way (delete from "InboxState" where
ctid = '(5,51)') - it also hangs.

But I can freeze it through pg_surgery.

# select heap_force_freeze('"InboxState"'::regclass, ARRAY['(5,
51)']::tid[]);

Output after freeze:
digitalarchive=# SELECT * FROM heap_page_items(get_raw_page('"InboxState"',
5)) where lp = 51;
-[ RECORD 1
]-------------------------------------------------------------------------------------------------------------------------------------------
lp          | 51
lp_off      | 3760
lp_flags    | 1
lp_len      | 100
t_xmin      | 2
t_xmax      | 0
t_field3    | 0
t_ctid      | (5,51)
t_infomask2 | 11
t_infomask  | 2817
t_hoff      | 32
t_bits      | 1111011000000000
t_oid       |
t_data      |
\x3e8a7c00000000000100000090877a16b4b308dd9460898784c4af2dab692693d29bdf78bcf5153401000000fd55f20f44ec08dd9460f88969b943ab3cd8020000000000

After that, queries to the table started to work normally.
I'll note that there are absolutely no errors in the postgres logs,
checksums are enabled, there are no errors for them either.

It seems that this is a bug.

ср, 21 мая 2025 г. в 02:52, ikramuddin <[email-masked]>:

> Is it taking too long only for this table or other tables also? If the
> issue is with this single table then check when it started to happened ,
> mean after creating one index or whatever change you perform just get back
> to that point and now the query should run fine
>
>
>
>
> On Tue, 20 May 2025 at 9:14 PM, Антон Глушаков <[email-masked]>
> wrote:
>
>> Thanks for the advice.

---

From: Laurenz Albe <[email-masked]>
Date: Wed, 21 May 2025 14:38:20 +0200

On Wed, 2025-05-21 at 12:06 +0300, Антон Глушаков wrote:
> As a result, I determined that the problem is on page 5 of the table (I made SELECT ctid selections until it hangs).
> Then I tried to delete rows by ctid (5, 0-100) from the table until I found the problematic row.
> 
> # SELECT * FROM heap_page_items(get_raw_page('"InboxState"', 5)) where lp = 51;
> -[ RECORD 1 ]-------------------------------------------------------------------------------------------------------------------------------------------
> lp          | 51
> lp_off      | 3760
> lp_flags    | 1
> lp_len      | 100
> t_xmin      | 136269917
> t_xmax      | 66664135
> t_field3    | 0
> t_ctid      | (47,13)
> t_infomask2 | 8203
> t_infomask  | 4929
> t_hoff      | 32
> t_data      | \x3e8a7c00000000000100000090877a16b4b308dd9460898784c4af2dab692693d29bdf78bcf5153401000000fd55f20f44ec08dd9460f88969b943ab3cd8020000000000

So the tuple is frozen AND updated, with the new version at (47,13).  Odd.
What do you see at (47,13)?

> I couldn't delete it in the standard way (delete from "InboxState" where ctid = '(5,51)') - it also hangs.
> 
> # select heap_force_freeze('"InboxState"'::regclass, ARRAY['(5, 51)']::tid[]);
> 
> Output after freeze:
> digitalarchive=# SELECT * FROM heap_page_items(get_raw_page('"InboxState"', 5)) where lp = 51;
> -[ RECORD 1 ]-------------------------------------------------------------------------------------------------------------------------------------------
> lp          | 51
> lp_off      | 3760
> lp_flags    | 1
> lp_len      | 100
> t_xmin      | 2
> t_xmax      | 0
> t_field3    | 0
> t_ctid      | (5,51)
> t_infomask2 | 11
> t_infomask  | 2817
> t_hoff      | 32
> t_data      | \x3e8a7c00000000000100000090877a16b4b308dd9460898784c4af2dab692693d29bdf78bcf5153401000000fd55f20f44ec08dd9460f88969b943ab3cd8020000000000

Now it is only frozen.

> I'll note that there are absolutely no errors in the postgres logs, checksums are enabled, there are no errors for them either.

I would still recommend a dump and restore to get rid of the data corruption.

> It seems that this is a bug.

Possible.

Yours,
Laurenz Albe

---

From: Антон Глушаков<[email-masked]>
Date: Wed, 21 May 2025 16:27:01 +0300

> What do you see at (47,13)?

I have restored the data before the freeze, here is the content (47.13)
SELECT * FROM heap_page_items(get_raw_page('"InboxState"', 47)) where lp =
13;
-[ RECORD 1
]-------------------------------------------------------------------------------------------------------------------------------------------
lp          | 13
lp_off      | 4632
lp_flags    | 1
lp_len      | 100
t_xmin      | 136385644
t_xmax      | 136385520
t_field3    | 0
t_ctid      | (47,13)
t_infomask2 | 11
t_infomask  | 8337
t_hoff      | 32
t_bits      | 1111011000000000
t_oid       |
t_data      |
\x3e8a7c00000000000100000090877a16b4b308dd9460898784c4af2dab692693d29bdf78bcf5153401000000ad43d6a5273608dd947a749769b943ab3cd8020001000000

> I would still recommend a dump and restore to get rid of the data
corruption.
Yes, thank you. It was a non-production environment, the data was recreated.

ср, 21 мая 2025 г. в 15:38, Laurenz Albe <[email-masked]>:

> > digitalarchive=# SELECT * FROM
> heap_page_items(get_raw_page('"InboxState"', 5)) where lp = 51;
> > -[ RECORD 1

---

From: Laurenz Albe <[email-masked]>
Date: Wed, 21 May 2025 17:09:55 +0200

On Wed, 2025-05-21 at 16:27 +0300, Антон Глушаков wrote:
> SELECT * FROM heap_page_items(get_raw_page('"InboxState"', 47)) where lp = 13;
> t_data      | \x3e8a7c00000000000100000090877a16b4b308dd9460898784c4af2dab692693d29bdf78bcf5153401000000ad43d6a5273608dd947a749769b943ab3cd8020001000000

That tuple should be visible.

So I'd say you should killed the other tuple with heap_force_kill().

Yours,
Laurenz Albe

---

From: Антон Глушаков<[email-masked]>
Date: Fri, 23 May 2025 09:51:15 +0300

Thank you.
I have investigated the logs to find the cause.
The only thing I found is that the problem started after a failover (we use
patroni with synchronous replication).
The problem is unlikely on the hardware level, since we use a private cloud
with enterprise-level hardware, and the checksum verification in postgres
did not find any problems.
If this is a bug in postgres, and hackers are willing to investigate the
problem, I can provide an archive with pgdata