Re: Direct I/O

Hi,

I'm hitting a panic in t_004_io_direct. The build is running on
overlayfs on tmpfs/ext4 (upper/lower) which is probably a weird
combination but has worked well for building everything over the last
decade. On Debian unstable:

PANIC:  could not open file "pg_wal/000000010000000000000001": Invalid argument

16:21:16 Bailout called.  Further testing stopped:  pg_ctl start failed
16:21:16 t/004_io_direct.pl ..............
16:21:16 Dubious, test returned 255 (wstat 65280, 0xff00)
16:21:16 No subtests run
16:21:16
16:21:16 Test Summary Report
16:21:16 -------------------
16:21:16 t/004_io_direct.pl            (Wstat: 65280 (exited 255) Tests: 0 Failed: 0)
16:21:16   Non-zero exit status: 255
16:21:16   Parse errors: No plan found in TAP output
16:21:16 Files=4, Tests=65,  9 wallclock secs ( 0.03 usr  0.02 sys +  3.78 cusr  1.48 csys =  5.31 CPU)
16:21:16 Result: FAIL

16:21:16 ******** build/src/test/modules/test_misc/tmp_check/log/004_io_direct_main.log ********
16:21:16 2023-04-11 23:21:16.431 UTC [25991] LOG:  starting PostgreSQL 16devel (Debian
16~~devel-1.pgdg+~20230411.2256.gc03c2ea)on x86_64-pc-linux-gnu, compiled by gcc (Debian 12.2.0-14) 12.2.0, 64-bit
 
16:21:16 2023-04-11 23:21:16.431 UTC [25991] LOG:  listening on Unix socket "/tmp/s0C4hWQq82/.s.PGSQL.54693"
16:21:16 2023-04-11 23:21:16.433 UTC [25994] LOG:  database system was shut down at 2023-04-11 23:21:16 UTC
16:21:16 2023-04-11 23:21:16.434 UTC [25994] PANIC:  could not open file "pg_wal/000000010000000000000001": Invalid
argument
16:21:16 2023-04-11 23:21:16.525 UTC [25991] LOG:  startup process (PID 25994) was terminated by signal 6: Aborted
16:21:16 2023-04-11 23:21:16.525 UTC [25991] LOG:  aborting startup due to startup process failure
16:21:16 2023-04-11 23:21:16.526 UTC [25991] LOG:  database system is shut down

16:21:16 ******** build/src/test/modules/test_misc/tmp_check/t_004_io_direct_main_data/pgdata/core ********
16:21:17
16:21:17 warning: Can't open file /dev/shm/PostgreSQL.3457641370 during file-backed mapping note processing
16:21:17
16:21:17 warning: Can't open file /dev/shm/PostgreSQL.2391834648 during file-backed mapping note processing
16:21:17
16:21:17 warning: Can't open file /dev/zero (deleted) during file-backed mapping note processing
16:21:17
16:21:17 warning: Can't open file /SYSV00000dea (deleted) during file-backed mapping note processing
16:21:17 [New LWP 25994]
16:21:17 [Thread debugging using libthread_db enabled]
16:21:17 Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
16:21:17 Core was generated by `postgres: main: startup                                                       '.
16:21:17 Program terminated with signal SIGABRT, Aborted.
16:21:17 #0  0x00007f176c591ccc in ?? () from /lib/x86_64-linux-gnu/libc.so.6
16:21:17 #0  0x00007f176c591ccc in ?? () from /lib/x86_64-linux-gnu/libc.so.6
16:21:17 No symbol table info available.
16:21:17 #1  0x00007f176c542ef2 in raise () from /lib/x86_64-linux-gnu/libc.so.6
16:21:17 No symbol table info available.
16:21:17 #2  0x00007f176c52d472 in abort () from /lib/x86_64-linux-gnu/libc.so.6
16:21:17 No symbol table info available.
16:21:17 #3  0x000055a7ba7978a1 in errfinish (filename=<optimized out>, lineno=<optimized out>, funcname=0x55a7ba810560
<__func__.47>"XLogFileInitInternal") at ./build/../src/backend/utils/error/elog.c:604
 
16:21:17         edata = 0x55a7baae3e20 <errordata>
16:21:17         elevel = 23
16:21:17         oldcontext = 0x55a7bb471590
16:21:17         econtext = 0x0
16:21:17         __func__ = "errfinish"
16:21:17 #4  0x000055a7ba21759c in XLogFileInitInternal (logsegno=1, logtli=logtli@entry=1,
added=added@entry=0x7ffebc6c8a3f,path=path@entry=0x7ffebc6c8a40 "pg_wal/00000001", '0' <repeats 15 times>, "1") at
./build/../src/backend/access/transam/xlog.c:2944
16:21:17         __errno_location = <optimized out>
16:21:17         tmppath =
"0\214l\274\376\177\000\000\321\330~\272\247U\000\000\005Q\223\272\247U\000\000p\214l\274\376\177\000\000`\214l\274\376\177\000\000\212\335~\000\v",
'\000'<repeats 31 times>,
"\247U\000\000\000\000\000\000\000\177\000\000*O\202\272\247U\000\000\254\206l\274\376\177\000\000\000\000\000\000\v",
'\000'<repeats 23 times>,
"0\000\000\000\000\000\000\000\247U\000\000\000\000\000\000\000\000\000\000\001Q\223\272\247U\000\000\240\215l\274\376\177\000\000\376\377\377\377\000\000\000\0000\207l\274\376\177\000\000[\326~\272\247U\000\0000\207l\274\376\177\000\000"...
16:21:17         installed_segno = 0
16:21:17         max_segno = <optimized out>
16:21:17         fd = <optimized out>
16:21:17         save_errno = <optimized out>
16:21:17         open_flags = 194
16:21:17         __func__ = "XLogFileInitInternal"
16:21:17 #5  0x000055a7ba35a1d5 in XLogFileInit (logsegno=<optimized out>, logtli=logtli@entry=1) at
./build/../src/backend/access/transam/xlog.c:3099
16:21:17         ignore_added = false
16:21:17         path = "pg_wal/00000001", '0' <repeats 15 times>,
"1\000\220\312P\273\247U\000\000/\375Yl\027\177\000\000\220\252P\273\247U\000\000\001",'\000' <repeats 15 times>,
"\220\252P\273\247U\000\000\300\212l\274\376\177\000\000\002\261{\272\247U\000\000\220\252P\273\247U\000\000\220\252P\273\247U\000\000\001",
'\000'<repeats 15 times>,
"\340\212l\274\376\177\000\000\021\032|\272\247U\000\000\000\000\000\000\000\000\000\000\240\312P\273\247U\000\0000\213l\274\376\177\000\000\350\262{\272\247U\000\000\001",
'\000'<repeats 16 times>, "\256\023i\027\177\000\000"...
 
