Revert 019_replslot_limit.pl related debugging aids.

This reverts most of 91c0570a791, f28bf667f60, fe0972ee5e6, afdeff10526. The
only thing left is the retry loop in 019_replslot_limit.pl that avoids
spurious failures by retrying a couple times.

We haven't seen any hard evidence that this is caused by anything but slow
process shutdown. We did not find any cases where walsenders did not vanish
after waiting for longer. Therefore there's no reason for this debugging code
to remain.

Discussion: https://postgr.es/m/20220530190155[email protected]
Backpatch: 15-

diff --git a/src/backend/replication/slot.c b/src/backend/replication/slot.c
index e5c2102bcd566d25aa72067ee2e39832d060580f..850b74936fe65315be387f079b67fb7cf1dfa72d 100644 (file)
--- a/src/backend/replication/slot.c
+++ b/src/backend/replication/slot.c
@@ -177,10 +177,6 @@ ReplicationSlotInitialize(void)
 static void
 ReplicationSlotShmemExit(int code, Datum arg)
 {
-   /* temp debugging aid to analyze 019_replslot_limit failures */
-   elog(DEBUG3, "replication slot exit hook, %s active slot",
-        MyReplicationSlot != NULL ? "with" : "without");
-
    /* Make sure active replication slots are released */
    if (MyReplicationSlot != NULL)
        ReplicationSlotRelease();
@@ -582,9 +578,6 @@ ReplicationSlotCleanup(void)
    Assert(MyReplicationSlot == NULL);
 
 restart:
-   /* temp debugging aid to analyze 019_replslot_limit failures */
-   elog(DEBUG3, "temporary replication slot cleanup: begin");
-
    LWLockAcquire(ReplicationSlotControlLock, LW_SHARED);
    for (i = 0; i < max_replication_slots; i++)
    {
@@ -593,10 +586,6 @@ restart:
        if (!s->in_use)
            continue;
 
-       /* unlocked read of active_pid is ok for debugging purposes */
-       elog(DEBUG3, "temporary replication slot cleanup: %d in use, active_pid: %d",
-            i, (int) s->active_pid);
-
        SpinLockAcquire(&s->mutex);
        if (s->active_pid == MyProcPid)
        {
@@ -614,8 +603,6 @@ restart:
    }
 
    LWLockRelease(ReplicationSlotControlLock);
-
-   elog(DEBUG3, "temporary replication slot cleanup: done");
 }
 
 /*
@@ -657,9 +644,6 @@ ReplicationSlotDropPtr(ReplicationSlot *slot)
    char        path[MAXPGPATH];
    char        tmppath[MAXPGPATH];
 
-   /* temp debugging aid to analyze 019_replslot_limit failures */
-   elog(DEBUG3, "replication slot drop: %s: begin", NameStr(slot->data.name));
-
    /*
     * If some other backend ran this code concurrently with us, we might try
     * to delete a slot with a certain name while someone else was trying to
@@ -710,9 +694,6 @@ ReplicationSlotDropPtr(ReplicationSlot *slot)
                        path, tmppath)));
    }
 
-   elog(DEBUG3, "replication slot drop: %s: removed on-disk",
-        NameStr(slot->data.name));
-
    /*
     * The slot is definitely gone.  Lock out concurrent scans of the array
     * long enough to kill it.  It's OK to clear the active PID here without
@@ -726,13 +707,8 @@ ReplicationSlotDropPtr(ReplicationSlot *slot)
    slot->active_pid = 0;
    slot->in_use = false;
    LWLockRelease(ReplicationSlotControlLock);
-
-   elog(DEBUG3, "replication slot drop: %s: marked as not in use", NameStr(slot->data.name));
-
    ConditionVariableBroadcast(&slot->active_cv);
 
-   elog(DEBUG3, "replication slot drop: %s: notified others", NameStr(slot->data.name));
-
    /*
     * Slot is dead and doesn't prevent resource removal anymore, recompute
     * limits.
@@ -740,8 +716,6 @@ ReplicationSlotDropPtr(ReplicationSlot *slot)
    ReplicationSlotsComputeRequiredXmin(false);
    ReplicationSlotsComputeRequiredLSN();
 
-   elog(DEBUG3, "replication slot drop: %s: computed required", NameStr(slot->data.name));
-
    /*
     * If removing the directory fails, the worst thing that will happen is
     * that the user won't be able to create a new slot with the same name
@@ -751,8 +725,6 @@ ReplicationSlotDropPtr(ReplicationSlot *slot)
        ereport(WARNING,
                (errmsg("could not remove directory \"%s\"", tmppath)));
 
-   elog(DEBUG3, "replication slot drop: %s: removed directory", NameStr(slot->data.name));
-
    /*
     * Drop the statistics entry for the replication slot.  Do this while
     * holding ReplicationSlotAllocationLock so that we don't drop a
@@ -767,9 +739,6 @@ ReplicationSlotDropPtr(ReplicationSlot *slot)
     * a slot while we're still cleaning up the detritus of the old one.
     */
    LWLockRelease(ReplicationSlotAllocationLock);
-
-   elog(DEBUG3, "replication slot drop: %s: done",
-        NameStr(slot->data.name));
 }
 
 /*
@@ -1329,12 +1298,6 @@ InvalidatePossiblyObsoleteSlot(ReplicationSlot *s, XLogRecPtr oldestLSN,
                (void) kill(active_pid, SIGTERM);
                last_signaled_pid = active_pid;
            }
-           else
-           {
-               /* temp debugging aid to analyze 019_replslot_limit failures */
-               elog(DEBUG3, "not signalling process %d during invalidation of slot \"%s\"",
-                    active_pid, NameStr(slotname));
-           }
 
            /* Wait until the slot is released. */
            ConditionVariableSleep(&s->active_cv,
@@ -1398,10 +1361,6 @@ InvalidateObsoleteReplicationSlots(XLogSegNo oldestSegno)
    XLogSegNoOffsetToRecPtr(oldestSegno, 0, wal_segment_size, oldestLSN);
 
 restart:
-   /* temp debugging aid to analyze 019_replslot_limit failures */
-   elog(DEBUG3, "begin invalidating obsolete replication slots older than %X/%X",
-        LSN_FORMAT_ARGS(oldestLSN));
-
    LWLockAcquire(ReplicationSlotControlLock, LW_SHARED);
    for (int i = 0; i < max_replication_slots; i++)
    {
@@ -1427,8 +1386,6 @@ restart:
        ReplicationSlotsComputeRequiredLSN();
    }
 
-   elog(DEBUG3, "done invalidating obsolete replication slots");
-
    return invalidated;
 }
 

