| From: | Dmytro Astapov <dastapov(at)gmail(dot)com> |
|---|---|
| To: | weijie JL <weijie1006jl(at)gmail(dot)com> |
| Cc: | pgsql-bugs(at)lists(dot)postgresql(dot)org |
| Subject: | Re: BUG #19725: PostgreSQL 18.6: pg_restore read failure with io_uring, not observed with worker |
| Date: | 2026-10-21 17:44:37 |
| Message-ID: | CAFQUnFhXYUM1Oj0RqO4UCt92KOk4zqnfGGRVFqxpPSdhrhq7Hw@mail.gmail.com |
| Views: | Whole Thread | Raw Message | Download mbox | Resend email |
| Thread: | |
| Lists: | pgsql-bugs |
Hi!
I can reproduce this on version 18.6 + kernel 6.12.109.el8, and I think
that I have the explanation for how it happens + proposal for the fix as
well.
*What I think is happening*: postgres io_uring requests hit the kernel
codepath where new io workers are spawned up to RLIMIT_NPRPOC. Once this
limit is hit, no new workers can't be spawned, but also postgresmaster
can't fork() or system() anymore, leading to "could not read blocks X..Y in
file ...: Operation canceled"
*How it could be fixed*: postgres should either call
io_uring_register_iowq_max_workers, or don't set IOSQE_ASYNC for reads.
*Detailed description of the chain of events follows:*
*1. Postgres asks io_uring to send buffered reads to worker threads*
In method_io_uring.c (line 441), once a backend already has more than 4
I/Os in flight, every further buffered read gets IOSQE_ASYNC:
if (in_flight_before > 4 && (ioh->flags & PGAIO_HF_BUFFERED))
io_uring_sqe_set_flags(sqe, IOSQE_ASYNC);
If `maintenance_io_concurrency` is higher that 4, then all of the
maintenance reads starting from 5th will take this path.
*2. The kernel places these reads into the pool whose only cap is
RLIMIT_NPROC*
Each task's io_uring worker pool has two halves:
- bounded (meant for regular files), capped at min(sq_entries, 4*ncpu);
- unbound, capped only at the task's RLIMIT_NPROC (io-wq.c).
Requests are classified in io_prep_async_work (
https://github.com/torvalds/linux/blob/v6.12/io_uring/io_uring.c#L480-L492)
if (req->file && (req->flags & REQ_F_ISREG)) { ... bound ... }
else if (!req->file || !S_ISBLK(...)) {
if (def->unbound_nonreg_file) // set for READ/READV
atomic_or(IO_WQ_WORK_UNBOUND, ...);
}
However, io_init_req sets req->file = NULL (at
https://github.com/torvalds/linux/blob/v6.12/io_uring/io_uring.c#L2046)
and the file is only attached later, at issue time. An IOSQE_ASYNC request
goes straight though io_queue_iowq() to io_prep_async_work() while
`req->file` is still NULL.
So a read of a regular file ends up routed to the unbound pool, whose cap
is RLIMIT_NPROC (65536), not a capped one. IOSQE_ASYNC also marks the work
as IO_WQ_WORK_CONCURRENT, which lets each enqueue create a worker instead
of waiting for a running one.
*3. Workers get created far faster than the actual I/O needs*
In io_wq_dec_running, when a worker blocks and it was the last running
worker while work is still queued, the kernel queues creation of a
brand-new worker immediately.
It doesn't wake one of the idle workers. On a cold buffer cache almost
every read blocks on disk, so this code path fires constantly. As a result,
the new worker handles one item and then goes idle. Only the head of the
free list gets reused, so the rest of the workers sit idle until
WORKER_IDLE_TIMEOUT = 5s expires and then they exit.
As a result, the steady-state thread count is therefore roughly "creation
rate × 5 s", not "I/Os in flight". The cap for the workers, as was
mentioned earlier, is RLIMIT_NPROC.
*Similar threads or bugs from the past*
-
Justin Pryzby on pgsql-hackers
<https://www.mail-archive.com/pgsql-hackers(at)lists(dot)postgresql(dot)org/msg208462.html>
(2025-10-17)
reported could not read blocks 122..126 ...: Operation canceled from
pg_dump under io_uring. He guessed it might be related to the io_uring
file descriptors leaking after crash-restarts, but I cannot find a
resolution.
-
Alexander Lakhin's AIO stress test
<https://www.mail-archive.com/pgsql-hackers(at)lists(dot)postgresql(dot)org/msg196158.html>
(pgsql-hackers,
April 2025, before 18.0) hit could not read blocks 0..0 in file
"global/1213": Operation canceled with parallel createdb/dropdb jobs, on
kernels 6.8 and 6.11. The bugs fixed later in that thread (1
<https://www.mail-archive.com/pgsql-hackers(at)lists(dot)postgresql(dot)org/msg196804.html>
, 2
<https://www.mail-archive.com/pgsql-hackers(at)lists(dot)postgresql(dot)org/msg197025.html>)
were different ones, a pg_aios crash and a PANIC from interrupt
handling. As far as I can see, the ECANCELED was never explained or fixed.
io_uring bugs that look relevant to me
-
liburing #420 <https://github.com/axboe/liburing/issues/420> (2021): a
user found IOSQE_ASYNC "spawns a thread for each request, meaning 10000+
threads". There is a commen there that bounded work is limited but
unbounded work "really [is] not". That discussion led to creation of
IORING_REGISTER_IOWQ_MAX_WORKERS.
-
liburing #349 <https://github.com/axboe/liburing/issues/349> (2021)
reported "unexpected high count of io_worker threads by using the
IOSQE_ASYNC flag".
-
Cloudflare, "Missing Manuals – io_uring worker pool"
<https://blog.cloudflare.com/missing-manuals-io_uring-worker-pool/> explains
that unbound workers default to RLIMIT_NPROC for each thread, and that
raising RLIMIT_NPROC without IORING_REGISTER_IOWQ_MAX_WORKERS can
backfire. The io_uring_register_iowq_max_workers(3)
<https://man7.org/linux/man-pages/man3/io_uring_register_iowq_max_workers.3.html>
man
page says the same.
So, in conclusion, it looks to me that the issue is that req->file is still
NULL when an IOSQE_ASYNC request is classified, and the reads end up in the
unbound pool, and the fix is either to call
io_uring_register_iowq_max_workers, or don't set IOSQE_ASYNC for reads.
Best regards, Dmytro
On Sun, Oct 4, 2026 at 10:51 AM weijie JL <weijie1006jl(at)gmail(dot)com> wrote:
> After setting backtrace_functions=md_readv_report, I received more log
> information:
> 2026-10-04 17:46:08.322 CST [local] test001 postgres [154450]LOG: XX000:
> could not read blocks 143..158 in file "base/6406098/6407866": Operation
> canceled
> 2026-10-04 17:46:08.322 CST [local] test001 postgres [154450]LOCATION:
> md_readv_report, md.c:2059
> 2026-10-04 17:46:08.322 CST [local] test001 postgres [154450]BACKTRACE:
> postgres: postgres test001 [local] CREATE INDEX() [0x92eafc]
> postgres: postgres test001 [local] CREATE INDEX() [0x92f7ec]
> postgres: postgres test001 [local] CREATE
> INDEX(pgaio_io_call_complete_shared+0xfa) [0x8ef3ea]
> postgres: postgres test001 [local] CREATE INDEX() [0x8f209c]
> postgres: postgres test001 [local] CREATE INDEX() [0x8f2b63]
> postgres: postgres test001 [local] CREATE INDEX() [0x8f0127]
> postgres: postgres test001 [local] CREATE
> INDEX(WaitReadBuffers+0x1f7) [0x8f5137]
> postgres: postgres test001 [local] CREATE
> INDEX(read_stream_next_buffer+0x211) [0x8f6ac1]
> postgres: postgres test001 [local] CREATE INDEX() [0x5874d6]
> postgres: postgres test001 [local] CREATE INDEX(heap_getnext+0x88)
> [0x5878e8]
> postgres: postgres test001 [local] CREATE INDEX() [0x58dcbd]
> postgres: postgres test001 [local] CREATE INDEX() [0x5b11ae]
> postgres: postgres test001 [local] CREATE INDEX(btbuild+0xb05)
> [0x5b7325]
> postgres: postgres test001 [local] CREATE INDEX(index_build+0x19c)
> [0x61fa2c]
> postgres: postgres test001 [local] CREATE
> INDEX(index_create+0x1328) [0x621608]
> postgres: postgres test001 [local] CREATE INDEX(DefineIndex+0x9bb)
> [0x6d11cb]
> postgres: postgres test001 [local] CREATE INDEX() [0xb18111]
> postgres: postgres test001 [local] CREATE
> INDEX(standard_ProcessUtility+0x3f8) [0x93c1d8]
> /usr/pgsql-18/lib/pg_stat_statements.so(+0x7375) [0x7f209b366375]
> postgres: postgres test001 [local] CREATE INDEX() [0x93cc3a]
> postgres: postgres test001 [local] CREATE INDEX() [0x93cdaf]
> postgres: postgres test001 [local] CREATE INDEX(PortalRun+0x291)
> [0x93d371]
> postgres: postgres test001 [local] CREATE INDEX() [0x935ab0]
> postgres: postgres test001 [local] CREATE
> INDEX(PostgresMain+0x1f1b) [0x937f6b]
> postgres: postgres test001 [local] CREATE INDEX() [0x9389d5]
> postgres: postgres test001 [local] CREATE
> INDEX(postmaster_child_launch+0x12d) [0x888ced]
> postgres: postgres test001 [local] CREATE INDEX() [0x891cb2]
> postgres: postgres test001 [local] CREATE
> INDEX(PostmasterMain+0xce9) [0x894309]
> postgres: postgres test001 [local] CREATE INDEX(main+0x1d0)
> [0x531bc0]
> /lib64/libc.so.6(+0x2a610) [0x7f209b82a610]
> /lib64/libc.so.6(__libc_start_main+0x80) [0x7f209b82a6c0]
> postgres: postgres test001 [local] CREATE INDEX(_start+0x25)
> [0x5321b5]
> 2026-10-04 17:46:08.322 CST [local] test001 postgres [154450]STATEMENT:
> CREATE INDEX idx_sys_notification_channel_notification_id ON
> dhr.sys_notification_channel USING btree (c_notification_id);
>
>
>
>
>
> > 2026年9月28日 11:34,PG Bug reporting form <noreply(at)postgresql(dot)org> 写道:
> >
> > The following bug has been logged on the website:
> >
> > Bug reference: 19725
> > Logged by: weijie JL
> > Email address: weijie1006jl(at)gmail(dot)com
> > PostgreSQL version: 18.6
> > Operating system: RockyLinux9
> > Description:
> >
> > Hello,
> >
> > I can reproduce a read failure during pg_restore with io_method=io_uring.
> > The error disappears with worker and recurs after switching back to
> > io_uring.
> >
> > Environment:
> > - PostgreSQL 18.6, x86_64
> > - VMware VM: 8 vCPUs, 32 GB RAM
> > - Kernel: 5.14.0-611.55.1.el9_7.x86_64
> >
> > Settings:
> > effective_io_concurrency = 256
> > maintenance_io_concurrency = 16
> > max_parallel_maintenance_workers = 2
> >
> > Restore command:
> > nohup pg_restore -d test001 dhr.dump/ -j8 -v > test.log 2>&1 &
> >
> > One failing statement:
> > ALTER TABLE ONLY dhr.obj_permission_object
> > ADD CONSTRAINT obj_permission_object_pkey PRIMARY KEY (id);
> >
> > Server error:
> > ERROR: could not read blocks 143..158 in file "base/1684908/1686127":
> > Operation canceled
> > LOCATION: md_readv_report, md.c:2059
> > SQLSTATE: XX000
> >
> > Observed test sequence:
> > 1. io_method=io_uring: the read error occurred during index creation.
> > 2. Changed io_method to worker: retried without errors.
> > 3. Changed io_method back to io_uring: the read error was reproduced.
> >
> > I have not measured the failure rate or prepared a self-contained
> > minimal reproducer.
> >
> > One earlier run also reported "could not map dynamic shared memory
> > segment" from parallel workers immediately after the read error.
> > Those DSM errors have not recurred in subsequent failing tests.
> >
> > Does this match a known PostgreSQL bug or kernel-side io_uring issue?
> > What additional logs or tracing would help identify the cause?
> >
> > Thank you.
> >
> >
>
>
>
>
| From | Date | Subject | |
|---|---|---|---|
| Next Message | Nitin Motiani | 2026-10-21 18:39:31 | Re: BUG #19773: pg_dump omits a different generation expression of an inherited column in a child table |
| Previous Message | Jesper St John | 2026-10-21 17:16:18 | Re: Timing issue in pg_basebackup |