Re: walsender timeout on logical replication set

Thank you vary much for coming in!

At Fri, 17 Sep 2021 10:18:11 +0530, Amit Kapila <amit.kapila16@gmail.com> wrote in 
> On Mon, Sep 13, 2021 at 7:01 AM Kyotaro Horiguchi
> <horikyota.ntt@gmail.com> wrote:
> >
> > Hello.
> >
> > As reported in [1] it seems that walsender can suffer timeout in
> > certain cases.  It is not clearly confirmed, but I suspect that
> > there's the case where LogicalRepApplyLoop keeps running the innermost
> > loop without receiving keepalive packet for longer than
> > wal_sender_timeout (not wal_receiver_timeout).
> 
> Why is that happening? In the previous investigation in this area [1]
> your tests revealed that after reading a WAL page, we always send keep
> alive, so even if the transaction is large, we should send some
> keepalive in-between.

We fixed too-many keepalives (aka keepalive-flood) in the thread, but
this is an issue of long absense of subscriber response. What I'm
suspecting, or assuming here is:

- The publisher is working fine. It doesn't send extra keepalives so
  much and does send regular keepalives with wal_sender_timeout/2 by
  the sender's clock.

- Networks conveys all the data in-time.

- The subscriber consumes received data at less than half the speed at
  which the publisher sends data.  In this case, while the burst
  traffic is coming, the publisher keep sending for
  wal_sender_timeout/2 seconds and it may not send a keepalive for the
  same duration. This is the correct behavior.  On the other hand, the
  subscriber is kept busy without receiving a keepalive for
  wal_sender_timeout seconds.  AFAICS LogicalRepApplyLoop doesn't send
  a response unless a keepalive comes while in the inner-most loop.

If wel_sender_timeout is relatively short (5 seconds, in the report),
a burst (or a gap-less) logical replication traffic can continue
easily for more than 2.5 seconds.  If wal_sender_timeout is longer (1
min, ditto), burst replication traffics last for more than
wal_sender_timeout/2 becomes relatively not so frequent.

However, I'm not sure how it makes things worse again to increase it
further to 5 min.

Is my diagnostics that while the innermost loop in LogicalRepAllyLoop
[A] is busy, it doesn't have a chance to send reply until a keepalive
comes in correct?  If so, walsender timeout due to slowness of
subscriber happens and we might need to break the innermost loop to
give subscriber a chance to send a response with appropriate
intervals. This is what I wanted to propose.

[A]
backend/replication/logical/worker.c:2565@today's master
>     /* Loop to process all available data (without blocking). */
>     for (;;)



> The other thing that I am not able to understand from Abhishek's reply
> [2] is why increasing wal_sender_timeout/wal_recevier_timeout leads to
> the removal of required WAL segments. As per my understanding, we
> shouldn't remove WAL unless we get confirmation that the subscriber
> has processed it.
> 
> [1] - https://www.postgresql.org/message-id/20210610.150016.1709823354377067679.horikyota.ntt%40gmail.com
> [2] - https://www.postgresql.org/message-id/CAEDsCzjEHLxgqa4d563CKFwSbgBvvnM91Cqfq_qoZDXCkyOsiw%40mail.gmail.com
> 
> Note - I have added Abhishek to see if he has answers to any of these questions.

Ouch! max_slot_wal_keep_size was introduced at 13. So I have no idea
of how required segments can be removed on the publisher for now.

== From the first report [1]
sourcedb=# select * from pg_replication_slots;
...
restart_lsn            116D0/C36886F8
confirmed_flush_lsn    116D0/C3E5D370

targetdb=# show wal_receiver_status_interval;
wal_receiver_status_interval  2s

targetdb=# select * from pg_stat_subscription;
..
received_lsn          116D1/2BA8F170
last_msg_send_time      2021-08-20 09:05:15.398423+09
last_msg_receipt_time 2021-08-20 09:05:15.398471+09
latest_end_lsn          116D1/2BA8F170
latest_end_time          2021-08-20 09:05:15.398423+09
==

There is a gap with about 105 segments (1.7GB) between how far the
subscriber advanced and the publisher's idea of how far the subscriber
advanced. But that alone cannot cause wal removal..

[1]
https://www.postgresql.org/message-id/flat/CAEDsCzjEHLxgqa4d563CKFwSbgBvvnM91Cqfq_qoZDXCkyOsiw%40mail.gmail.com#72da631f3af885b06669ddc1636a0a63

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center