BUG #19792: BUG: Deadlock between WaitIO and read-stream look-ahead under io_method=io_uring (18.6)

Started by PG Bug reporting form1 day ago1 messagesbugs

noreply@postgresql.org

1 day ago

The following bug has been logged on the website:

Bug reference: 19792
Logged by: Tomas Barton
Email address: barton.tomas@gmail.com
PostgreSQL version: 18.6
Operating system: Debian 12
Description:

PostgreSQL 18.6 (Debian 18.6-1.pgdg12+2), Debian 12, kernel 6.1.187,
io_method=io_uring.
io_method = io_uring
Storage: local ext4 on md RAID, no I/O errors in dmesg
Extensions in play: pg_stat_statements (no custom AMs; the affected table
has only btree indexes)

Three backends hung indefinitely and could not be cancelled or terminated
(`statement_timeout`, `pg_cancel_backend`, `pg_terminate_backend` all
ineffective,
as expected for LWLock / buffer-IO waits):

| pid | backend | wait event | what it is doing |
|---|---|---|---|
| 3689628 | client backend (A) | IPC:BufferIo | `INSERT ... ON CONFLICT DO
UPDATE`, in `_bt_split` -> `_bt_allocbuf` -> `ReadBuffer(block 628)` ->
`StartBufferIO` -> `WaitIO`, holding exclusive content lock on leaf block
627 |
| 2213934 | autovacuum worker (B) | LWLock:BufferContent | `btvacuumcleanup`
-> `btvacuumscan` -> `btvacuumpage` -> `_bt_lockbuf(block 627, BT_READ)` |
| 2214042 | client backend (C) | LWLock:BufferContent | backward index-only
scan (`MAX(last_update)`), `_bt_search` -> `_bt_relandgetbuf` ->
`_bt_lockbuf(block 627)` |

Block 627 and 628 both belong to the btree index
`last_update_similar_items_thenlper_gte_large_recent` (relfilenode
3378615556) on table
`"db-prod".similar_items_thenlper_gte_large_recent` (oid 3371211934). The
index is on a
timestamp column, so inserts land on the rightmost leaf (627) and split
frequently. Block 628
is a free page returned by the FSM.

## Mechanism

1. Backend B (autovacuum, no dead tuples, in the index-cleanup pass) walks
the index through a
read stream. The stream issued the read of block 628 as look-ahead.
`pg_aios` shows that I/O
as handle **17445**, generation **9035984**, owner pid **2213934**, state
**SUBMITTED**.
2. Backend A, splitting leaf 627 (exclusive content lock held), got block
628 from the FSM and
called `ReadBuffer`. `StartBufferIO` found `BM_IO_IN_PROGRESS` already
set by B. At that
moment B had set the flag but **had not yet staged the I/O**, so
`buf->io_wref` was still
invalid. The `WaitIO` frame of A confirms this: its local copy is
`iow = {aio_index = 4294967295, ...}`. A therefore took the fallback
branch and went to
sleep on the buffer's condition variable (`ConditionVariableSleep(cv,
WAIT_EVENT_BUFFER_IO)`).
3. B then staged and submitted the I/O. `buffer_stage_common` sets
`buf_hdr->io_wref` but does
**not** broadcast the buffer's I/O condition variable, so A is not woken.
The buffer header
now reads `io_wref = {aio_index = 17445, generation_lower = 9035984}`
while A still sleeps.
4. B proceeded to `_bt_lockbuf(627, BT_READ)` and blocked on the content
lock held by A.
5. Under io_uring, the completion of handle 17445 is only processed by its
owner (B) or by a
backend that waits on that wait reference (`pgaio_wref_wait`). B is
blocked on an LWLock and
A never re-reads `io_wref` (nothing wakes it). The completion sits in B's
ring forever.
Backend C and any future reader of block 627 queue behind A.

In `io_method=worker` the I/O worker runs the completion callback, which
calls
`TerminateBufferIO` and broadcasts the condition variable, so the same race
is harmless there.

The relevant code in REL_18_STABLE is unchanged since the original AIO
commits: `WaitIO()`
sleeps on the buffer CV when `io_wref` is invalid, and
`buffer_stage_common()` sets `io_wref`
without a broadcast. Master (post commits 74eafea / 999dec9, March 2026) has
the same fallback;
`AsyncReadBuffers()` there even comments: "It's possible that another
backend has started IO on
the buffer but not yet set its wait reference. In this case, we have no
choice but to wait for
either the wait reference to be valid or the IO to be done." Nothing signals
the first of those
two transitions.

Possibly related (different trigger, same family): "Potential deadlock in
pgaio_io_wait()",
Thomas Munro / Heikki Linnakangas, pgsql-hackers, Aug-Oct 2025
(/messages/by-id/CA+hUKG+mZYrSdnhk-XrBYO18H829K77S9gMKUsykOiTJtqB43g@mail.gmail.com).
Also BUG #19725 (io_uring read failures on 18.6).

## Suggested fix

Either broadcast `BufferDescriptorGetIOCV(buf)` after setting
`buf_hdr->io_wref` in
`buffer_stage_common()` (so a waiter in `WaitIO()` re-checks and switches to
`pgaio_wref_wait()`), or make `WaitIO()` sleep with a timeout / re-check
loop when it observes
`BM_IO_IN_PROGRESS` with an invalid `io_wref`.

## Recovery

Fast shutdown cannot complete (the backends do not reach
`CHECK_FOR_INTERRUPTS`). Immediate
shutdown or SIGKILL of the INSERT backend, followed by crash recovery.
`io_method` was changed
to `worker` on restart.

---

# Evidence

## 1. pg_stat_activity (monitoring view, before diagnosis)

## 2. OS state of the three processes (no D state, nothing pending in the
kernel)

```
PID STAT WCHAN CMD
2213934 Ss futex_wait_queue postgres: 18/main: autovacuum
worker recommender
2214042 Ss futex_wait_queue postgres: 18/main: recommender
recommender 10.0.3.1(43106) SELECT
3689628 Ssl do_epoll_wait postgres: 18/main: recommender
recommender 10.0.2.13(33290) INSERT