16:21:17         fd = <optimized out>
16:21:17         __func__ = "XLogFileInit"
16:21:17 #6  0x000055a7ba35bab3 in XLogWrite (WriteRqst=..., tli=tli@entry=1, flexible=flexible@entry=false) at
./build/../src/backend/access/transam/xlog.c:2137
16:21:17         EndPtr = 21954560
16:21:17         ispartialpage = true
16:21:17         last_iteration = <optimized out>
16:21:17         finishing_seg = <optimized out>
16:21:17         curridx = 7
16:21:17         npages = 0
16:21:17         startidx = 0
16:21:17         startoffset = 0
16:21:17         __func__ = "XLogWrite"
16:21:17 #7  0x000055a7ba35c8e0 in XLogFlush (record=21949600) at ./build/../src/backend/access/transam/xlog.c:2638
16:21:17         insertpos = 21949600
16:21:17         WriteRqstPtr = 21949600
16:21:17         WriteRqst = <optimized out>
16:21:17         insertTLI = 1
16:21:17         __func__ = "XLogFlush"
16:21:17 #8  0x000055a7ba36118e in XLogReportParameters () at ./build/../src/backend/access/transam/xlog.c:7620
16:21:17         xlrec = {MaxConnections = 100, max_worker_processes = 8, max_wal_senders = 0, max_prepared_xacts = 0,
max_locks_per_xact= 64, wal_level = 1, wal_log_hints = false, track_commit_timestamp = false}
 
16:21:17         recptr = <optimized out>
16:21:17 #9  StartupXLOG () at ./build/../src/backend/access/transam/xlog.c:5726
16:21:17         Insert = <optimized out>
16:21:17         checkPoint = <optimized out>
16:21:17         wasShutdown = true
16:21:17         didCrash = <optimized out>
16:21:17         haveTblspcMap = false
16:21:17         haveBackupLabel = false
16:21:17         EndOfLog = 21949544
16:21:17         EndOfLogTLI = <optimized out>
16:21:17         newTLI = 1
16:21:17         performedWalRecovery = <optimized out>
16:21:17         endOfRecoveryInfo = <optimized out>
16:21:17         abortedRecPtr = <optimized out>
16:21:17         missingContrecPtr = 0
16:21:17         oldestActiveXID = <optimized out>
16:21:17         promoted = false
16:21:17         __func__ = "StartupXLOG"
16:21:17 #10 0x000055a7ba5b4d00 in StartupProcessMain () at ./build/../src/backend/postmaster/startup.c:267
16:21:17 No locals.
16:21:17 #11 0x000055a7ba5ab0cf in AuxiliaryProcessMain (auxtype=auxtype@entry=StartupProcess) at
./build/../src/backend/postmaster/auxprocess.c:141
16:21:17         __func__ = "AuxiliaryProcessMain"
16:21:17 #12 0x000055a7ba5b0aa3 in StartChildProcess (type=StartupProcess) at
./build/../src/backend/postmaster/postmaster.c:5369
16:21:17         pid = <optimized out>
16:21:17         __func__ = "StartChildProcess"
16:21:17         save_errno = <optimized out>
16:21:17         __errno_location = <optimized out>
16:21:17         __errno_location = <optimized out>
16:21:17         __errno_location = <optimized out>
16:21:17         __errno_location = <optimized out>
16:21:17         __errno_location = <optimized out>
16:21:17         __errno_location = <optimized out>
16:21:17         __errno_location = <optimized out>
16:21:17 #13 0x000055a7ba5b45d6 in PostmasterMain (argc=argc@entry=4, argv=argv@entry=0x55a7bb471450) at
./build/../src/backend/postmaster/postmaster.c:1455
16:21:17         opt = <optimized out>
16:21:17         status = <optimized out>
16:21:17         userDoption = <optimized out>
16:21:17         listen_addr_saved = <optimized out>
16:21:17         i = <optimized out>
16:21:17         output_config_variable = <optimized out>
16:21:17         __func__ = "PostmasterMain"
16:21:17 #14 0x000055a7ba29fd62 in main (argc=4, argv=0x55a7bb471450) at ./build/../src/backend/main/main.c:200
16:21:17         do_check_root = <optimized out>

Apologies if this was already reported elsewhere in the thread, I
skimmed it but the problems looked different.

Christoph