Date: Fri, 10 Feb 2023 15:31:24 +0100
From: hubert depesz lubaczewski <depesz@depesz.com>
Sender: depesz@depesz.com
To: Masahiko Sawada <sawada.mshk@gmail.com>
Cc: Amit Kapila <amit.kapila16@gmail.com>,
	PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>
Subject: Re: WAL segments removed from primary despite the fact that logical
 replication slot needs it.
Message-ID: <Y+ZVPHHcYirQDgJF@depesz.com>
Reply-To: depesz@depesz.com
References: <Y3T6WxK483Vu6bsi@depesz.com>
 <CAD21AoBFmWYvgmwiugOmHD8h9-0k+zY=Cd584PNGjvRGZk9fSA@mail.gmail.com>
 <Y3YKlyfdn8sX5Gpn@depesz.com>
 <CAA4eK1Lz6W4mEL0ANPxL-bLQRmrh1+4sWbXf2CWG9oAgKs_j3A@mail.gmail.com>
 <Y3tFw2r6NVMnWqA/@depesz.com>
 <CAA4eK1L3LThSYYNf3hEDhy9qomFkdVmfV1YCjNDDbNBPhcg=Pg@mail.gmail.com>
 <Y3tpa/MmSnO3wBjG@depesz.com>
 <CAD21AoDb3zB=0sZJN5K+eynALhJeOogHREPXhPprgCOU99hrrw@mail.gmail.com>
 <Y5HGyYfvOiQZFg8H@depesz.com>
 <CAD21AoBG2OSDOFTtpPtQ7fx5Vt8p3dS5hPAv28CBSC6z2kHx-g@mail.gmail.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Disposition: inline
In-Reply-To: 
 <CAD21AoBG2OSDOFTtpPtQ7fx5Vt8p3dS5hPAv28CBSC6z2kHx-g@mail.gmail.com>
Archived-At: 
 <https://www.postgresql.org/message-id/Y%2BZVPHHcYirQDgJF%40depesz.com>
Precedence: bulk

Hi,
so, we have another bit of interesting information. maybe related, maybe
not.

We noticed weird situation on two clusters we're trying to upgrade.

In both cases sitaution looked the same:

1. there was another process (debezium) connected to source (pg12) using
   logical replication
2. pg12 -> pg14 replication failed with the message 'ERROR:  requested
   WAL segment ... has already been '
3. some time afterwards (most likely couple of hours) the process that
   is/was responsible for debezium replicaiton (pg process) stopped
   handling WAL, but instead is eating 100% of cpu.

When this situation happens, we can't pg_cancel_backend(pid) for the
"broken" wal sender, it also can't be pg_terminate_backend() !

strace of the process doesn't show anything.

When I tried to get backtrace from gdb all I got was:

(gdb) bt
#0  0x0000aaaad270521c in hash_seq_search ()
#1  0x0000ffff806c86cc in ?? () from /usr/lib/postgresql/12/lib/pgoutput.so
#2  0x0000aaaad26e3644 in CallSyscacheCallbacks ()
#3  0x0000aaaad26e3644 in CallSyscacheCallbacks ()
#4  0x0000aaaad257764c in ReorderBufferCommit ()
#5  0x0000aaaad256c804 in ?? ()
#6  0x0000aaaaf303d280 in ?? ()

If I'd quit gdb, and restart, and redo bt, I get 

#0  0x0000ffff806c81a8 in hash_seq_search@plt () from /usr/lib/postgresql/12/lib/pgoutput.so
#1  0x0000ffff806c86cc in ?? () from /usr/lib/postgresql/12/lib/pgoutput.so
#2  0x0000aaaad291ae58 in ?? ()

or

#0  0x0000aaaad2705244 in hash_seq_search ()
#1  0x0000ffff806c86cc in ?? () from /usr/lib/postgresql/12/lib/pgoutput.so
#2  0x0000aaaad26e3644 in CallSyscacheCallbacks ()
#3  0x0000aaaad26e3644 in CallSyscacheCallbacks ()
#4  0x0000aaaad257764c in ReorderBufferCommit ()
#5  0x0000aaaad256c804 in ?? ()
#6  0x0000aaaaf303d280 in ?? ()

At this moment, the only thing that we can do is kill -9 the process (or
restart pg).

I don't know if it's relevant, but I have this case *right now*, and if
it's helpful I can provide more information before we will have to kill
it.

Best regards,

depesz