Re: Logical replication timeout problem

public inbox for [email protected]  
help / color / mirror / Atom feed

From: Fabrice Chapuis <[email protected]>
To: Amit Kapila <[email protected]>
Cc: PostgreSQL Hackers <[email protected]>
Subject: Re: Logical replication timeout problem
Date: Mon, 20 Sep 2021 18:13:24 +0200
Message-ID: <CAA5-nLA8C0LZdVDdPDNeWcJYGzGVV3nJ7Ni0PdSyHJNxi628ww@mail.gmail.com> (raw)
In-Reply-To: <CAA4eK1KrJP=oMOu5VJKn1uZjn+Xq110AGUxJpBrp3jN7vWXVPg@mail.gmail.com>
References: <CAA5-nLARN7-3SLU_QUxfy510pmrYK6JJb=bk3hcgemAM_pAv+w@mail.gmail.com>
	<CAA4eK1JLerufRV4Zr4h-vW4Fjz6LJjd-QZxVywpFrtfvZhXVWg@mail.gmail.com>
	<CAA5-nLC0NKo1VsKgf+jEEH=5jGAN2pyCivyG59yX3bQcLSL4tg@mail.gmail.com>
	<CAA4eK1KHQfnhmdnLZQrRoAW3dYOPqXKtT5C54HoBno3MCtH4wA@mail.gmail.com>
	<CAA5-nLCH-XbCknSx2nVMtCByj8pv3jyRFQxL0qj4FLwby4TyNg@mail.gmail.com>
	<CAA4eK1KrJP=oMOu5VJKn1uZjn+Xq110AGUxJpBrp3jN7vWXVPg@mail.gmail.com>

By passing the autovacuum parameter to off the problem did not occur right
after loading the table as in our previous tests. However, the timeout
occurred later. We have seen the accumulation of .snap files for several Gb.

...
-rw-------. 1 postgres postgres 16791226 Sep 20 15:26
xid-1238444701-lsn-2D2B-F5000000.snap
-rw-------. 1 postgres postgres 16973268 Sep 20 15:26
xid-1238444701-lsn-2D2B-F6000000.snap
-rw-------. 1 postgres postgres 16790984 Sep 20 15:26
xid-1238444701-lsn-2D2B-F7000000.snap
-rw-------. 1 postgres postgres 16988112 Sep 20 15:26
xid-1238444701-lsn-2D2B-F8000000.snap
-rw-------. 1 postgres postgres 16864593 Sep 20 15:26
xid-1238444701-lsn-2D2B-F9000000.snap
-rw-------. 1 postgres postgres 16902167 Sep 20 15:26
xid-1238444701-lsn-2D2B-FA000000.snap
-rw-------. 1 postgres postgres 16914638 Sep 20 15:26
xid-1238444701-lsn-2D2B-FB000000.snap
-rw-------. 1 postgres postgres 16782471 Sep 20 15:26
xid-1238444701-lsn-2D2B-FC000000.snap
-rw-------. 1 postgres postgres 16963667 Sep 20 15:27
xid-1238444701-lsn-2D2B-FD000000.snap
...



2021-09-20 17:11:29 CEST [12687]: [1283-1] user=,db=,client= LOG:
checkpoint starting: time
2021-09-20 17:11:31 CEST [12687]: [1284-1] user=,db=,client= LOG:
checkpoint complete: wrote 13 buffers (0.0%); 0 WAL file(s) added, 0
removed, 0 recycled; write=1.713 s, sync=0.001 s, total=1.718 s
; sync files=12, longest=0.001 s, average=0.001 s; distance=29 kB,
estimate=352191 kB
2021-09-20 17:12:43 CEST [59986]: [2-1] user=,db=,client= ERROR:
terminating logical replication worker due to timeout
2021-09-20 17:12:43 CEST [12546]: [1068-1] user=,db=,client= LOG:  worker
process: logical replication worker for subscription 24215702 (PID 59986)
exited with exit code 1
2021-09-20 17:12:43 CEST [39945]: [1-1] user=,db=,client= LOG:  logical
replication apply worker for subscription "sub" has started
2021-09-20 17:12:43 CEST [39946]: [1-1] user=repuser,db=db,client=127.0.0.1
LOG:  received replication command: IDENTIFY_SYSTEM

Regards,

Fabrice



On Mon, Sep 20, 2021 at 1:51 PM Amit Kapila <[email protected]> wrote:

> On Mon, Sep 20, 2021 at 4:10 PM Fabrice Chapuis <[email protected]>
> wrote:
> >
> > Hi Amit,
> >
> > We can replay the problem: we load a table of several Gb in the schema
> of the publisher, this generates the worker's timeout after one minute from
> the end of this load. The table on which this load is executed is not
> replicated.
> >
> > 2021-09-16 12:06:50 CEST [24881]: [1-1]
> user=postgres,db=db012a00,client=[local] LOG:  duration: 1281408.171 ms
> statement: COPY db.table (col1, col2) FROM stdin;
> >
> > 2021-09-16 12:07:11 CEST [12161]: [1-1] user=,db=,client= LOG:
> automatic analyze of table "db.table " system usage: CPU: user: 4.13 s,
> system: 0.55 s, elapsed: 9.58 s
> >
> > 2021-09-16 12:07:50 CEST [3770]: [2-1] user=,db=,client= ERROR:
> terminating logical replication worker due to timeout
> >
> > Before increasing value for wal_sender_timeout and wal_receiver_timeout
> I thought to further investigate the mechanisms leading to this timeout.
> >
>
> The basic problem here seems to be that WAL Sender is not able to send
> a keepalive or any other message for the configured
> wal_receiver_timeout. I am not sure how that can happen but can you
> once try by switching autovacuum = off? I wanted to ensure that
> WALSender is not blocked due to the background process autovacuum.
>
> --
> With Regards,
> Amit Kapila.
>

view thread (56+ messages)  latest in thread

reply

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Reply to all the recipients using the --to and --cc options:
  reply via email

  To: [email protected]
  Cc: [email protected], [email protected], [email protected]
  Subject: Re: Logical replication timeout problem
  In-Reply-To: <CAA5-nLA8C0LZdVDdPDNeWcJYGzGVV3nJ7Ni0PdSyHJNxi628ww@mail.gmail.com>

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox