Thread: Drop replslot after pgstat_shutdown cause assert coredump

Drop replslot after pgstat_shutdown cause assert coredump

From
"houzj.fnst@fujitsu.com"
Date:
Hi,

When testing logical replication, I found a case which caused assert coredump on
latest HEAD. The reproduction steps are as follows:

1)
----publisher----
create table test(i int);
create publication pub for table test;
begin;

insert into test values(1);

2)
----subscriber----
create table test(i int);
create subscription sub connection 'dbname=postgres port=10000' publication pub;
- wait for a second and Ctrl-C

3)
----publisher----
commit;

I can see the walsender tried to release a not-quite-ready repliaction slot
that was created when create a subscription. But the pgstat has been shutdown
before invoking ReplicationSlotRelease().

The stack is as follows:

#2  in ExceptionalCondition (pgstat_is_initialized && !pgstat_is_shutdown)
#3  in pgstat_assert_is_up () at pgstat.c:4852
#4  in pgstat_send (msg=msg@entry=0x7ffe716f7470, len=len@entry=144) at pgstat.c:3075
#5  in pgstat_report_replslot_drop (slotname=slotname@entry=0x7fbcf57a3c98 "sub") at pgstat.c:1869
#6  in ReplicationSlotDropPtr (slot=0x7fbcf57a3c80) at slot.c:696
#7  in ReplicationSlotDropAcquired () at slot.c:585
#8  in ReplicationSlotRelease () at slot.c:482
#9  in ProcKill (code=<optimized out>, arg=<optimized out>) at proc.c:852
#10 in shmem_exit (code=code@entry=0) at ipc.c:272
#11 in proc_exit_prepare (code=code@entry=0) at ipc.c:194
#12 in proc_exit (code=code@entry=0) at ipc.c:107
#13 in ProcessRepliesIfAny () at walsender.c:1807
#14 in WalSndWaitForWal (loc=loc@entry=22087632) at walsender.c:1417
#15 in logical_read_xlog_page (state=0x2f8c600, targetPagePtr=22085632,
    reqLen=, targetRecPtr=, cur_page=0x2f6c1e0 "\016\321\005") at walsender.c:821
#16 in ReadPageInternal (state=state@entry=0x2f8c600,
    pageptr=pageptr@entry=22085632, reqLen=reqLen@entry=2000) at xlogreader.c:667
#17 in XLogReadRecord (state=0x2f8c600,
    errormsg=errormsg@entry=0x7ffe716f7f98) at xlogreader.c:337
#18 in DecodingContextFindStartpoint (ctx=ctx@entry=0x2f8c240)
    at logical.c:606
#19 in CreateReplicationSlot (cmd=cmd@entry=0x2f1aef0)

Is this behavior expected ?

Best regards,
Hou zhijie




Re: Drop replslot after pgstat_shutdown cause assert coredump

From
Greg Nancarrow
Date:
On Mon, Oct 11, 2021 at 6:55 PM houzj.fnst@fujitsu.com
<houzj.fnst@fujitsu.com> wrote:
>
> I can see the walsender tried to release a not-quite-ready repliaction slot
> that was created when create a subscription. But the pgstat has been shutdown
> before invoking ReplicationSlotRelease().
>
> The stack is as follows:
>
> #2  in ExceptionalCondition (pgstat_is_initialized && !pgstat_is_shutdown)
> #3  in pgstat_assert_is_up () at pgstat.c:4852
> #4  in pgstat_send (msg=msg@entry=0x7ffe716f7470, len=len@entry=144) at pgstat.c:3075
> #5  in pgstat_report_replslot_drop (slotname=slotname@entry=0x7fbcf57a3c98 "sub") at pgstat.c:1869
> #6  in ReplicationSlotDropPtr (slot=0x7fbcf57a3c80) at slot.c:696
> #7  in ReplicationSlotDropAcquired () at slot.c:585
> #8  in ReplicationSlotRelease () at slot.c:482
> #9  in ProcKill (code=<optimized out>, arg=<optimized out>) at proc.c:852
> #10 in shmem_exit (code=code@entry=0) at ipc.c:272
> #11 in proc_exit_prepare (code=code@entry=0) at ipc.c:194
> #12 in proc_exit (code=code@entry=0) at ipc.c:107
> #13 in ProcessRepliesIfAny () at walsender.c:1807
> #14 in WalSndWaitForWal (loc=loc@entry=22087632) at walsender.c:1417
> #15 in logical_read_xlog_page (state=0x2f8c600, targetPagePtr=22085632,
>     reqLen=, targetRecPtr=, cur_page=0x2f6c1e0 "\016\321\005") at walsender.c:821
> #16 in ReadPageInternal (state=state@entry=0x2f8c600,
>     pageptr=pageptr@entry=22085632, reqLen=reqLen@entry=2000) at xlogreader.c:667
> #17 in XLogReadRecord (state=0x2f8c600,
>     errormsg=errormsg@entry=0x7ffe716f7f98) at xlogreader.c:337
> #18 in DecodingContextFindStartpoint (ctx=ctx@entry=0x2f8c240)
>     at logical.c:606
> #19 in CreateReplicationSlot (cmd=cmd@entry=0x2f1aef0)
>
> Is this behavior expected ?
>

I'd say it's not!

Just looking at the stacktrace, I'm thinking that the following commit
may have had a bearing on this problem, by causing pgstat to be
shutdown earlier:

commit fb2c5028e63589c01fbdf8b031be824766dc7a68
Author: Andres Freund <andres@anarazel.de>
Date:   Fri Aug 6 10:05:57 2021 -0700

    pgstat: Schedule per-backend pgstat shutdown via before_shmem_exit().


Can you see if the problem can be reproduced prior to this commit?


Regards,
Greg Nancarrow
Fujitsu Australia



Re: Drop replslot after pgstat_shutdown cause assert coredump

From
Fujii Masao
Date:

On 2021/10/11 22:15, Greg Nancarrow wrote:
> On Mon, Oct 11, 2021 at 6:55 PM houzj.fnst@fujitsu.com
> <houzj.fnst@fujitsu.com> wrote:
>>
>> I can see the walsender tried to release a not-quite-ready repliaction slot
>> that was created when create a subscription. But the pgstat has been shutdown
>> before invoking ReplicationSlotRelease().
>>
>> The stack is as follows:
>>
>> #2  in ExceptionalCondition (pgstat_is_initialized && !pgstat_is_shutdown)
>> #3  in pgstat_assert_is_up () at pgstat.c:4852
>> #4  in pgstat_send (msg=msg@entry=0x7ffe716f7470, len=len@entry=144) at pgstat.c:3075
>> #5  in pgstat_report_replslot_drop (slotname=slotname@entry=0x7fbcf57a3c98 "sub") at pgstat.c:1869
>> #6  in ReplicationSlotDropPtr (slot=0x7fbcf57a3c80) at slot.c:696
>> #7  in ReplicationSlotDropAcquired () at slot.c:585
>> #8  in ReplicationSlotRelease () at slot.c:482
>> #9  in ProcKill (code=<optimized out>, arg=<optimized out>) at proc.c:852
>> #10 in shmem_exit (code=code@entry=0) at ipc.c:272
>> #11 in proc_exit_prepare (code=code@entry=0) at ipc.c:194
>> #12 in proc_exit (code=code@entry=0) at ipc.c:107
>> #13 in ProcessRepliesIfAny () at walsender.c:1807
>> #14 in WalSndWaitForWal (loc=loc@entry=22087632) at walsender.c:1417
>> #15 in logical_read_xlog_page (state=0x2f8c600, targetPagePtr=22085632,
>>      reqLen=, targetRecPtr=, cur_page=0x2f6c1e0 "\016\321\005") at walsender.c:821
>> #16 in ReadPageInternal (state=state@entry=0x2f8c600,
>>      pageptr=pageptr@entry=22085632, reqLen=reqLen@entry=2000) at xlogreader.c:667
>> #17 in XLogReadRecord (state=0x2f8c600,
>>      errormsg=errormsg@entry=0x7ffe716f7f98) at xlogreader.c:337
>> #18 in DecodingContextFindStartpoint (ctx=ctx@entry=0x2f8c240)
>>      at logical.c:606
>> #19 in CreateReplicationSlot (cmd=cmd@entry=0x2f1aef0)
>>
>> Is this behavior expected ?
>>
> 
> I'd say it's not!

