Thread: core dumps in auto_prewarm, tests succeed
Hi,
I noticed that I was getting core dumps while executing the tests, without the
tests failing. Backtraces are vriations of this:
#0 0x0000000000ca29cd in pg_atomic_read_u32_impl (ptr=0x7fe13497a004) at
../../../../../home/andres/src/postgresql/src/include/port/atomics/generic.h:48
#1 0x0000000000ca2b08 in pg_atomic_read_u32 (ptr=0x7fe13497a004) at
../../../../../home/andres/src/postgresql/src/include/port/atomics.h:239
#2 0x0000000000ca3c3d in LWLockAttemptLock (lock=0x7fe13497a000, mode=LW_EXCLUSIVE)
at ../../../../../home/andres/src/postgresql/src/backend/storage/lmgr/lwlock.c:825
#3 0x0000000000ca440c in LWLockAcquire (lock=0x7fe13497a000, mode=LW_EXCLUSIVE)
at ../../../../../home/andres/src/postgresql/src/backend/storage/lmgr/lwlock.c:1264
#4 0x00007fe130204ab4 in apw_detach_shmem (code=0, arg=0) at
../../../../../home/andres/src/postgresql/contrib/pg_prewarm/autoprewarm.c:788
#5 0x0000000000c81c99 in shmem_exit (code=0) at
../../../../../home/andres/src/postgresql/src/backend/storage/ipc/ipc.c:276
#6 0x0000000000c81a7c in proc_exit_prepare (code=0) at
../../../../../home/andres/src/postgresql/src/backend/storage/ipc/ipc.c:198
#7 0x0000000000c819a8 in proc_exit (code=0) at
../../../../../home/andres/src/postgresql/src/backend/storage/ipc/ipc.c:111
#8 0x0000000000bdd0b3 in BackgroundWorkerMain () at
../../../../../home/andres/src/postgresql/src/backend/postmaster/bgworker.c:841
#9 0x0000000000be861d in do_start_bgworker (rw=0x341ff20) at
../../../../../home/andres/src/postgresql/src/backend/postmaster/postmaster.c:5756
#10 0x0000000000be8a34 in maybe_start_bgworkers () at
../../../../../home/andres/src/postgresql/src/backend/postmaster/postmaster.c:5980
#11 0x0000000000be4f9f in process_pm_child_exit () at
../../../../../home/andres/src/postgresql/src/backend/postmaster/postmaster.c:3039
#12 0x0000000000be2de4 in ServerLoop () at
../../../../../home/andres/src/postgresql/src/backend/postmaster/postmaster.c:1765
#13 0x0000000000be27bf in PostmasterMain (argc=4, argv=0x33dbba0) at
../../../../../home/andres/src/postgresql/src/backend/postmaster/postmaster.c:1475
#14 0x0000000000aca326 in main (argc=4, argv=0x33dbba0) at
../../../../../home/andres/src/postgresql/src/backend/main/main.c:198
The most likely culprit seems to be:
https://postgr.es/m/E1rQvjC-002Chd-Cd%40gemulon.postgresql.org
The test encountering this is pg_prewarm/001_basic:
(gdb) p DataDir
$12 = 0x33ef8a0 "/srv/dev/build/postgres/m-dev-assert/testrun/pg_prewarm/001_basic/data/t_001_basic_main_data/pgdata"
A secondary issue is that the tests suceed despite two segfaults. The problem
here likely is that we don't have sufficient error handling during shutdowns:
2024-01-22 12:31:34.133 PST [3054823] LOG: background worker "logical replication launcher" (PID 3054836) exited with
exitcode 1
2024-01-22 12:31:34.443 PST [3054823] LOG: background worker "autoprewarm leader" (PID 3054835) was terminated by
signal11: Segmentation fault
2024-01-22 12:31:34.443 PST [3054823] LOG: terminating any other active server processes
2024-01-22 12:31:34.444 PST [3054823] LOG: abnormal database system shutdown
2024-01-22 12:31:34.469 PST [3054823] LOG: database system is shut down
2024-01-22 12:31:34.555 PST [3055133] LOG: starting PostgreSQL 17devel on x86_64-linux, compiled by gcc-14.0.0,
64-bit
2024-01-22 12:31:34.555 PST [3055133] LOG: listening on Unix socket "/tmp/p6XG0kQW9w/.s.PGSQL.60402"
2024-01-22 12:31:34.557 PST [3055148] LOG: database system was interrupted; last known up at 2024-01-22 12:31:33 PST
2024-01-22 12:31:34.557 PST [3055148] LOG: database system was not properly shut down; automatic recovery in progress
2024-01-22 12:31:34.558 PST [3055148] LOG: redo starts at 0/1531090
2024-01-22 12:31:34.559 PST [3055148] LOG: invalid record length at 0/1555F60: expected at least 24, got 0
2024-01-22 12:31:34.559 PST [3055148] LOG: redo done at 0/1555F38 system usage: CPU: user: 0.00 s, system: 0.00 s,
elapsed:0.00 s
2024-01-22 12:31:34.559 PST [3055146] LOG: checkpoint starting: end-of-recovery immediate wait
2024-01-22 12:31:34.570 PST [3055146] LOG: checkpoint complete: wrote 42 buffers (0.3%); 0 WAL file(s) added, 0
removed,0 recycled; write=0.002 s, sync=0.001 s, total=0.011 s; sync files=0, longest=0.000 s, average=0.000 s;
distance=147kB, estimate=147 kB; lsn=0/1555F60, redo lsn=0/1555F60
2024-01-22 12:31:34.573 PST [3055133] LOG: database system is ready to accept connections
ISTM that we shouldn't basically silently overlook shutdowns due to crashes in
the tests. How to not do so is unfortunately not immediately obvious to me...
Greetings,
Andres Freund
On Mon, Jan 22, 2024 at 12:41:17PM -0800, Andres Freund wrote: > I noticed that I was getting core dumps while executing the tests, without the > tests failing. Backtraces are vriations of this: Looking, thanks for the heads-up. -- Nathan Bossart Amazon Web Services: https://aws.amazon.com
On Mon, Jan 22, 2024 at 02:44:57PM -0600, Nathan Bossart wrote:
> On Mon, Jan 22, 2024 at 12:41:17PM -0800, Andres Freund wrote:
>> I noticed that I was getting core dumps while executing the tests, without the
>> tests failing. Backtraces are vriations of this:
>
> Looking, thanks for the heads-up.
I think this is because the autoprewarm state was moved to a DSM segment,
and DSM segments are detached before the on_shmem_exit callbacks are called
during process exit. Moving apw_detach_shmem to the before_shmem_exit list
seems to resolve the crashes.
diff --git a/contrib/pg_prewarm/autoprewarm.c b/contrib/pg_prewarm/autoprewarm.c
index 9ea6c2252a..88c3a04109 100644
--- a/contrib/pg_prewarm/autoprewarm.c
+++ b/contrib/pg_prewarm/autoprewarm.c
@@ -165,7 +165,7 @@ autoprewarm_main(Datum main_arg)
first_time = false;
/* Set on-detach hook so that our PID will be cleared on exit. */
- on_shmem_exit(apw_detach_shmem, 0);
+ before_shmem_exit(apw_detach_shmem, 0);
/*
* Store our PID in the shared memory area --- unless there's already
--
Nathan Bossart
Amazon Web Services: https://aws.amazon.com
Hi, On 2024-01-22 15:19:36 -0600, Nathan Bossart wrote: > On Mon, Jan 22, 2024 at 02:44:57PM -0600, Nathan Bossart wrote: > > On Mon, Jan 22, 2024 at 12:41:17PM -0800, Andres Freund wrote: > >> I noticed that I was getting core dumps while executing the tests, without the > >> tests failing. Backtraces are vriations of this: > > > > Looking, thanks for the heads-up. > > I think this is because the autoprewarm state was moved to a DSM segment, > and DSM segments are detached before the on_shmem_exit callbacks are called > during process exit. Moving apw_detach_shmem to the before_shmem_exit list > seems to resolve the crashes. That seems plausible. Would still be nice to have at least this test ensure that the shutdown code works. Perhaps just a check of the control file after shutdown, ensuring that the state is "shutdowned" vs crashed? Greetings, Andres Freund
On Mon, Jan 22, 2024 at 01:24:54PM -0800, Andres Freund wrote: > On 2024-01-22 15:19:36 -0600, Nathan Bossart wrote: >> I think this is because the autoprewarm state was moved to a DSM segment, >> and DSM segments are detached before the on_shmem_exit callbacks are called >> during process exit. Moving apw_detach_shmem to the before_shmem_exit list >> seems to resolve the crashes. > > That seems plausible. Would still be nice to have at least this test ensure > that the shutdown code works. Perhaps just a check of the control file after > shutdown, ensuring that the state is "shutdowned" vs crashed? I'll give that a try. I'll also expand the comment above the before_shmem_exit() call. -- Nathan Bossart Amazon Web Services: https://aws.amazon.com
On Mon, Jan 22, 2024 at 03:38:15PM -0600, Nathan Bossart wrote: > On Mon, Jan 22, 2024 at 01:24:54PM -0800, Andres Freund wrote: >> On 2024-01-22 15:19:36 -0600, Nathan Bossart wrote: >>> I think this is because the autoprewarm state was moved to a DSM segment, >>> and DSM segments are detached before the on_shmem_exit callbacks are called >>> during process exit. Moving apw_detach_shmem to the before_shmem_exit list >>> seems to resolve the crashes. >> >> That seems plausible. Would still be nice to have at least this test ensure >> that the shutdown code works. Perhaps just a check of the control file after >> shutdown, ensuring that the state is "shutdowned" vs crashed? > > I'll give that a try. I'll also expand the comment above the > before_shmem_exit() call. Here is a patch. This might be a topic for another thread, but I do wonder whether we could put a generic pg_controldata check in node->stop that would at least make sure that the state is some sort of expected shut-down state. My first thought is that it could be a tad expensive, but... maybe it wouldn't be too bad. -- Nathan Bossart Amazon Web Services: https://aws.amazon.com
Attachment
Hello Andres, 22.01.2024 23:41, Andres Freund wrote: > Hi, > > I noticed that I was getting core dumps while executing the tests, without the > tests failing. Backtraces are vriations of this: > ... > > ISTM that we shouldn't basically silently overlook shutdowns due to crashes in > the tests. How to not do so is unfortunately not immediately obvious to me... > FWIW, I encountered this behavior as well (with pg_stat): https://www.postgresql.org/message-id/18158-88f667028dbc7e7b@postgresql.org and proposed a way to detect such shutdowns for a discussion: https://www.postgresql.org/message-id/flat/290b9ae3-98a2-0896-a957-18d3b60b6260%40gmail.com where Shveta referenced a previous thread started by Tom Lane: https://www.postgresql.org/message-id/flat/2366244.1651681550@sss.pgh.pa.us What do you think about leaving postmaster.pid on disk in case of an abnormal shutdown? Best regards, Alexander
On Mon, Jan 22, 2024 at 04:27:43PM -0600, Nathan Bossart wrote: > Here is a patch. I'd like to fix these crashes sooner than later, so I will plan on committing this tonight (barring objections or feedback). If this needs to be revisited later for some reason, I'm happy to do so. -- Nathan Bossart Amazon Web Services: https://aws.amazon.com
Hi, On 2024-01-22 16:27:43 -0600, Nathan Bossart wrote: > Here is a patch. LGTM. > This might be a topic for another thread, but I do wonder whether we could > put a generic pg_controldata check in node->stop that would at least make > sure that the state is some sort of expected shut-down state. My first > thought is that it could be a tad expensive, but... maybe it wouldn't be > too bad. I think that'd probably would be a good idea - I suspect there'd need to be a fair number of exceptions, but that it'd be easier to change uses of ->stop() to the exception case where needed, than to add a new function doing checking and converting most things to that. Greetings, Andres Freund
Hi, On 2024-01-23 08:00:00 +0300, Alexander Lakhin wrote: > 22.01.2024 23:41, Andres Freund wrote: > > ISTM that we shouldn't basically silently overlook shutdowns due to crashes in > > the tests. How to not do so is unfortunately not immediately obvious to me... > > > > FWIW, I encountered this behavior as well (with pg_stat): > https://www.postgresql.org/message-id/18158-88f667028dbc7e7b@postgresql.org > > and proposed a way to detect such shutdowns for a discussion: > https://www.postgresql.org/message-id/flat/290b9ae3-98a2-0896-a957-18d3b60b6260%40gmail.com > > where Shveta referenced a previous thread started by Tom Lane: > https://www.postgresql.org/message-id/flat/2366244.1651681550@sss.pgh.pa.us > > What do you think about leaving postmaster.pid on disk in case of an > abnormal shutdown? I don't think that's viable and would cause more problems than it solves, it'd make us think that we might have an old postgres process hanging around that needs to be terminted before we can start up. And I simply don't see the point - we already record whether we crashed in the control file, no? Greetings, Andres Freund
On 2024-Jan-22, Nathan Bossart wrote: > Here is a patch. Looks reasonable. > This might be a topic for another thread, but I do wonder whether we could > put a generic pg_controldata check in node->stop that would at least make > sure that the state is some sort of expected shut-down state. My first > thought is that it could be a tad expensive, but... maybe it wouldn't be > too bad. Does this actually detect a problem if you take out the fix? I think what's going to happen is that postmaster is going to crash, then do the recovery cycle, then stop as instructed by the test; so pg_controldata would report that it was correctly shut down. If we had a restart-cycle-counter to check maybe we could verify that it hasn't changed, but I don't think we have that. -- Álvaro Herrera PostgreSQL Developer — https://www.EnterpriseDB.com/ "Cada quien es cada cual y baja las escaleras como quiere" (JMSerrat)
On Tue, Jan 23, 2024 at 06:33:25PM +0100, Alvaro Herrera wrote: > On 2024-Jan-22, Nathan Bossart wrote: >> This might be a topic for another thread, but I do wonder whether we could >> put a generic pg_controldata check in node->stop that would at least make >> sure that the state is some sort of expected shut-down state. My first >> thought is that it could be a tad expensive, but... maybe it wouldn't be >> too bad. > > Does this actually detect a problem if you take out the fix? I think > what's going to happen is that postmaster is going to crash, then do the > recovery cycle, then stop as instructed by the test; so pg_controldata > would report that it was correctly shut down. Yes, the control data shows "in production" without it. The segfault happens within the shut-down path, and the test logs indicate that the server continues shutting down without doing a recovery cycle: 2024-01-23 12:14:49.254 CST [2376301] LOG: received fast shutdown request 2024-01-23 12:14:49.254 CST [2376301] LOG: aborting any active transactions 2024-01-23 12:14:49.255 CST [2376301] LOG: background worker "logical replication launcher" (PID 2376308) exited with exitcode 1 2024-01-23 12:14:49.256 CST [2376301] LOG: background worker "autoprewarm leader" (PID 2376307) was terminated by signal11: Segmentation fault 2024-01-23 12:14:49.256 CST [2376301] LOG: terminating any other active server processes 2024-01-23 12:14:49.257 CST [2376301] LOG: abnormal database system shutdown 2024-01-23 12:14:49.261 CST [2376301] LOG: database system is shut down -- Nathan Bossart Amazon Web Services: https://aws.amazon.com
On Tue, Jan 23, 2024 at 12:22:58PM -0600, Nathan Bossart wrote: > On Tue, Jan 23, 2024 at 06:33:25PM +0100, Alvaro Herrera wrote: >> Does this actually detect a problem if you take out the fix? I think >> what's going to happen is that postmaster is going to crash, then do the >> recovery cycle, then stop as instructed by the test; so pg_controldata >> would report that it was correctly shut down. > > Yes, the control data shows "in production" without it. The segfault > happens within the shut-down path, and the test logs indicate that the > server continues shutting down without doing a recovery cycle: I see that ->init turns off restart_after_crash, which might be why it's not doing a recovery cycle. -- Nathan Bossart Amazon Web Services: https://aws.amazon.com
23.01.2024 20:30, Andres Freund wrote:
> I don't think that's viable and would cause more problems than it solves, it'd
> make us think that we might have an old postgres process hanging around that
> needs to be terminted before we can start up. And I simply don't see the point
> - we already record whether we crashed in the control file, no?
With an Assert injected in walsender.c (as in [1]) and test
012_subtransactions.pl modified to finish just after the first
"$node_primary->stop;", I see:
pg_controldata -D src/test/recovery/tmp_check/t_012_subtransactions_primary_data/pgdata/
Database cluster state: shut down
But the assertion undoubtedly failed:
grep TRAP src/test/recovery/tmp_check/log/*
src/test/recovery/tmp_check/log/012_subtransactions_primary.log:TRAP: failed Assert("0"), File: "walsender.c", Line:
2688, PID: 142201
As to the need to terminate a process, which is supposedly hanging around,
I think, this situation doesn't differ in general from what we have after
kill -9...
So my point was to let 'pg_ctl stop' know about an error occurred during
the server stop.
[1] https://www.postgresql.org/message-id/290b9ae3-98a2-0896-a957-18d3b60b6260%40gmail.com
Best regards,
Alexander
On Tue, Jan 23, 2024 at 06:33:25PM +0100, Alvaro Herrera wrote: > On 2024-Jan-22, Nathan Bossart wrote: > >> Here is a patch. > > Looks reasonable. Committed. Thank you for the report and the reviews. -- Nathan Bossart Amazon Web Services: https://aws.amazon.com
Hi,
On 2024-01-23 22:00:01 +0300, Alexander Lakhin wrote:
> 23.01.2024 20:30, Andres Freund wrote:
> > I don't think that's viable and would cause more problems than it solves, it'd
> > make us think that we might have an old postgres process hanging around that
> > needs to be terminted before we can start up. And I simply don't see the point
> > - we already record whether we crashed in the control file, no?
>
> With an Assert injected in walsender.c (as in [1]) and test
> 012_subtransactions.pl modified to finish just after the first
> "$node_primary->stop;", I see:
> pg_controldata -D src/test/recovery/tmp_check/t_012_subtransactions_primary_data/pgdata/
> Database cluster state: shut down
>
> But the assertion undoubtedly failed:
> grep TRAP src/test/recovery/tmp_check/log/*
> src/test/recovery/tmp_check/log/012_subtransactions_primary.log:TRAP: failed
> Assert("0"), File: "walsender.c", Line: 2688, PID: 142201
Yea, because it's after checkpointer has changed the state to "shutdowned". I
think we could add additional states, to be set by postmaster, instead of
checkpointer, for this purpose.
> As to the need to terminate a process, which is supposedly hanging around,
> I think, this situation doesn't differ in general from what we have after
> kill -9...
So? Making it more likely for postgres failing to restart successfully,
because the pid has been reused, is bad.
Greetings,
Andres Freund