| From: | weijie JL <weijie1006jl(at)gmail(dot)com> |
|---|---|
| To: | Dmytro Astapov <dastapov(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-23 07:15:43 |
| Message-ID: | 9ABA0472-4ECF-4DA7-A55F-BB08D7B19495@gmail.com |
| Views: | Whole Thread | Raw Message | Download mbox | Resend email |
| Thread: | |
| Lists: | pgsql-bugs |
Hi Dmytro,
Thanks for reproducing the issue and for the detailed analysis and proposed fixes. This is very helpful.
Over the past few days, normal SQL queries in our test environment have also triggered this error. To work around the issue in the current version, I’ve switched all our production environments to the default io_method = worker setting.
> 2026年10月22日 01:44,Dmytro Astapov <dastapov(at)gmail(dot)com> 写道:
>
> 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 <mailto: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 <mailto: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 <mailto: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 | Richard Guo | 2026-10-23 07:40:19 | Re: BUG #19765: Wrong result from a chain of LEFT JOINs since v16 |
| Previous Message | Dilip Kumar | 2026-10-23 07:04:37 | Re: BUG #19761: btree_gist: "cannot subtract infinite dates" when inserting 'infinity' into a GiST index on date |