Horton

Re: AIO v2.5

Andres Freund <andres@anarazel.de>

View thread
From: Andres Freund <andres@anarazel.de>
To: Alexander Lakhin <exclusion@gmail.com>
Cc: pgsql-hackers@postgresql.org, Thomas Munro <thomas.munro@gmail.com>, Heikki Linnakangas <hlinnaka@iki.fi>, Robert Haas <robertmhaas@gmail.com>, Jakub Wartak <jakub.wartak@enterprisedb.com>, Jelte Fennema-Nio <postgres@jeltef.nl>, Antonin Houska <ah@cybertec.at>, Noah Misch <noah@leadboat.com>
Date: 2025-04-24T00:40:48Z
Lists: pgsql-hackers

Commits

Same data as JSON: GET /api/v1/messages/:b64id/commits the thread's linked commits as JSON, with link sources. API reference →

  1. aio: Fix assertion, clarify README

  2. aio: Fix reference to outdated name

  3. aio: Fix possible state confusions due to interrupt processing

  4. aio: Improve debug logging around waiting for IOs

  5. aio: Fix crash potential for pg_aios views due to late state update

  6. Increase BAS_BULKREAD based on effective_io_concurrency

  7. localbuf: Add Valgrind buffer access instrumentation

  8. aio: Make AIO more compatible with valgrind

  9. aio: Avoid spurious coverity warning

  10. tests: Fix incompatibility of test_aio with *_FORCE_RELEASE

  11. tests: Cope with WARNINGs during failed CREATE DB on windows

  12. aio: Add errcontext for processing I/Os for another backend

  13. aio: Add README.md explaining higher level design

  14. aio: Minor comment improvements

  15. aio: Add test_aio module

  16. aio: Add pg_aios view

  17. docs: Add acronym and glossary entries for I/O and AIO

  18. Enable IO concurrency on all systems

  19. read_stream: Introduce and use optional batchmode support

  20. docs: Reframe track_io_timing related docs as wait time

  21. bufmgr: Use AIO in StartReadBuffers()

  22. bufmgr: Implement AIO read support

  23. aio: Add WARNING result status

  24. Let caller of PageIsVerified() control ignore_checksum_failure

  25. pgstat: Allow checksum errors to be reported in critical sections

  26. Add errhint_internal()

  27. localbuf: Track pincount in BufferDesc as well

  28. aio, bufmgr: Comment fixes/improvements

  29. Fix mis-attribution of checksum failure stats to the wrong database

  30. aio: Implement support for reads in smgr/md/fd

  31. aio: Add io_method=io_uring

  32. aio: Add liburing dependency

  33. aio: Rename pgaio_io_prep_* to pgaio_io_start_*

  34. aio: Pass result of local callbacks to ->report_return

  35. aio: Be more paranoid about interrupts

  36. Redefine max_files_per_process to control additionally opened files

  37. aio: Change prefix of PgAioResultStatus values to PGAIO_RS_

  38. bufmgr: Improve stats when a buffer is read in concurrently

  39. aio: Add io_method=worker

  40. aio: Infrastructure for io_method=worker

  41. aio: Add core asynchronous I/O infrastructure

  42. aio: Basic subsystem initialization

  43. tests: Expand temp table tests to some pin related matters

  44. localbuf: Introduce FlushLocalBuffer()

  45. localbuf: Introduce TerminateLocalBufferIO()

  46. localbuf: Fix dangerous coding pattern in GetLocalVictimBuffer()

  47. localbuf: Introduce StartLocalBufferIO()

  48. localbuf: Introduce InvalidateLocalBuffer()

  49. Allow lwlocks to be disowned

  50. Make jsonb casts to scalar types translate JSON null to SQL NULL.

  51. bufmgr/smgr: Don't cross segment boundaries in StartReadBuffers()

  52. Use aux process resource owner in walsender

  53. bufmgr: Return early in ScheduleBufferTagForWriteback() if fsync=off

Hi,

On 2025-04-20 18:00:00 +0300, Alexander Lakhin wrote:
> 31.03.2025 02:46, Andres Freund wrote:
> > I've pushed most of these after some very light further editing.  Yay.  Thanks
> > a lot for all the reviews!
> > 
> > So far the buildfarm hasn't been complaining, but it's early days.
> 
> I found one complaint against commit 12ce89fd0, expressed as:
> https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=scorpion&dt=2025-04-08%2001%3A36%3A41

Thanks for pointing that out and repro'ing it!


> 2025-04-08 01:41:54.670 UTC [4013251][client backend][0/2:0] DEBUG: waiting for self with 0 pending

I'd like to extend this debug message with the number of in-flight IOs.  I
assume nobody will mind me doing that.



> I could reproduce this error with the following TEMP_CONFIG:
> log_min_messages = DEBUG4
> 
> log_connections = on
> log_disconnections = on
> log_statement = 'all'
> log_line_prefix = '%m [%d][%p:%l][%b] %q[%a] '
> 
> fsync = on
> io_method=io_uring
> backtrace_functions = 'pgaio_io_wait_for_free'