Yes. I think this is a bug.


> Just looking at the stacktrace, I'm thinking that the following commit
> may have had a bearing on this problem, by causing pgstat to be
> shutdown earlier:
> 
> commit fb2c5028e63589c01fbdf8b031be824766dc7a68
> Author: Andres Freund <andres@anarazel.de>
> Date:   Fri Aug 6 10:05:57 2021 -0700
> 
>      pgstat: Schedule per-backend pgstat shutdown via before_shmem_exit().
> 
> 
> Can you see if the problem can be reproduced prior to this commit?

Even in prior to the commit, pgstat_shutdown_hook() can be called
before ProcKill() at the backend exit, so ISTM that the problem can
be reproduced.

Probably we need to make sure that pgstat_shutdown_hook() is called
after ProcKill(), e.g., by registering pgstat_shutdown_hook() into
on_proc_exit_list (I'm not sure if this change is safe, though).
Or maybe pgstat logic for replication slot drop needs to be overhauled.

Regards,

-- 
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION



Re: Drop replslot after pgstat_shutdown cause assert coredump

From
Kyotaro Horiguchi
Date:
At Fri, 22 Oct 2021 02:10:21 +0900, Fujii Masao <masao.fujii@oss.nttdata.com> wrote in 
> Even in prior to the commit, pgstat_shutdown_hook() can be called
> before ProcKill() at the backend exit, so ISTM that the problem can
> be reproduced.
> 
> Probably we need to make sure that pgstat_shutdown_hook() is called
> after ProcKill(), e.g., by registering pgstat_shutdown_hook() into

Considering the coming shared-memory based stats collector, pgstat
must be shutdown before shared memory shutdown.  Every operation that
requires stats collector also must be shut down before the pgstat
shutdown. A naive solution would be having before-pgstat-shutdown hook
but I'm not sure it's the right direction.

> on_proc_exit_list (I'm not sure if this change is safe, though).
> Or maybe pgstat logic for replication slot drop needs to be
> overhauled.

I think we don't want to lose the stats numbers of the to-be-dropped
slot. So the slot-drop must happen before pgstat shutdown.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center



Re: Drop replslot after pgstat_shutdown cause assert coredump

From
Kyotaro Horiguchi
Date:
I said:
> Considering the coming shared-memory based stats collector, pgstat
> must be shutdown before shared memory shutdown.  Every operation that
> requires stats collector also must be shut down before the pgstat
> shutdown. A naive solution would be having before-pgstat-shutdown hook
> but I'm not sure it's the right direction.

For this particular issue, we can add an explicit initilization phase
of replication slot per backend, which simply registers before_shmem
callback.  It would work fine unless we carelessly place the
initialization before pgstat_initialize() (not pgstat_init()) call.

(Honestly, I haven't been able to reproduce the issue itself for
 myself yet..)

> > on_proc_exit_list (I'm not sure if this change is safe, though).
> > Or maybe pgstat logic for replication slot drop needs to be
> > overhauled.
> 
> I think we don't want to lose the stats numbers of the to-be-dropped
> slot. So the slot-drop must happen before pgstat shutdown.

I haven't sought other similar issues. I'm going to check it if they,
if any, can be fixe the same way.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center
diff --git a/src/backend/postmaster/pgstat.c b/src/backend/postmaster/pgstat.c
index b7d0fbaefd..13762f82af 100644
--- a/src/backend/postmaster/pgstat.c
+++ b/src/backend/postmaster/pgstat.c
@@ -306,6 +306,8 @@ static bool pgstat_is_initialized = false;
 static bool pgstat_is_shutdown = false;
 #endif
 
+/* per-backend variable for assertion */
+bool pgstat_initialized PG_USED_FOR_ASSERTS_ONLY = false;
 
 /* ----------
  * Local function forward declarations
@@ -3036,6 +3038,7 @@ pgstat_initialize(void)
 
     /* Set up a process-exit hook to clean up */
     before_shmem_exit(pgstat_shutdown_hook, 0);
+    pgstat_initialized = true;
 
 #ifdef USE_ASSERT_CHECKING
     pgstat_is_initialized = true;
diff --git a/src/backend/replication/slot.c b/src/backend/replication/slot.c
index 1c6c0c7ce2..e0430aefa9 100644
--- a/src/backend/replication/slot.c
+++ b/src/backend/replication/slot.c
@@ -46,6 +46,7 @@
 #include "pgstat.h"
 #include "replication/slot.h"
 #include "storage/fd.h"
+#include "storage/ipc.h"
 #include "storage/proc.h"
 #include "storage/procarray.h"
 #include "utils/builtins.h"
@@ -160,6 +161,33 @@ ReplicationSlotsShmemInit(void)
     }
 }
 
+/*
+ * Exit hook to cleanup replication slots.
+ */
+static void
+ReplicationSlotShutdown(int code, Datum arg)
+{
+    /* Make sure active replication slots are released */
+    if (MyReplicationSlot != NULL)
+        ReplicationSlotRelease();
+
+    /* Also cleanup all the temporary slots. */
+    ReplicationSlotCleanup();
+}
+
+/*
+ * Initialize of replication slot facility per backend.
+ */
+void
+ReplicationSlotInit(void)
+{
+    if (max_replication_slots > 0)
+    {
+        assert_pgstat_initialized();
+        before_shmem_exit(ReplicationSlotShutdown, (Datum) 0);
+    }
+}
+
 /*
  * Check whether the passed slot name is valid and report errors at elevel.
  *
diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c
index b7d9da0aa9..b593ec8964 100644
--- a/src/backend/storage/lmgr/proc.c
+++ b/src/backend/storage/lmgr/proc.c
@@ -41,7 +41,6 @@
 #include "miscadmin.h"
 #include "pgstat.h"
 #include "postmaster/autovacuum.h"
-#include "replication/slot.h"
 #include "replication/syncrep.h"
 #include "replication/walsender.h"
 #include "storage/condition_variable.h"
@@ -847,13 +846,6 @@ ProcKill(int code, Datum arg)
     /* Cancel any pending condition variable sleep, too */
     ConditionVariableCancelSleep();
 
-    /* Make sure active replication slots are released */
-    if (MyReplicationSlot != NULL)
-        ReplicationSlotRelease();
-
-    /* Also cleanup all the temporary slots. */
-    ReplicationSlotCleanup();
-
     /*
      * Detach from any lock group of which we are a member.  If the leader
      * exist before all other group members, its PGPROC will remain allocated
diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
index 78bc64671e..dd83864b54 100644
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -40,6 +40,7 @@
 #include "pgstat.h"
 #include "postmaster/autovacuum.h"
 #include "postmaster/postmaster.h"
+#include "replication/slot.h"
 #include "replication/walsender.h"
 #include "storage/bufmgr.h"
 #include "storage/fd.h"
@@ -531,6 +532,12 @@ BaseInit(void)
      */
     pgstat_initialize();
 
+    /*
+     * Initialize replication slot. This must be after pgstat_initialize() so
+     * that the cleanup happnes before the shutdown of pgstat facility.
+     */
+    ReplicationSlotInit();
+
     /* Do local initialization of storage and buffer managers */
     InitSync();
     smgrinit();
diff --git a/src/include/pgstat.h b/src/include/pgstat.h
index bcd3588ea2..f06810c115 100644
--- a/src/include/pgstat.h
+++ b/src/include/pgstat.h
@@ -992,6 +992,14 @@ extern PgStat_Counter pgStatTransactionIdleTime;
  */
 extern SessionEndType pgStatSessionEndCause;
 
+/*
+ * modules requires pgstat required to install their before-shmem hook after
+ * pgstat. This variable is used to make sure that.
+ */
+extern bool pgstat_initialized;
+#define assert_pgstat_initialized() Assert (pgstat_initialized);
+
+
 /* ----------
  * Functions called from postmaster
  * ----------
diff --git a/src/include/replication/slot.h b/src/include/replication/slot.h
index 53d773ccff..124d107662 100644
--- a/src/include/replication/slot.h
+++ b/src/include/replication/slot.h
@@ -193,6 +193,9 @@ extern PGDLLIMPORT int max_replication_slots;
 extern Size ReplicationSlotsShmemSize(void);
 extern void ReplicationSlotsShmemInit(void);
 
+/* per-backend initialization */
+extern void ReplicationSlotInit(void);
+
 /* management of individual slots */
 extern void ReplicationSlotCreate(const char *name, bool db_specific,
                                   ReplicationSlotPersistency p, bool two_phase);

Re: Drop replslot after pgstat_shutdown cause assert coredump

From
Kyotaro Horiguchi
Date:
At Fri, 22 Oct 2021 11:43:08 +0900 (JST), Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote in 
> (Honestly, I haven't been able to reproduce the issue itself for
>  myself yet..)

I managed to reproduce it for me.

psql "dbname=postgres replication=database"
postgres=# CREATE_REPLICATION_SLOT "ts1" TEMPORARY LOGICAL "pgoutput";
postgres=# C-d
(crash)

And confirmed that it doesn't happen with the fix.

> I haven't sought other similar issues. I'm going to check it if they,
> if any, can be fixed the same way.

FileClose calls pgstat_report_tempfile() via
BeforeShmemExit_Files. It is already registered after pgstat.
I added a call to assert_pgstat_initialized() to 

All other pgstat functions seem to be called outside shmem_exit.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center
diff --git a/src/backend/postmaster/pgstat.c b/src/backend/postmaster/pgstat.c
index b7d0fbaefd..13762f82af 100644
--- a/src/backend/postmaster/pgstat.c
+++ b/src/backend/postmaster/pgstat.c
@@ -306,6 +306,8 @@ static bool pgstat_is_initialized = false;
 static bool pgstat_is_shutdown = false;
 #endif
 
+/* per-backend variable for assertion */
+bool pgstat_initialized PG_USED_FOR_ASSERTS_ONLY = false;
 
 /* ----------
  * Local function forward declarations
@@ -3036,6 +3038,7 @@ pgstat_initialize(void)
 
     /* Set up a process-exit hook to clean up */
     before_shmem_exit(pgstat_shutdown_hook, 0);
+    pgstat_initialized = true;
 
 #ifdef USE_ASSERT_CHECKING
     pgstat_is_initialized = true;
diff --git a/src/backend/replication/slot.c b/src/backend/replication/slot.c
index 1c6c0c7ce2..b2c719d31e 100644
--- a/src/backend/replication/slot.c
+++ b/src/backend/replication/slot.c
@@ -46,6 +46,7 @@
 #include "pgstat.h"
 #include "replication/slot.h"
 #include "storage/fd.h"
+#include "storage/ipc.h"
 #include "storage/proc.h"
 #include "storage/procarray.h"
 #include "utils/builtins.h"
@@ -160,6 +161,33 @@ ReplicationSlotsShmemInit(void)
     }
 }
 
