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(at)entry=1, added=added(at)entry=0x7ffebc6c8a3f, path=path(at)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(at)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(at)entry=1, flexible=flexible(at)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(at)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(at)entry=4, argv=argv(at)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