diff --git a/src/backend/storage/lmgr/lwlock.c b/src/backend/storage/lmgr/lwlock.c
index 8aef909037da712481cec1d2bed2d10f5f560f50..fc5c76a48f8762e7e034461f63c3c9ec7be913c2 100644 (file)
--- a/src/backend/storage/lmgr/lwlock.c
+++ b/src/backend/storage/lmgr/lwlock.c
@@ -1942,10 +1942,3 @@ LWLockHeldByMeInMode(LWLock *l, LWLockMode mode)
    }
    return false;
 }
-
-/* temp debugging aid to analyze 019_replslot_limit failures */
-int
-LWLockHeldCount(void)
-{
-   return num_held_lwlocks;
-}

diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
index 6b9082604fb7213570ef8ab8a389db69ea0c3de7..a5c208a20a829da0eb9882ab41cba87814bddfe4 100644 (file)
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -1231,24 +1231,6 @@ ShutdownPostgres(int code, Datum arg)
     * them explicitly.
     */
    LockReleaseAll(USER_LOCKMETHOD, true);
-
-   /*
-    * temp debugging aid to analyze 019_replslot_limit failures
-    *
-    * If an error were thrown outside of a transaction nothing up to now
-    * would have released lwlocks. We probably will add an
-    * LWLockReleaseAll(). But for now make it easier to understand such cases
-    * by warning if any lwlocks are held.
-    */
-#ifdef USE_ASSERT_CHECKING
-   {
-       int         held_lwlocks = LWLockHeldCount();
-
-       if (held_lwlocks)
-           elog(WARNING, "holding %d lwlocks at the end of ShutdownPostgres()",
-                held_lwlocks);
-   }
-#endif
 }
 
 