+/*
+ * Exit hook to cleanup replication slots.
+ */
+static void
+ReplicationSlotShutdown(int code, Datum arg)
+{
+    /* Make sure active replication slots are released */
+    if (MyReplicationSlot != NULL)
+        ReplicationSlotRelease();
+
+    /* Also cleanup all the temporary slots. */
+    ReplicationSlotCleanup();
+}
+
+/*
+ * Initialize replication slot facility per backend.
+ */
+void
+ReplicationSlotInit(void)
+{
+    if (max_replication_slots < 1)
+        return;
+
+    assert_pgstat_initialized();    /* the callback requires pgstat */
+    before_shmem_exit(ReplicationSlotShutdown, (Datum) 0);
+}
+
 /*
  * Check whether the passed slot name is valid and report errors at elevel.
  *
diff --git a/src/backend/storage/file/fd.c b/src/backend/storage/file/fd.c
index f9cda6906d..8fbacdc86c 100644
--- a/src/backend/storage/file/fd.c
+++ b/src/backend/storage/file/fd.c
@@ -917,6 +917,7 @@ InitTemporaryFileAccess(void)
      * Register before-shmem-exit hook to ensure temp files are dropped while
      * we can still report stats.
      */
+    assert_pgstat_initialized();    /* the callback requires pgstat */
     before_shmem_exit(BeforeShmemExit_Files, 0);
 
 #ifdef USE_ASSERT_CHECKING
diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c
index b7d9da0aa9..b593ec8964 100644
--- a/src/backend/storage/lmgr/proc.c
+++ b/src/backend/storage/lmgr/proc.c
@@ -41,7 +41,6 @@
 #include "miscadmin.h"
 #include "pgstat.h"
 #include "postmaster/autovacuum.h"
-#include "replication/slot.h"
 #include "replication/syncrep.h"
 #include "replication/walsender.h"
 #include "storage/condition_variable.h"
@@ -847,13 +846,6 @@ ProcKill(int code, Datum arg)
     /* Cancel any pending condition variable sleep, too */
     ConditionVariableCancelSleep();
 
-    /* Make sure active replication slots are released */
-    if (MyReplicationSlot != NULL)
-        ReplicationSlotRelease();
-
-    /* Also cleanup all the temporary slots. */
-    ReplicationSlotCleanup();
-
     /*
      * Detach from any lock group of which we are a member.  If the leader
      * exist before all other group members, its PGPROC will remain allocated
diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
index 78bc64671e..b7c1a400f5 100644
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -40,6 +40,7 @@
 #include "pgstat.h"
 #include "postmaster/autovacuum.h"
 #include "postmaster/postmaster.h"
+#include "replication/slot.h"
 #include "replication/walsender.h"
 #include "storage/bufmgr.h"
 #include "storage/fd.h"
@@ -531,6 +532,12 @@ BaseInit(void)
      */
     pgstat_initialize();
 