== /proc/2213934/stack
[<0>] futex_wait_queue+0x60/0x90
[<0>] futex_wait+0x185/0x270
[<0>] do_futex+0x106/0x1b0
[<0>] __x64_sys_futex+0x8e/0x1d0
[<0>] do_syscall_64+0x5d/0xb0
[<0>] entry_SYSCALL_64_after_hwframe+0x6e/0xd8
== /proc/3689628/stack
[<0>] do_epoll_wait+0x698/0x7d0
[<0>] __x64_sys_epoll_wait+0x6f/0x110
[<0>] do_syscall_64+0x5d/0xb0
[<0>] entry_SYSCALL_64_after_hwframe+0x6e/0xd8
== /proc/2214042/stack
[<0>] futex_wait_queue+0x60/0x90
[<0>] futex_wait+0x185/0x270
[<0>] do_futex+0x106/0x1b0
[<0>] __x64_sys_futex+0x8e/0x1d0
[<0>] do_syscall_64+0x5d/0xb0
[<0>] entry_SYSCALL_64_after_hwframe+0x6e/0xd8

# threads of the INSERT backend (io_uring worker idle)
== /proc/3689628/task/1773077 iou-wrk-3689628 S
[<0>] io_wqe_worker+0x1b9/0x3a0
[<0>] ret_from_fork+0x22/0x30
== /proc/3689628/task/3689628 postgres S
[<0>] do_epoll_wait+0x698/0x7d0
[<0>] __x64_sys_epoll_wait+0x6f/0x110
[<0>] do_syscall_64+0x5d/0xb0
[<0>] entry_SYSCALL_64_after_hwframe+0x6e/0xd8
```

dmesg contains nothing since a routine md data-check on 2026-09-24.

## 3. Settings

```
io_method
-----------
io_uring