diff --git a/src/bin/pg_basebackup/pg_basebackup.c b/src/bin/pg_basebackup/pg_basebackup.c
index b66eac707a45fecd92231fb11ffd6796c0255102..4445a86aee2018c5d087e5accae2ac1c72608e8a 100644 (file)
--- a/src/bin/pg_basebackup/pg_basebackup.c
+++ b/src/bin/pg_basebackup/pg_basebackup.c
@@ -694,16 +694,8 @@ StartLogStreamer(char *startpos, uint32 timeline, char *sysidentifier,
    bgchild = fork();
    if (bgchild == 0)
    {
-       int         ret;
-
        /* in child process */
-       ret = LogStreamerMain(param);
-
-       /* temp debugging aid to analyze 019_replslot_limit failures */
-       if (verbose)
-           pg_log_info("log streamer with pid %d exiting", getpid());
-
-       exit(ret);
+       exit(LogStreamerMain(param));
    }
    else if (bgchild < 0)
        pg_fatal("could not create background process: %m");

diff --git a/src/include/storage/lwlock.h b/src/include/storage/lwlock.h
index e8c91139f89c89b1b2313d258c2050777f2163c6..52b32bda9919c083ea5087cd90129ebc82f1de29 100644 (file)
--- a/src/include/storage/lwlock.h
+++ b/src/include/storage/lwlock.h
@@ -121,7 +121,6 @@ extern void LWLockReleaseClearVar(LWLock *lock, uint64 *valptr, uint64 val);
 extern void LWLockReleaseAll(void);
 extern bool LWLockHeldByMe(LWLock *lock);
 extern bool LWLockHeldByMeInMode(LWLock *lock, LWLockMode mode);
-extern int LWLockHeldCount(void);
 
 extern bool LWLockWaitForVar(LWLock *lock, uint64 *valptr, uint64 oldval, uint64 *newval);
 extern void LWLockUpdateVar(LWLock *lock, uint64 *valptr, uint64 value);

diff --git a/src/test/recovery/t/019_replslot_limit.pl b/src/test/recovery/t/019_replslot_limit.pl
index 6bbf55c3ee127303e5f511953776439f86cd8075..84c9c4b0b3cfd20ab25ce5a783960fb694b56b8e 100644 (file)
--- a/src/test/recovery/t/019_replslot_limit.pl
+++ b/src/test/recovery/t/019_replslot_limit.pl
@@ -316,16 +316,13 @@ $node_primary3->append_conf(
    max_wal_size = 2MB
    log_checkpoints = yes
    max_slot_wal_keep_size = 1MB
-
-   # temp debugging aid to analyze 019_replslot_limit failures
-   log_min_messages=debug3
    ));
 $node_primary3->start;
 $node_primary3->safe_psql('postgres',
    "SELECT pg_create_physical_replication_slot('rep3')");
 # Take backup
 $backup_name = 'my_backup';
-$node_primary3->backup($backup_name, backup_options => ['--verbose']);
+$node_primary3->backup($backup_name);
 # Create standby
 my $node_standby3 = PostgreSQL::Test::Cluster->new('standby_3');
 $node_standby3->init_from_backup($node_primary3, $backup_name,
@@ -336,11 +333,9 @@ $node_primary3->wait_for_catchup($node_standby3);
 
 my $senderpid;
 
-# We've seen occasional cases where multiple walsender pids are active. It
-# could be that we're just observing process shutdown being slow. To collect
-# more information, retry a couple times, print a bit of debugging information
-# each iteration. Don't fail the test if retries find just one pid, the
-# buildfarm failures are too noisy.
+# We've seen occasional cases where multiple walsender pids are still active
+# at this point, apparently just due to process shutdown being slow. To avoid
+# spurious failures, retry a couple times.
 my $i = 0;
 while (1)
 {