+    /*
+     * Initialize replication slot. This must be after pgstat_initialize() so
+     * that the cleanup happens before the shutdown of pgstat facility.
+     */
+    ReplicationSlotInit();
+
     /* Do local initialization of storage and buffer managers */
     InitSync();
     smgrinit();
diff --git a/src/include/pgstat.h b/src/include/pgstat.h
index bcd3588ea2..3727e4cd53 100644
--- a/src/include/pgstat.h
+++ b/src/include/pgstat.h
@@ -992,6 +992,15 @@ extern PgStat_Counter pgStatTransactionIdleTime;
  */
 extern SessionEndType pgStatSessionEndCause;
 
+/*
+ * Modules that require pgstat (at process exit) should install their
+ * before-shmem hook after pgstat. This variable is used to make sure of that
+ * prerequisite.
+ */
+extern bool pgstat_initialized;
+#define assert_pgstat_initialized() Assert (pgstat_initialized);
+
+
 /* ----------
  * Functions called from postmaster
  * ----------
diff --git a/src/include/replication/slot.h b/src/include/replication/slot.h
index 53d773ccff..124d107662 100644
--- a/src/include/replication/slot.h
+++ b/src/include/replication/slot.h
@@ -193,6 +193,9 @@ extern PGDLLIMPORT int max_replication_slots;
 extern Size ReplicationSlotsShmemSize(void);
 extern void ReplicationSlotsShmemInit(void);
 
+/* per-backend initialization */
+extern void ReplicationSlotInit(void);
+
 /* management of individual slots */
 extern void ReplicationSlotCreate(const char *name, bool db_specific,
                                   ReplicationSlotPersistency p, bool two_phase);