Hm. Several hundred iterations in without triggering the issue even once, with
that added config. Given your reproducer used fsync, I assume this was on a
real filesystem not tmpfs? What FS?  I tried on XFS.

very well could just be a timing dependent issue, the time for an fsync will
differ heavily betweeen devices...


> When running 032_relfilenode_reuse.pl in a loop, I got failures on
> iterations 10, 18, 6:
> 2025-04-20 15:56:01.310 CEST [][1517068:122][startup] DEBUG: updated min recovery point to 0/4296E90 on timeline 1
> 2025-04-20 15:56:01.310 CEST [][1517068:123][startup] CONTEXT:  WAL redo at
> 0/4296E48 for Transaction/COMMIT: 2025-04-20 15:56:01.09363+02; inval msgs:
> catcache 21; sync
> 2025-04-20 15:56:01.310 CEST [][1517068:124][startup] DEBUG: waiting for all
> backends to process ProcSignalBarrier generation 5
> 2025-04-20 15:56:01.310 CEST [][1517068:125][startup] CONTEXT:  WAL redo at 0/4296E90 for Database/DROP: dir 16409/50001
> 2025-04-20 15:56:01.312 CEST [postgres][1517075:144][client backend]
> [032_relfilenode_reuse.pl] DEBUG:  waiting for self with 0 pending
> 2025-04-20 15:56:01.312 CEST [postgres][1517075:145][client backend] [032_relfilenode_reuse.pl] BACKTRACE:
> pgaio_io_wait_for_free at aio.c:703:2
>  (inlined by) pgaio_io_acquire at aio.c:186:3
> AsyncReadBuffers at bufmgr.c:1854:9
> StartReadBuffersImpl at bufmgr.c:1425:18
>  (inlined by) StartReadBuffers at bufmgr.c:1497:9
> read_stream_start_pending_read at read_stream.c:333:25
> read_stream_look_ahead at read_stream.c:475:3
> read_stream_next_buffer at read_stream.c:840:6
> pg_prewarm at pg_prewarm.c:214:10
> ExecInterpExpr at execExprInterp.c:927:7
> ExecEvalExprNoReturn at executor.h:447:2
> ...
> 2025-04-20 15:56:01.312 CEST [][1517068:126][startup] DEBUG: finished
> waiting for all backends to process ProcSignalBarrier generation 5
> 2025-04-20 15:56:01.312 CEST [][1517068:127][startup] CONTEXT:  WAL redo at 0/4296E90 for Database/DROP: dir 16409/50001
> 2025-04-20 15:56:01.314 CEST [postgres][1517075:146][client backend]
> [032_relfilenode_reuse.pl] ERROR:  no free IOs despite no in-flight IOs

The earlier report also had a ProcSignalBarrier wait just before. That's
doesn't have to be related, the test stresses those pretty intentionally.

But it does seem like it could be related, perhaps we somehow end processing
interrupts while issuing IOs, which then again submits IOs or something? I
don't immediately see such code, e.g. pgaio_closing_fd() is careful to iterate
over the list while waiting.

I think pgaio_closing_fd() should get a DEBUG2 (or so) message documenting
that we are waiting for an IO due to closing an FD. pgaio_shutdown() as well,
while at it.


I somewhat suspect that this is the same issue that you reported earlier, that
I also couldn't repro.  That involved a lot of CREATE DATABASEs, which will
trigger a lot of procsignal barriers...  I'll try to come up with a more
dedicated stress test and see whether I can trigger a problem that way.


> I also encountered another failure when running this test:
> t/032_relfilenode_reuse.pl .. 1/? Bailout called.  Further testing stopped:  aborting wait: program died
> 
> Core was generated by `postgres: standby: law postgres [local] SELECT                   '.
> Program terminated with signal SIGABRT, Aborted.
> #0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:44
> 
> (gdb) bt
> #0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:44
> #1  __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78
> #2  __GI___pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
> #3  0x0000700a5a24527e in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
> #4  0x0000700a5a2288ff in __GI_abort () at ./stdlib/abort.c:79
> #5  0x0000630ff2c5dcea in errfinish (filename=filename@entry=0x630ff2cdd139 "aio.c", lineno=lineno@entry=559,
>     funcname=funcname@entry=0x630ff2e85da8 <__func__.9> "pgaio_io_wait") at elog.c:599
> #6  0x0000630ff2aae79c in pgaio_io_wait (ioh=ioh@entry=0x700a57b59700, ref_generation=3972) at aio.c:559
> #7  0x0000630ff2aaefab in pgaio_io_wait_for_free () at aio.c:771

Do you still have the core file for this? Or at least the generated log
message? It'd be useful to know what state the IO was in when the error was
triggered...

Greetings,

Andres Freund