Assertion failure on PG15 with modified test_shm_mq test
Hello,
I've a slightly modified version of test_shm_mq, that I changed to include
a shared fileset. The motivation to do that came because I hit an
assertion failure with PG15 while doing some development work on BDR and I
suspected it to be a PG15 bug.
The stack trace looks as below:
(lldb) bt
* thread #1
* frame #0: 0x00007ff8187b100e libsystem_kernel.dylib`__pthread_kill + 10
frame #1: 0x00007ff8187e71ff libsystem_pthread.dylib`pthread_kill + 263
frame #2: 0x00007ff818732d24 libsystem_c.dylib`abort + 123
frame #3: 0x000000010fce1bab
postgres`ExceptionalCondition(conditionName="pgstat_is_initialized &&
!pgstat_is_shutdown", errorType="FailedAssertion", fileName="pgstat.c",
lineNumber=1227) at assert.c:69:2
frame #4: 0x000000010fb06412 postgres`pgstat_assert_is_up at
pgstat.c:1227:2
frame #5: 0x000000010fb0d2c7
postgres`pgstat_get_entry_ref(kind=PGSTAT_KIND_DATABASE, dboid=0, objoid=0,
create=true, created_entry=0x0000000000000000) at pgstat_shmem.c:406:2
frame #6: 0x000000010fb07579
postgres`pgstat_prep_pending_entry(kind=PGSTAT_KIND_DATABASE, dboid=0,
objoid=0, created_entry=0x0000000000000000) at pgstat.c:1068:14
frame #7: 0x000000010fb09cce
postgres`pgstat_prep_database_pending(dboid=0) at pgstat_database.c:327:14
frame #8: 0x000000010fb09dff
postgres`pgstat_report_tempfile(filesize=0) at pgstat_database.c:179:10
frame #9: 0x000000010fa8dbe9
postgres`ReportTemporaryFileUsage(path="base/pgsql_tmp/pgsql_tmp17312.0.fileset/test_mq_sharefile.0",
size=0) at fd.c:1521:2
frame #10: 0x000000010fa8db3c
postgres`PathNameDeleteTemporaryFile(path="base/pgsql_tmp/pgsql_tmp17312.0.fileset/test_mq_sharefile.0",
error_on_failure=false) at fd.c:1945:3
frame #11: 0x000000010fa8d3a8
postgres`unlink_if_exists_fname(fname="base/pgsql_tmp/pgsql_tmp17312.0.fileset/test_mq_sharefile.0",
isdir=false, elevel=15) at fd.c:3674:3
frame #12: 0x000000010fa8d270
postgres`walkdir(path="base/pgsql_tmp/pgsql_tmp17312.0.fileset",
action=(postgres`unlink_if_exists_fname at fd.c:3663),
process_symlinks=false, elevel=15) at fd.c:3573:5
frame #13: 0x000000010fa8d0e2
postgres`PathNameDeleteTemporaryDir(dirname="base/pgsql_tmp/pgsql_tmp17312.0.fileset")
at fd.c:1689:2
frame #14: 0x000000010fa91ac1
postgres`FileSetDeleteAll(fileset=0x0000000119240870) at fileset.c:165:3
frame #15: 0x000000010fa92b08
postgres`SharedFileSetOnDetach(segment=0x00007f93ff00a7c0,
datum=4716759152) at sharedfileset.c:119:3
frame #16: 0x000000010fa96b00
postgres`dsm_detach(seg=0x00007f93ff00a7c0) at dsm.c:801:3
frame #17: 0x000000010fa96f51 postgres`dsm_backend_shutdown at
dsm.c:738:3
frame #18: 0x000000010fa99402 postgres`shmem_exit(code=1) at ipc.c:259:2
frame #19: 0x000000010fa99227 postgres`proc_exit_prepare(code=1) at
ipc.c:194:2
frame #20: 0x000000010fa99133 postgres`proc_exit(code=1) at ipc.c:107:2
frame #21: 0x000000010fce318c postgres`errfinish(filename="postgres.c",
lineno=3204, funcname="ProcessInterrupts") at elog.c:661:3
frame #22: 0x000000010fad7c51 postgres`ProcessInterrupts at
postgres.c:3201:4
frame #23: 0x000000011924d85b
test_shm_mq.so`test_shm_mq_main(main_arg=1155036180) at worker.c:159:2
frame #24: 0x000000010f9da11e postgres`StartBackgroundWorker at
bgworker.c:858:2
frame #25: 0x000000010f9e80b4
postgres`do_start_bgworker(rw=0x00007f93ef904080) at postmaster.c:5823:4
frame #26: 0x000000010f9e2524 postgres`maybe_start_bgworkers at
postmaster.c:6047:9
frame #27: 0x000000010f9e0e63
postgres`sigusr1_handler(postgres_signal_arg=30) at postmaster.c:5204:3
frame #28: 0x00007ff8187fcdfd libsystem_platform.dylib`_sigtramp + 29
frame #29: 0x00007ff8187b2d5b libsystem_kernel.dylib`__select + 11
frame #30: 0x000000010f9e268d postgres`ServerLoop at
postmaster.c:1770:13
frame #31: 0x000000010f9e0157 postgres`PostmasterMain(argc=8,
argv=0x0000600002f30190) at postmaster.c:1478:11
frame #32: 0x000000010f8bc930 postgres`main(argc=8,
argv=0x0000600002f30190) at main.c:202:3
frame #33: 0x000000011f7d651e dyld`start + 462
I notice that pgstat_shutdown_hook() is registered as a before-shmem-exit
callback. The callback is responsible for detaching from the pgstat shared
memory segment. But looks like other parts of the system still expect it to
be available during later stages of proc exit.
It's not clear to me if pgstat shutdown should happen later or code that
gets executed later in the cycle should not try to use pgstat. It's also
entirely possible that my usage of SharedFileSet is completely wrong. If
that's the case, please let me know the mistake in the usage.
Patch modifying the test case is attached. In order to reproduce the
problem quickly, I added a CHECK_FOR_INTERRUPTS() in the test, but I don't
see why that would be a bad coding practice.
Thanks,
Pavan
Attachments:
crash_pgstat.patchapplication/octet-stream; name=crash_pgstat.patchDownload
diff --git a/src/test/modules/test_shm_mq/setup.c b/src/test/modules/test_shm_mq/setup.c
index e05e97c6de2..759b5b3a82b 100644
--- a/src/test/modules/test_shm_mq/setup.c
+++ b/src/test/modules/test_shm_mq/setup.c
@@ -18,11 +18,17 @@
#include "miscadmin.h"
#include "pgstat.h"
#include "postmaster/bgworker.h"
+#include "storage/buffile.h"
#include "storage/procsignal.h"
#include "storage/shm_toc.h"
#include "test_shm_mq.h"
#include "utils/memutils.h"
+typedef struct
+{
+ SharedFileSet fileset;
+} shared_state;
+
typedef struct
{
int nworkers;
@@ -32,7 +38,8 @@ typedef struct
static void setup_dynamic_shared_memory(int64 queue_size, int nworkers,
dsm_segment **segp,
test_shm_mq_header **hdrp,
- shm_mq **outp, shm_mq **inp);
+ shm_mq **outp, shm_mq **inp,
+ BufFile **fdp);
static worker_state *setup_background_workers(int nworkers,
dsm_segment *seg);
static void cleanup_background_workers(dsm_segment *seg, Datum arg);
@@ -53,9 +60,10 @@ test_shm_mq_setup(int64 queue_size, int32 nworkers, dsm_segment **segp,
shm_mq *outq = NULL; /* placate compiler */
shm_mq *inq = NULL; /* placate compiler */
worker_state *wstate;
+ BufFile *fd;
/* Set up a dynamic shared memory segment. */
- setup_dynamic_shared_memory(queue_size, nworkers, &seg, &hdr, &outq, &inq);
+ setup_dynamic_shared_memory(queue_size, nworkers, &seg, &hdr, &outq, &inq, &fd);
*segp = seg;
/* Register background workers. */
@@ -68,6 +76,10 @@ test_shm_mq_setup(int64 queue_size, int32 nworkers, dsm_segment **segp,
/* Wait for workers to become ready. */
wait_for_workers_to_become_ready(wstate, hdr);
+ /* Force error processing */
+ elog(ERROR, "force error");
+
+ BufFileClose(fd);
/*
* Once we reach this point, all workers are ready. We no longer need to
* kill them if we die; they'll die on their own as the message queues
@@ -88,7 +100,7 @@ test_shm_mq_setup(int64 queue_size, int32 nworkers, dsm_segment **segp,
static void
setup_dynamic_shared_memory(int64 queue_size, int nworkers,
dsm_segment **segp, test_shm_mq_header **hdrp,
- shm_mq **outp, shm_mq **inp)
+ shm_mq **outp, shm_mq **inp, BufFile **fdp)
{
shm_toc_estimator e;
int i;
@@ -96,6 +108,7 @@ setup_dynamic_shared_memory(int64 queue_size, int nworkers,
dsm_segment *seg;
shm_toc *toc;
test_shm_mq_header *hdr;
+ BufFile *fd;
/* Ensure a valid queue size. */
if (queue_size < 0 || ((uint64) queue_size) < shm_mq_minimum_size)
@@ -160,9 +173,18 @@ setup_dynamic_shared_memory(int64 queue_size, int nworkers,
}
}
+ SharedFileSetInit(&hdr->fileset, seg);
+#if PG_VERSION_NUM >= 150000
+ fd = BufFileCreateFileSet(&(hdr->fileset.fs), "test_mq_sharefile");
+#else
+ fd = BufFileCreateShared(&(hdr->fileset), "test_mq_sharefile");
+#endif
+
+
/* Return results to caller. */
*segp = seg;
*hdrp = hdr;
+ *fdp = fd;
}
/*
diff --git a/src/test/modules/test_shm_mq/test_shm_mq.h b/src/test/modules/test_shm_mq/test_shm_mq.h
index a6661218347..447c6ba61a7 100644
--- a/src/test/modules/test_shm_mq/test_shm_mq.h
+++ b/src/test/modules/test_shm_mq/test_shm_mq.h
@@ -15,6 +15,7 @@
#define TEST_SHM_MQ_H
#include "storage/dsm.h"
+#include "storage/sharedfileset.h"
#include "storage/shm_mq.h"
#include "storage/spin.h"
@@ -32,6 +33,7 @@ typedef struct
int workers_total;
int workers_attached;
int workers_ready;
+ SharedFileSet fileset;
} test_shm_mq_header;
/* Set up dynamic shared memory and background workers for test run. */
diff --git a/src/test/modules/test_shm_mq/worker.c b/src/test/modules/test_shm_mq/worker.c
index 2180776a669..4372ccd81dc 100644
--- a/src/test/modules/test_shm_mq/worker.c
+++ b/src/test/modules/test_shm_mq/worker.c
@@ -19,12 +19,15 @@
#include "postgres.h"
+#include "access/xact.h"
#include "miscadmin.h"
+#include "storage/buffile.h"
#include "storage/ipc.h"
#include "storage/procarray.h"
#include "storage/shm_mq.h"
#include "storage/shm_toc.h"
#include "tcop/tcopprot.h"
+#include "utils/resowner.h"
#include "test_shm_mq.h"
@@ -53,6 +56,7 @@ test_shm_mq_main(Datum main_arg)
volatile test_shm_mq_header *hdr;
int myworkernumber;
PGPROC *registrant;
+ BufFile *fd;
/*
* Establish signal handlers.
@@ -110,6 +114,19 @@ test_shm_mq_main(Datum main_arg)
*/
attach_to_queues(seg, toc, myworkernumber, &inqh, &outqh);
+ CurrentResourceOwner = ResourceOwnerCreate(NULL, "worker");
+
+ /*
+ * Open shared file. The explicit typecasts are to keep compiler
+ * happy because hdr is declared as volatile here.
+ */
+ SharedFileSetAttach((SharedFileSet *)&hdr->fileset, seg);
+#if PG_VERSION_NUM >= 150000
+ fd = BufFileOpenFileSet((FileSet *)&hdr->fileset.fs, "test_mq_sharefile", O_RDONLY, false);
+#else
+ fd = BufFileOpenShared((SharedFileSet *)&hdr->fileset, "test_mq_sharefile", O_RDONLY);
+#endif
+
/*
* Indicate that we're fully initialized and ready to begin the main part
* of the parallel operation.
@@ -133,6 +150,14 @@ test_shm_mq_main(Datum main_arg)
/* Do the work. */
copy_messages(inqh, outqh);
+ BufFileClose(fd);
+
+ /*
+ * Force interrupt processing. Not sure why, but this makes it easy
+ * to reproduce the problem.
+ */
+ CHECK_FOR_INTERRUPTS();
+
/*
* We're done. For cleanliness, explicitly detach from the shared memory
* segment (that would happen anyway during process exit, though).
On Wed, Aug 17, 2022 at 11:15:28AM +0530, Pavan Deolasee wrote:
I notice that pgstat_shutdown_hook() is registered as a before-shmem-exit
callback. The callback is responsible for detaching from the pgstat shared
memory segment. But looks like other parts of the system still expect it to
be available during later stages of proc exit.It's not clear to me if pgstat shutdown should happen later or code that
gets executed later in the cycle should not try to use pgstat. It's also
entirely possible that my usage of SharedFileSet is completely wrong. If
that's the case, please let me know the mistake in the usage.
That's visibly an issue with shared memory and the stats. I have
added an open item. Andres?
--
Michael
Hi,
On 2022-08-17 11:15:28 +0530, Pavan Deolasee wrote:
I've a slightly modified version of test_shm_mq, that I changed to include
a shared fileset. The motivation to do that came because I hit an
assertion failure with PG15 while doing some development work on BDR and I
suspected it to be a PG15 bug.
I notice that pgstat_shutdown_hook() is registered as a before-shmem-exit
callback. The callback is responsible for detaching from the pgstat shared
memory segment. But looks like other parts of the system still expect it to
be available during later stages of proc exit.
It's not clear to me if pgstat shutdown should happen later or code that
gets executed later in the cycle should not try to use pgstat. It's also
entirely possible that my usage of SharedFileSet is completely wrong. If
that's the case, please let me know the mistake in the usage.
I don't think we have the infrastructure for a nice solution to this at the
moment - we need a fairly large overhaul of process initialization / shutdown
to handle these interdependencies nicely.
We can't move pgstat shutdown into on_dsm callback because that's too late to
allocate *new* dsm segments, which we might need to do while flushing
out pending stats.
See https://git.postgresql.org/gitweb/?p=postgresql.git;a=commit;h=fa91d4c91f28f4819dc54f93adbd413a685e366a
for a way to avoid the problem.
Greetings,
Andres Freund
Hi,
On 2022-08-17 15:02:28 +0900, Michael Paquier wrote:
On Wed, Aug 17, 2022 at 11:15:28AM +0530, Pavan Deolasee wrote:
I notice that pgstat_shutdown_hook() is registered as a before-shmem-exit
callback. The callback is responsible for detaching from the pgstat shared
memory segment. But looks like other parts of the system still expect it to
be available during later stages of proc exit.It's not clear to me if pgstat shutdown should happen later or code that
gets executed later in the cycle should not try to use pgstat. It's also
entirely possible that my usage of SharedFileSet is completely wrong. If
that's the case, please let me know the mistake in the usage.That's visibly an issue with shared memory and the stats. I have
added an open item. Andres?
I don't think there's anything reasonably done about this for 15, as explained
upthread. We need a big redesign of the shutdown sequence at some point, but
...
Greetings,
Andres Freund
Hi,
On Thu, Aug 18, 2022 at 5:38 AM Andres Freund <andres@anarazel.de> wrote:
I don't think we have the infrastructure for a nice solution to this at the
moment - we need a fairly large overhaul of process initialization /
shutdown
to handle these interdependencies nicely.
Ok, understood.
We can't move pgstat shutdown into on_dsm callback because that's too late
to
allocate *new* dsm segments, which we might need to do while flushing
out pending stats.See
https://git.postgresql.org/gitweb/?p=postgresql.git;a=commit;h=fa91d4c91f28f4819dc54f93adbd413a685e366a
for a way to avoid the problem.
Thanks for the hint. I will try that approach. I wonder though if there is
something more we can do. For example, would it make sense to throw a
WARNING and avoid segfault if pgstat machinery is already shutdown? Just
worried if the code can be reached from multiple paths and testing all of
those would be difficult for extension developers, especially given this
may happen in error recovery path.
Thanks,
Pavan
--
Pavan Deolasee
EnterpriseDB: https://www.enterprisedb..com
At Thu, 18 Aug 2022 16:58:24 +0530, Pavan Deolasee <pavan.deolasee@gmail.com> wrote in
Hi,
On Thu, Aug 18, 2022 at 5:38 AM Andres Freund <andres@anarazel.de> wrote:
We can't move pgstat shutdown into on_dsm callback because that's too late
to
allocate *new* dsm segments, which we might need to do while flushing
out pending stats.See
https://git.postgresql.org/gitweb/?p=postgresql.git;a=commit;h=fa91d4c91f28f4819dc54f93adbd413a685e366a
for a way to avoid the problem.Thanks for the hint. I will try that approach. I wonder though if there is
something more we can do. For example, would it make sense to throw a
WARNING and avoid segfault if pgstat machinery is already shutdown? Just
worried if the code can be reached from multiple paths and testing all of
those would be difficult for extension developers, especially given this
may happen in error recovery path.
I'm not sure how extensions can face this problem, but..
pgstat is designed not to lose reported numbers. The assertion is
manifets that intention. It is not enabled on non-assertion builds
and pgstat enters undefined state then maybe crash after the assertion
point. On the other hand I don't think we want to perform the same
check for the all places the assertion exists on non-assertion builds.
We cannot simply replace the assertion with ereport().
regards.
--
Kyotaro Horiguchi
NTT Open Source Software Center