io_workers
------------
6
```

## 4. Relations involved

```
oid | relname | relkind
| relfilenode
------------+-----------------------------------------------------+---------+-------------
3371211934 | similar_items_thenlper_gte_large_recent | r
| 3371211934
3378609811 | similar_items_thenlper_gte_large_recent_pkey | i
| 3378609811
3378615556 | last_update_similar_items_thenlper_gte_large_recent | i
| 3378615556
```

## 5. pg_stat_progress_vacuum for the autovacuum (pid 2213934)

```
pid | datid | datname | relid | phase |
heap_blks_total | heap_blks_scanned | heap_blks_vacuumed |
index_vacuum_count | max_dead_tuple_bytes | dead_tuple_bytes |
num_dead_item_ids | indexes_total | indexes_processed | delay_time
---------+-------+-------------+------------+---------------------+-----------------+-------------------+--------------------+--------------------+----------------------+------------------+-------------------+---------------+-------------------+------------
2213934 | 16386 | recommender | 3371211934 | cleaning up indexes |
1204577 | 1204577 | 1204577 | 0 |
2147483648 | 0 | 0 | 2 |
1 | 0
```

## 6. pg_aios: the I/O owned by the autovacuum that nobody completes

The INSERT's own handle (acquired before `StartBufferIO`, never used):

```
pid | io_id | io_generation | state | operation | ... |
target_desc
---------+-------+---------------+------------+-----------+-----+-------------
3689628 | 10321 | 29264366 | HANDED_OUT | | |
```

(Other rows in `pg_aios` at the time were short-lived reads from unrelated
sessions; all of
those backends had exited by the next check.)

## 7. Buffer header of the buffer the INSERT waits on (block 628), read via
gdb from pid 3689628

```
(gdb) p *(BufferDesc *)0x7fab2868ad80
$1 = {tag = {spcOid = 1663, dbOid = 16386, relNumber = 3378615556, forkNum =
MAIN_FORKNUM, blockNum = 628},
buf_id = 994552, state = {value = 2248671235}, wait_backend_pgprocno =
-1, freeNext = -2,
io_wref = {aio_index = 17445, generation_upper = 0, generation_lower =
9035984},
content_lock = {tranche = 62, state = {value = 1073741824}, waiters =
{head = -1, tail = -1}}}
(gdb) p/x ((BufferDesc *)0x7fab2868ad80)->state.value
$2 = 0x86080003
```

Decoded: refcount 3, usagecount 2, flags = BM_PERMANENT | BM_IO_IN_PROGRESS
| BM_TAG_VALID.
Not BM_VALID, no BM_IO_ERROR. `io_wref` matches handle 17445 / generation
9035984 above.
Note the contrast with the INSERT's `WaitIO` frame below, whose copy of
`iow` has
`aio_index = 4294967295` (invalid): the reference became valid after A went
to sleep.

## 8. Backtrace of the INSERT backend (pid 3689628), `bt full`

Frames 0-20 with locals. The large `io_pages` scratch array in frame 10 and
the
`events` array in frame 39 are elided as noise.

```
#0 0x00007fb342f28ef3 in epoll_wait () from /lib/x86_64-linux-gnu/libc.so.6
#1 0x0000561a358ba97b in WaitEventSetWaitBlock (nevents=1,
occurred_events=0x7ffcb93c2b50, cur_timeout=-1, set=0x561a53fcb8f0) at
./build/../src/backend/storage/ipc/waiteventset.c:1191
#2 WaitEventSetWait (set=0x561a53fcb8f0, timeout=timeout@entry=-1,
occurred_events=occurred_events@entry=0x7ffcb93c2b50,
nevents=nevents@entry=1, wait_event_info=wait_event_info@entry=134217736) at
./build/../src/backend/storage/ipc/waiteventset.c:1139
#3 0x0000561a358af5e5 in WaitLatch (latch=<optimized out>,
wakeEvents=wakeEvents@entry=33, timeout=timeout@entry=-1,
wait_event_info=wait_event_info@entry=134217736) at
./build/../src/backend/storage/ipc/latch.c:196
#4 0x0000561a358bc215 in ConditionVariableTimedSleep
(cv=cv@entry=0x7fb30e72af00, timeout=timeout@entry=-1,
wait_event_info=wait_event_info@entry=134217736) at
./build/../src/backend/storage/lmgr/condition_variable.c:163
#5 0x0000561a358bc3be in ConditionVariableSleep
(cv=cv@entry=0x7fb30e72af00,
wait_event_info=wait_event_info@entry=134217736) at
./build/../src/backend/storage/lmgr/condition_variable.c:98
#6 0x0000561a3589c191 in WaitIO (buf=buf@entry=0x7fab2868ad80) at
./build/../src/backend/storage/buffer/bufmgr.c:6032
buf_state = <optimized out>
iow = {aio_index = 4294967295, generation_upper = 0,
generation_lower = 28473836}
cv = 0x7fb30e72af00
#7 0x0000561a3589d20d in StartBufferIO (buf=0x7fab2868ad80,
forInput=forInput@entry=true, nowait=nowait@entry=false) at
./build/../src/backend/storage/buffer/bufmgr.c:6076
#8 0x0000561a3589d3ac in ReadBuffersCanStartIOOnce (nowait=false,
buffer=<optimized out>) at
./build/../src/backend/storage/buffer/bufmgr.c:1566
#9 ReadBuffersCanStartIO (nowait=false, buffer=<optimized out>) at
./build/../src/backend/storage/buffer/bufmgr.c:1594
#10 AsyncReadBuffers (operation=operation@entry=0x7ffcb93c3230,
nblocks_progress=nblocks_progress@entry=0x7ffcb93c317c) at
./build/../src/backend/storage/buffer/bufmgr.c:1871
buffers = 0x7ffcb93c322c
flags = 8
forknum = MAIN_FORKNUM
persistence = 112 'p'
nblocks_done = 0
blocknum = 628
io_buffers = 0x7ffcb93c322c
io_buffers_len = 0
ioh = 0x7fb3363fd390
ioh_flags = 1
io_pages = {... elided ...}
io_context = IOCONTEXT_NORMAL
io_object = IOOBJECT_RELATION
did_start_io = <optimized out>
#11 0x0000561a3589fcac in StartReadBuffersImpl (allow_forwarding=false,
flags=8, nblocks=0x7ffcb93c317c, blockNum=628, buffers=0x7ffcb93c322c,
operation=0x7ffcb93c3230) at
./build/../src/backend/storage/buffer/bufmgr.c:1437
actual_nblocks = 1
maxcombine = 0
#12 StartReadBuffer (operation=operation@entry=0x7ffcb93c3230,
buffer=buffer@entry=0x7ffcb93c322c, blocknum=blocknum@entry=628,
flags=flags@entry=8) at ./build/../src/backend/storage/buffer/bufmgr.c:1525
nblocks = 1
#13 0x0000561a358a10dd in ReadBuffer_common (strategy=<optimized out>,
mode=<optimized out>, blockNum=<optimized out>, forkNum=<optimized out>,
smgr_persistence=<optimized out>, smgr=<optimized out>, rel=<optimized out>)
at ./build/../src/backend/storage/buffer/bufmgr.c:1255
operation = {rel = 0x7fab1e2e94e8, smgr = 0x561a541d2150,
persistence = 112 'p', forknum = MAIN_FORKNUM, strategy = 0x0, buffers =
0x7ffcb93c322c, blocknum = 628, flags = 8, nblocks = 1, nblocks_done = 0,
io_wref = {aio_index = 4294967295, generation_upper = 0, generation_lower =
0}, io_return = {...}}
buffer = 994553
flags = 8
#14 ReadBufferExtended (reln=<optimized out>,
forkNum=forkNum@entry=MAIN_FORKNUM, blockNum=628,
mode=mode@entry=RBM_NORMAL, strategy=strategy@entry=0x0) at
./build/../src/backend/storage/buffer/bufmgr.c:815
#15 0x0000561a358a15ee in ReadBuffer (reln=<optimized out>,
blockNum=<optimized out>) at
./build/../src/backend/storage/buffer/bufmgr.c:760
#16 0x0000561a355a157c in _bt_allocbuf (rel=rel@entry=0x7fab1e2e94e8,
heaprel=heaprel@entry=0x561a54175460) at
./build/../src/backend/access/nbtree/nbtpage.c:906
buf = <optimized out>
blkno = 628
page = <optimized out>
#17 0x0000561a3559e8f1 in _bt_split (postingoff=0, nposting=0x0,
orignewitem=0x0, newitem=0x561a54403018, newitemsz=16, newitemoff=8, cbuf=0,
buf=992779, itup_key=<optimized out>, heaprel=0x561a54175460,
rel=0x7fab1e2e94e8) at ./build/../src/backend/access/nbtree/nbtinsert.c:1720
origpagenumber = 627
maxoff = 7
firstrightoff = 6
afterleftoff = 2
isleaf = true
isrightmost = true
newitemonleft = false
sbuf = 0
spage = 0x0
origpage = 0x7fad19111000 "\035\353\n"
leftpage = 0x561a543ff248 "\035\353\n"
lefthighkey = 0x561a543fdb90
#18 _bt_insertonpg (rel=0x7fab1e2e94e8, heaprel=0x561a54175460,
itup_key=<optimized out>, buf=992779, cbuf=0, stack=0x561a543fd490,
itup=0x561a54403018, itemsz=<optimized out>, newitemoff=8,
postingoff=<optimized out>, split_only_page=<optimized out>) at
./build/../src/backend/access/nbtree/nbtinsert.c:1217
isroot = false
isrightmost = true
isonly = false
#19 0x0000561a355a0571 in _bt_doinsert (rel=rel@entry=0x7fab1e2e94e8,
itup=itup@entry=0x561a54403018,
checkUnique=checkUnique@entry=UNIQUE_CHECK_NO,
indexUnchanged=indexUnchanged@entry=false,
heapRel=heapRel@entry=0x561a54175460) at
./build/../src/backend/access/nbtree/nbtinsert.c:260
insertstate = {itup = 0x561a54403018, itemsz = 16, itup_key =
0x561a542f3320, buf = 992779, bounds_valid = true, low = 8, stricthigh = 8,
postingoff = 0}
#20 0x0000561a355a6b23 in btinsert (rel=0x7fab1e2e94e8, values=<optimized
out>, isnull=<optimized out>, ht_ctid=0x561a543fcad8,
heapRel=0x561a54175460, checkUnique=UNIQUE_CHECK_NO,
indexUnchanged=<optimized out>, indexInfo=<optimized out>) at
./build/../src/backend/access/nbtree/nbtree.c:215
#21 0x0000561a35707243 in ExecInsertIndexTuples
(resultRelInfo=resultRelInfo@entry=0x561a5427da50,
slot=slot@entry=0x561a543fcaa8, estate=<optimized out>,
update=update@entry=true, noDupErr=noDupErr@entry=false,
specConflict=specConflict@entry=0x0, arbiterIndexes=<optimized out>,
onlySummarizing=<optimized out>) at
./build/../src/backend/executor/execIndexing.c:449
#22 0x0000561a357336ee in ExecUpdateEpilogue
(context=context@entry=0x7ffcb93c3c80, updateCxt=<optimized out>,
resultRelInfo=resultRelInfo@entry=0x561a5427da50,
tupleid=tupleid@entry=0x7ffcb93c3baa, oldtuple=oldtuple@entry=0x0,
slot=slot@entry=0x561a543fcaa8) at
./build/../src/backend/executor/nodeModifyTable.c:2330
#23 0x0000561a35734f27 in ExecUpdate (context=context@entry=0x7ffcb93c3c80,
resultRelInfo=resultRelInfo@entry=0x561a5427da50,
tupleid=tupleid@entry=0x7ffcb93c3baa, oldtuple=oldtuple@entry=0x0,
oldSlot=<optimized out>, oldSlot@entry=0x561a5427f348, slot=0x561a543fcaa8,
canSetTag=<optimized out>) at
./build/../src/backend/executor/nodeModifyTable.c:2709
#24 0x0000561a35735c6e in ExecOnConflictUpdate (returning=<synthetic
pointer>, canSetTag=<optimized out>, excludedSlot=<optimized out>,
conflictTid=0x7ffcb93c3baa, resultRelInfo=0x561a5427da50,
context=0x7ffcb93c3c80) at
./build/../src/backend/executor/nodeModifyTable.c:2925
#25 ExecInsert (context=context@entry=0x7ffcb93c3c80,
resultRelInfo=resultRelInfo@entry=0x561a5427da50, slot=<optimized out>,
slot@entry=0x561a543fcd00, canSetTag=<optimized out>,
inserted_tuple=inserted_tuple@entry=0x0,
insert_destrel=insert_destrel@entry=0x0) at
./build/../src/backend/executor/nodeModifyTable.c:1152
#26 0x0000561a3573714e in ExecModifyTable (pstate=0x561a5427d848) at
./build/../src/backend/executor/nodeModifyTable.c:4509
#27 0x0000561a35707eda in ExecProcNode (node=0x561a5427d848) at
./build/../src/include/executor/executor.h:315
#28 ExecutePlan (dest=0x561a5400eed8, direction=<optimized out>,
numberTuples=0, sendTuples=false, operation=CMD_INSERT,
queryDesc=0x561a5429b2b8) at ./build/../src/backend/executor/execMain.c:1711
#29 standard_ExecutorRun (queryDesc=0x561a5429b2b8, direction=<optimized
out>, count=0) at ./build/../src/backend/executor/execMain.c:366
#30 0x00007fb342c434e5 in pgss_ExecutorRun (queryDesc=0x561a5429b2b8,
direction=ForwardScanDirection, count=0) at
./build/../contrib/pg_stat_statements/pg_stat_statements.c:1036
#31 0x0000561a358db264 in ProcessQuery (plan=0x561a558c8948,
sourceText=0x561a542fa9f0 "\n INSERT INTO
\"db-prod\".\"similar_items_thenlper_gte_large_recent\" (itemid,
similar_items, last_update)\n VALUES ('AmZHZVwxWbZ5', '[{\"id\":
\"A7GBDfQ8rMhD\", \"r"..., params=0x0, queryEnv=0x0, dest=0x561a5400eed8,
qc=0x7ffcb93c4110) at ./build/../src/backend/tcop/pquery.c:161
#32 0x0000561a358dbe79 in PortalRunMulti
(portal=portal@entry=0x561a540e4a48, isTopLevel=isTopLevel@entry=true,
setHoldSnapshot=setHoldSnapshot@entry=false, dest=dest@entry=0x561a5400eed8,
altdest=altdest@entry=0x561a5400eed8, qc=qc@entry=0x7ffcb93c4110) at
./build/../src/backend/tcop/pquery.c:1272
#33 0x0000561a358dc326 in PortalRun (portal=portal@entry=0x561a540e4a48,
count=count@entry=9223372036854775807, isTopLevel=isTopLevel@entry=true,
dest=dest@entry=0x561a5400eed8, altdest=altdest@entry=0x561a5400eed8,
qc=qc@entry=0x7ffcb93c4110) at ./build/../src/backend/tcop/pquery.c:788
#34 0x0000561a358d8189 in exec_simple_query (query_string=0x561a542fa9f0
"...INSERT INTO \"db-prod\".\"similar_items_thenlper_gte_large_recent\"
...") at ./build/../src/backend/tcop/postgres.c:1274
#35 0x0000561a358d9e2c in PostgresMain (dbname=<optimized out>,
username=<optimized out>) at ./build/../src/backend/tcop/postgres.c:4770
#36 0x0000561a358d46bf in BackendMain (startup_data=<optimized out>,
startup_data_len=<optimized out>) at
./build/../src/backend/tcop/backend_startup.c:124
#37 0x0000561a35835745 in postmaster_child_launch (child_type=B_BACKEND,
child_slot=20, ...) at
./build/../src/backend/postmaster/launch_backend.c:290
#38 0x0000561a35839039 in BackendStartup (client_sock=0x7ffcb93c4630) at
./build/../src/backend/postmaster/postmaster.c:3569
#39 ServerLoop () at ./build/../src/backend/postmaster/postmaster.c:1703
#40 0x0000561a3583abbd in PostmasterMain (argc=argc@entry=5,
argv=argv@entry=0x561a53fca7f0) at
./build/../src/backend/postmaster/postmaster.c:1401
#41 0x0000561a3553bb7c in main (argc=5, argv=0x561a53fca7f0) at
./build/../src/backend/main/main.c:227
```

Note: `buf=992779` in frames 17-19 is block 627 (held exclusively); `buffer
= 994553` in frame
13 is block 628 (the buffer being waited on, header dumped in section 7).

## 9. Backtrace of the autovacuum worker (pid 2213934)

```
#0 0x00007fb342ea5e96 in ?? () from /lib/x86_64-linux-gnu/libc.so.6
#1 0x00007fb342eb0d90 in ?? () from /lib/x86_64-linux-gnu/libc.so.6
#2 0x0000561a3582df72 in PGSemaphoreLock (sema=0x7fab1e8dc838) at
./build/src/backend/port/pg_sema.c:326
#3 0x0000561a358c4c0d in LWLockAcquire (lock=0x7fab2866f230,
mode=LW_SHARED) at ./build/../src/backend/storage/lmgr/lwlock.c:1299
#4 0x0000561a355a1dc9 in _bt_lockbuf (rel=rel@entry=0x561a5415a430,
buf=buf@entry=992779, access=access@entry=1) at
./build/../src/backend/access/nbtree/nbtpage.c:1042
#5 0x0000561a355a732b in btvacuumpage (vstate=vstate@entry=0x7ffcb93c3720,
buf=992779) at ./build/../src/backend/access/nbtree/nbtree.c:1383
#6 0x0000561a355a7d98 in btvacuumscan (info=info@entry=0x7ffcb93c39e0,
stats=stats@entry=0x561a54105450, callback=callback@entry=0x0,
callback_state=callback_state@entry=0x0, cycleid=cycleid@entry=0) at
./build/../src/backend/access/nbtree/nbtree.c:1312
#7 0x0000561a355a80a8 in btvacuumcleanup (stats=0x561a54105450,
info=0x7ffcb93c39e0) at ./build/../src/backend/access/nbtree/nbtree.c:1138
#8 btvacuumcleanup (info=0x7ffcb93c39e0, stats=0x0) at
./build/../src/backend/access/nbtree/nbtree.c:1098
#9 0x0000561a356f3faf in vac_cleanup_one_index
(ivinfo=ivinfo@entry=0x7ffcb93c39e0, istat=istat@entry=0x0) at
./build/../src/backend/commands/vacuum.c:2674
#10 0x0000561a35598c99 in lazy_cleanup_one_index (vacrel=0x561a541049b0,
estimated_count=true, reltuples=2712141, istat=0x0, indrel=<optimized out>)
at ./build/../src/backend/access/heap/vacuumlazy.c:3173
#11 lazy_cleanup_all_indexes (vacrel=0x561a541049b0) at
./build/../src/backend/access/heap/vacuumlazy.c:3061
#12 lazy_scan_heap (vacrel=0x561a541049b0) at
./build/../src/backend/access/heap/vacuumlazy.c:1558
#13 heap_vacuum_rel (rel=<optimized out>, params=<optimized out>,
bstrategy=<optimized out>) at
./build/../src/backend/access/heap/vacuumlazy.c:839
#14 0x0000561a356f1afa in table_relation_vacuum (bstrategy=0x561a5418f9e8,
params=0x7ffcb93c3f80, rel=0x561a54156ff0) at
./build/../src/include/access/tableam.h:1677
#15 vacuum_rel (relid=3371211934, relation=<optimized out>,
params=params@entry=0x7ffcb93c3f80,
bstrategy=bstrategy@entry=0x561a5418f9e8) at
./build/../src/backend/commands/vacuum.c:2317
#16 0x0000561a356f2f4a in vacuum (relations=0x561a5419a7d8,
params=params@entry=0x561a54198810,
bstrategy=bstrategy@entry=0x561a5418f9e8,
vac_context=vac_context@entry=0x561a5419a5e0,
isTopLevel=isTopLevel@entry=true) at
./build/../src/backend/commands/vacuum.c:649
#17 0x0000561a35831c7f in autovacuum_do_vac_analyze
(bstrategy=0x561a5418f9e8, tab=0x561a54198808) at
./build/../src/backend/postmaster/autovacuum.c:3196
#18 do_autovacuum () at ./build/../src/backend/postmaster/autovacuum.c:2457
#19 0x0000561a3583224a in AutoVacWorkerMain (startup_data=<optimized out>,
startup_data_len=<optimized out>) at
./build/../src/backend/postmaster/autovacuum.c:1590
#20 0x0000561a35835745 in postmaster_child_launch
(child_type=child_type@entry=B_AUTOVAC_WORKER, child_slot=560, ...) at
./build/../src/backend/postmaster/launch_backend.c:290
#21 0x0000561a358377bd in StartChildProcess (type=B_AUTOVAC_WORKER) at
./build/../src/backend/postmaster/postmaster.c:3962
#22 0x0000561a35839ac8 in StartAutovacuumWorker () at
./build/../src/backend/postmaster/postmaster.c:4026
#23 process_pm_pmsignal () at
./build/../src/backend/postmaster/postmaster.c:3783
#24 ServerLoop () at ./build/../src/backend/postmaster/postmaster.c:1696
#25 0x0000561a3583abbd in PostmasterMain (argc=argc@entry=5,
argv=argv@entry=0x561a53fca7f0) at
./build/../src/backend/postmaster/postmaster.c:1401
#26 0x0000561a3553bb7c in main (argc=5, argv=0x561a53fca7f0) at
./build/../src/backend/main/main.c:227
```

`buf=992779` is block 627, the leaf held exclusively by the INSERT. The read
stream feeding
`btvacuumscan` had already issued block 628 (handle 17445, section 6).

## 10. Backtrace of the SELECT backend (pid 2214042), collateral

```
#0 0x00007fb342ea5e96 in ?? () from /lib/x86_64-linux-gnu/libc.so.6
#1 0x00007fb342eb0d90 in ?? () from /lib/x86_64-linux-gnu/libc.so.6
#2 0x0000561a3582df72 in PGSemaphoreLock (sema=0x7fab1e8d7938) at
./build/src/backend/port/pg_sema.c:326
#3 0x0000561a358c4c0d in LWLockAcquire (lock=0x7fab2866f230,
mode=LW_SHARED) at ./build/../src/backend/storage/lmgr/lwlock.c:1299
#4 0x0000561a355a1d5f in _bt_lockbuf (access=1, buf=992779,
rel=0x561a5418f170) at ./build/../src/backend/access/nbtree/nbtpage.c:1042
#5 _bt_relandgetbuf (rel=rel@entry=0x561a5418f170, obuf=<optimized out>,
blkno=<optimized out>, access=access@entry=1) at
./build/../src/backend/access/nbtree/nbtpage.c:1011
#6 0x0000561a355a9f68 in _bt_search (access=<optimized out>,
bufP=<optimized out>, key=<optimized out>, heaprel=<optimized out>,
rel=<optimized out>) at ./build/../src/backend/access/nbtree/nbtsearch.c:186
#7 _bt_search (rel=0x561a5418f170, heaprel=<optimized out>, key=<optimized
out>, bufP=0x561a541f6808, access=<optimized out>) at
./build/../src/backend/access/nbtree/nbtsearch.c:107
#8 0x0000561a355aa791 in _bt_first (scan=scan@entry=0x561a541f32c8,
dir=dir@entry=BackwardScanDirection) at
./build/../src/backend/access/nbtree/nbtsearch.c:1520
#9 0x0000561a355a6bcf in btgettuple (scan=0x561a541f32c8,
dir=BackwardScanDirection) at
./build/../src/backend/access/nbtree/nbtree.c:245
#10 0x0000561a3559b739 in index_getnext_tid (scan=scan@entry=0x561a541f32c8,
direction=direction@entry=BackwardScanDirection) at
./build/../src/backend/access/index/indexam.c:637
#11 0x0000561a3572bfd4 in IndexOnlyNext (node=0x561a541d8ed0) at
./build/../src/backend/executor/nodeIndexonlyscan.c:122
#12 0x0000561a3572edc9 in ExecProcNode (node=0x561a541d8ed0) at
./build/../src/include/executor/executor.h:315
#13 ExecLimit (pstate=0x561a541d8bc0) at
./build/../src/backend/executor/nodeLimit.c:95
#14 0x0000561a3573da1d in ExecProcNode (node=<optimized out>) at
./build/../src/include/executor/executor.h:315
#15 ExecSetParamPlan (node=0x561a541da6d0,
econtext=econtext@entry=0x561a541da230) at
./build/../src/backend/executor/nodeSubplan.c:1125
#16 0x0000561a35704c7a in ExecEvalParamExec (econtext=0x561a541da230,
op=<optimized out>, state=0x561a541da5d0) at
./build/../src/backend/executor/execExprInterp.c:3064
#17 ExecInterpExpr (state=0x561a541da5d0, econtext=0x561a541da230,
isnull=<optimized out>) at
./build/../src/backend/executor/execExprInterp.c:1322
#18 0x0000561a3573a1f5 in ExecEvalExprNoReturn (econtext=0x561a541da230,
state=0x561a541da5d0) at ./build/../src/include/executor/executor.h:419
#19 ExecEvalExprNoReturnSwitchContext (econtext=0x561a541da230,
state=0x561a541da5d0) at ./build/../src/include/executor/executor.h:460
#20 ExecProject (projInfo=0x561a541da5c8) at
./build/../src/include/executor/executor.h:492
#21 ExecResult (pstate=<optimized out>) at
./build/../src/backend/executor/nodeResult.c:135
#22 0x0000561a35707eda in ExecProcNode (node=0x561a541da128) at
./build/../src/include/executor/executor.h:315
#23 ExecutePlan (dest=0x561a541de868, direction=<optimized out>,
numberTuples=0, sendTuples=true, operation=CMD_SELECT,
queryDesc=0x561a541d8508) at ./build/../src/backend/executor/execMain.c:1711
#24 standard_ExecutorRun (queryDesc=0x561a541d8508, direction=<optimized
out>, count=0) at ./build/../src/backend/executor/execMain.c:366
#25 0x00007fb342c434e5 in pgss_ExecutorRun (queryDesc=0x561a541d8508,
direction=ForwardScanDirection, count=0) at
./build/../contrib/pg_stat_statements/pg_stat_statements.c:1036
#26 0x0000561a358dad97 in PortalRunSelect
(portal=portal@entry=0x561a540efec8, forward=forward@entry=true, count=0,
count@entry=9223372036854775807, dest=dest@entry=0x561a541de868) at
./build/../src/backend/tcop/pquery.c:921
#27 0x0000561a358dc1fb in PortalRun (portal=portal@entry=0x561a540efec8,
count=count@entry=9223372036854775807, isTopLevel=isTopLevel@entry=true,
dest=dest@entry=0x561a541de868, altdest=altdest@entry=0x561a541de868,
qc=qc@entry=0x7ffcb93c4110) at ./build/../src/backend/tcop/pquery.c:765
#28 0x0000561a358d8189 in exec_simple_query (query_string=0x561a5400d0a8
"SET LOCAL statement_timeout = 600000; \n SELECT\n CURRENT_TIMESTAMP,\n
MAX(last_update) as last_update_timestamp,\n (CURRENT_TIMESTAMP -
MAX(last_update))"...) at ./build/../src/backend/tcop/postgres.c:1274
#29 0x0000561a358d9e2c in PostgresMain (dbname=<optimized out>,
username=<optimized out>) at ./build/../src/backend/tcop/postgres.c:4770
#30 0x0000561a358d46bf in BackendMain (startup_data=<optimized out>,
startup_data_len=<optimized out>) at
./build/../src/backend/tcop/backend_startup.c:124
#31 0x0000561a35835745 in postmaster_child_launch (child_type=B_BACKEND,
child_slot=36, ...) at
./build/../src/backend/postmaster/launch_backend.c:290
#32 0x0000561a35839039 in BackendStartup (client_sock=0x7ffcb93c4630) at
./build/../src/backend/postmaster/postmaster.c:3569
#33 ServerLoop () at ./build/../src/backend/postmaster/postmaster.c:1703
#34 0x0000561a3583abbd in PostmasterMain (argc=argc@entry=5,
argv=argv@entry=0x561a53fca7f0) at
./build/../src/backend/postmaster/postmaster.c:1401
#35 0x0000561a3553bb7c in main (argc=5, argv=0x561a53fca7f0) at
./build/../src/backend/main/main.c:227
```

Same LWLock address (0x7fab2866f230) and same buffer (992779 = block 627) as
the autovacuum.