Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1gyuGK-0001Ao-HO for pgsql-admin@arkaria.postgresql.org; Wed, 27 Feb 2019 08:08:21 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.89) (envelope-from ) id 1gyuGH-0006tG-Ob for pgsql-admin@arkaria.postgresql.org; Wed, 27 Feb 2019 08:08:17 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1gyuGH-0006t9-6o for pgsql-admin@lists.postgresql.org; Wed, 27 Feb 2019 08:08:17 +0000 Received: from mail-ua1-x942.google.com ([2607:f8b0:4864:20::942]) by magus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1gyuG8-000266-Rm for pgsql-admin@postgresql.org; Wed, 27 Feb 2019 08:08:16 +0000 Received: by mail-ua1-x942.google.com with SMTP id g1so3658071uae.10 for ; Wed, 27 Feb 2019 00:08:08 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=avast.com; s=google; h=from:references:in-reply-to:mime-version:thread-index:date :message-id:subject:to:cc; bh=90eZxIno14csyMRr0H1OMIS4uxJj+KAF01aMEOXGq3U=; b=QdYJks3Kj0aahqQkFJY6J1iat60lvkL1rfwZBTMo3fN4ziM+Se7hC5PMOYTl7zVQxk 8w6Lfv7UyiVbA1yTnOImjQa21UIkdW2NhqLcr/1UVr1s1PzxI5P5R+g0bBfcvaxlPHmJ KgZlG9b604fzYXcvuZaMkDze5wpteJVszXUKI= X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:references:in-reply-to:mime-version :thread-index:date:message-id:subject:to:cc; bh=90eZxIno14csyMRr0H1OMIS4uxJj+KAF01aMEOXGq3U=; b=JwAw1y/moJMAPX5msC3QavhXrobcgpcvbMcfHwCsLD0legUqWs48L2fHF0es1x8k4D XgVQa+IpVDS4azlONZrDKhkhBtfo5mADz/rU5NX+3ECKdcyYEO6ZTM4mqVsVqOJIPhaS ptvGPAqAmQegd5F/m7VJBpUgr674+udmEhH6ZQwDp4yP8+z7wpxOLyt1ZEP5bFl/XWaD 7UwkQ87FIyRD9ZSZjyHzUi5PIJIPs03+wlUuk4sNjW8v34Y2gbER56OKb66TtFeEXoFR wLx9viXVOiuzDEQ4xxDnpdu8KKxQVgQnmiJV5QJmp9MDjnVbRk3we+OidS/VDEhyJJxG fw2w== X-Gm-Message-State: APjAAAWzgKfQOmpqOnGofg6hgk1Z/RjzSmazmN4ZlTdUlexZ8NZa8i7Y x+moV4jornziVX7AVchAC5SdYFAGuGj5EP537DBBMQ== X-Google-Smtp-Source: AHgI3Ibj8BGAdnHLR3EL3P2R5CDlopi5Fv/TfI6n8vc+Q/VphmBOy+ymbELOPYl4YGR0sbs5Goq2pRGhRiD+0M3FJ0M= X-Received: by 2002:ab0:3145:: with SMTP id e5mr1296043uam.65.1551254885466; Wed, 27 Feb 2019 00:08:05 -0800 (PST) From: =?UTF-8?B?VG9tw6HFoSBVa28=?= References: <238227add62b080920c485b04ed4c341@mail.gmail.com> <742a645771b2bf7d4711fc32318226e5@mail.gmail.com> In-Reply-To: MIME-Version: 1.0 X-Mailer: Microsoft Outlook 16.0 Thread-Index: AQH5YlaYiH/04mWiagzbfffaOX7eKwG7/FJlA2yAp7UCLdNkkqVvb2oQ Date: Wed, 27 Feb 2019 09:08:02 +0100 Message-ID: <4210f00664cd6947f76436b77ecb30b8@mail.gmail.com> Subject: RE: streaming vs wal shipping issue To: Shreeyansh Dba Cc: pgsql-admin , =?UTF-8?Q?Petr_Nov=C3=A1k?= Content-Type: multipart/alternative; boundary="000000000000682e370582dbacf5" List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Precedence: bulk --000000000000682e370582dbacf5 Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable Hi agan, Point is, that files, which are not deleted after recovery, are WAL files present in DATA_DIR/pg_xlog directory =E2=80=A6 Regards Tomas Uko *From:* Shreeyansh Dba *Sent:* =C3=BAter=C3=BD 26. =C3=BAnora 2019 17:56 *To:* Tom=C3=A1=C5=A1 Uko *Cc:* pgsql-admin ; Petr Nov=C3=A1k *Subject:* Re: streaming vs wal shipping issue PostgreSQL doesn't clean up files copied by your archive_command. You need to have a separate task clean those out. PostgreSQL's active wal_keep_segments etc. are in the data/pg_xlog directory. Please have look at http://www.postgresql.org/docs/9.4/interactive/pgarchivecleanup.html Thanks & Regards, *Shreeyansh DBA Team* www.shreeyansh.com On Tue, Feb 26, 2019 at 8:31 PM Tom=C3=A1=C5=A1 Uko wrote: Hi, Just to clarify, we use both methods, everything is correctly set and when there is no issue working =E2=80=A6 i.e. see this line from log: 2019-02-25 09:09:28.490 CET, pid: 2090891, client: , db: , usr: ; LOG: started streaming WAL from primary at CE8B/17000000 on timeline 2 But problem appears once there is large enough replication lag, so streaming replication just give up and it reverts to replaying WALs (which is point of have both methods, so we don=E2=80=99t need to re-initialize slave/replica again from master), until it catches up with master again (and switches to streaming replication again). Only problem is, that those WAL files copied from =E2=80=9Cmaster=E2=80=9D (technically from shared sto= rage server) are never deleted from slave/replica pg_xlog directory (after they are replayed on slave/replica). Best regards Tomas Uko *From:* Shreeyansh Dba *Sent:* =C3=BAter=C3=BD 26. =C3=BAnora 2019 14:01 *To:* Tom=C3=A1=C5=A1 Uko *Cc:* pgsql-admin ; Petr Nov=C3=A1k *Subject:* Re: streaming vs wal shipping issue Hi Tom=C3=A1=C5=A1 Uko, Here you go in detail to understand the steaming vs wal shipping : "Streaming replication" refers to continuous sending of WAL records over a TCP/IP connection between the master and the replica, using the walsender protocol over replication connections. The master reads its own WAL from pg_xlog and sends it to the replica on demand. It's configured with a primary_conninfo directive in recovery.conf and pg_hba.conf entries on the master to permit replicationconnections. You also need wal_keep_segments an= d some other options. "Log shipping" refers to periodic sending of WAL records as whole WAL archives via a file transfer protocol to an archive location from which the replica can then fetch them. It's configured with a restore_command directi= ve in recovery.conf and an archive_command in the master. PostgreSQL doesn't care where the files are or how they're transferred, only that the archive_command puts them there and the restore_command fetches the required archive. Streaming replication doesn't have as much lag, as records are sent as they are generated. However, it requires both master and replica to be online and able to communicate directly. It also requires the replica to keep up well enough that the master still has on-disk copies of the WAL the replica needs, and generally requires you to spend extra pg_xlog space on retaining extra WAL for the replica. Thanks & Regards, *Shreeyansh DBA Team* www.shreeyansh.com On Tue, Feb 26, 2019 at 2:56 PM Tom=C3=A1=C5=A1 Uko wrote: Hi all, We have recently found weird issue with WAL being still present after recovery (In fact, they are never deleted), this problem is on several version (starting from 9.4 up to 9.6, possibly later). Our setup is this: - Master in one DC, with wal shipping to different storage/server o Wal shipping via archive_command (pigz and scp - and we check return codes J ) - Several replicas in different DCs, configured use streaming replication as well as wal restore from that storage with archive_mode =3D 'on' o snippet of recovery.conf: standby_mode =3D 'on' primary_conninfo =3D 'host=3DXY port=3D5432 user=3DAAA password=3DPASSWORD sslmode=3Dverify-full' restore_command =3D '~/bin/wal_handler.sh -r -h REMOTE_STORAGE -f %f -p %p = -d LOCATION_ON_REMOTE_STORAGE' This custom script does this: [ -f =E2=80=9CPARAM_P/PARAM_F " ] && { echo "Logfile PARAM_P/PARAM_F alre= ady exists"; } echo "Restoring xlog PARAM_F " scp -i $SshKey -o PasswordAuthentication=3Dno -o StrictHostKeyChecking=3D= no REMOTE_STORAGE:LOCATION_ON_REMOTE_STORAGE/PARAM_F.gz PARAM_P [ $? =3D=3D 0 ] || { echo "Failed to retrieve log PARAM_F from REMOTE_STORAGE" && exit 1; } unpigz -f PARAM_P/PARAM_F.gz [ $? =3D=3D 0 ] || { echo "Failed to unpack log to PARAM_P/PARAM_F.gz" && exit 1; } When our master became under some massive DML workload (daily bases) some of replicas stops using streaming replication and switch to wal restore (so far good). Message in logs: 2019-02-25 23:10:03.087 CET, pid: 2100971, client: , db: , usr: ; LOG: recovery restart point at CEA9/3007188 2019-02-25 23:10:03.087 CET, pid: 2100971, client: , db: , usr: ; DETAIL: last completed transaction was at log time 2019-02-25 22:27:14.059533+01 2019-02-25 23:10:36.829 CET, pid: 2100971, client: , db: , usr: ; LOG: restartpoint starting: xlog 2019-02-25 23:10:47.832 CET, pid: 2100974, client: , db: , usr: ; FATAL: could not receive data from WAL stream: ERROR: requested WAL segment 000000020000CEA90000008A has already been removed But once they start restoring wals, they never deletes afterwards. We=E2=80= =99ve discovered when there is restore point, it creates next wal segment in sequence (in pg_xlog dir), which is immediately overwritten by restore. With overwrite enabled logs are full of: Restoring xlog 000000020000CE3900000029 Restoring xlog 000000020000CE390000002A Restoring xlog 000000020000CE390000002B Restoring xlog 000000020000CE390000002C Restoring xlog 000000020000CE390000002D Restoring xlog 000000020000CE390000002E And once if catches up: scp: /LOCATION_ON_REMOTE_STORAGE/000000020000CE8B00000017.gz: No such file or directory Failed to retrieve log 000000020000CE8B00000017 from REMOTE_STORAGE 2019-02-25 09:09:28.490 CET, pid: 2090891, client: , db: , usr: ; LOG: started streaming WAL from primary at CE8B/17000000 on timeline 2 When we disabled overriding of WALs during restore we git this error messag= e 2019-02-25 23:10:03.086 CET, pid: 2100971, client: , db: , usr: ; LOG: restartpoint complete: wrote 142421 buffers (18.1%); 0 transaction log file(s) added, 68 removed, 0 recycled; write=3D24.086 s, sync=3D0.022 s, total=3D24.424 s; sync files=3D74, longest=3D0.005 s, average=3D0.000 s; distance=3D1114130 kB, estimate=3D1114148 kB 2019-02-25 23:10:03.087 CET, pid: 2100971, client: , db: , usr: ; LOG: recovery restart point at CEA9/3007188 2019-02-25 23:10:03.087 CET, pid: 2100971, client: , db: , usr: ; DETAIL: last completed transaction was at log time 2019-02-25 22:27:14.059533+01 2019-02-25 23:10:36.829 CET, pid: 2100971, client: , db: , usr: ; LOG: restartpoint starting: xlog Logfile pg_xlog/000000020000CEA90000008A already exists Restoring xlog 000000020000CEA90000008A unpigz: abort: write error on pg_xlog/000000020000CEA90000008A (Inappropriate ioctl for device) Which means, wal file is present in this xlog directory Thanks for any advice --000000000000682e370582dbacf5 Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable

Hi agan,

=C2=A0

Point is, that files, which are not deleted after re= covery, are WAL files present in DATA_DIR/pg_xlog directory =E2=80=A6

=C2=A0

Regards

Tomas Uko

=C2=A0

=C2=A0

From: Shreeyansh Dba <shreeyansh2014@gmail.com>
Sent: =C3=BAt= er=C3=BD 26. =C3=BAnora 2019 17:56
To: Tom=C3=A1=C5=A1 Uko <uko@avast.com>
Cc: pgsql-ad= min <pgsql-admin@postgresq= l.org>; Petr Nov=C3=A1k <nova= kp@avast.com>
Subject: Re: streaming vs wal shipping issue=

=C2=A0

PostgreSQL doesn't clean up files copied by your archive_co= mmand. You need to have a separate task clean those out. PostgreSQL's a= ctive wal_keep_segments etc. are in the data/pg_xlog directory.

=C2=A0

Thanks & Regards,
Shreeyansh DBA Tea= m
www.shreeyansh.com

=C2=A0

= =C2=A0

On Tue, Feb 26, 2019 at 8:31 PM = Tom=C3=A1=C5=A1 Uko <uko@avast.com&= gt; wrote:

Hi,

=C2= =A0

Just to clarify, we use both methods,= everything is correctly set and when there is no issue working =E2=80=A6 = =C2=A0i.e. see this line from log:

2019-02-25 = 09:09:28.490 CET, pid: 2090891, client: , db: , usr: ; LOG:=C2=A0 started s= treaming WAL from primary at CE8B/17000000 on timeline 2

=C2=A0

But problem appear= s once there is large enough replication lag, so streaming replication just= give up and it reverts to replaying WALs (which is point of have both meth= ods, so we don=E2=80=99t need to re-initialize slave/replica again from mas= ter), until it catches up with master again (and switches to streaming repl= ication again). Only problem is, that those WAL files copied from =E2=80=9C= master=E2=80=9D (technically from shared storage server) are never deleted = from slave/replica pg_xlog directory (after they are replayed on slave/repl= ica). =C2=A0

=C2=A0

Best regards

Tomas Uko

=C2=A0

From: Shreeyansh Dba <shreeyansh2014@gmail.com>
Sent: =C3=BAter=C3=BD = 26. =C3=BAnora 2019 14:01
To: Tom=C3=A1=C5=A1 Uko <uko@avast.com>
Cc:= pgsql-admin <pgsql-admin@postgresql.org>; Petr Nov=C3=A1k <novakp@avast.com>
Sub= ject: Re: streaming vs wal shipping issue

=C2=A0

=

Hi=C2= =A0Tom=C3=A1=C5=A1 Uko,

Here you go in detail to underst= and=C2=A0the steaming vs wal shipping :
"Streaming replication"= ; refers to continuous sending of WAL records over a TCP/IP connection betw= een the master and the replica, using the walsender protocol over=C2=A0replication=C2=A0connections. The master reads its own WAL fr= om=C2=A0p= g_xlog=C2=A0and sends it to the replica on deman= d. It's configured with a=C2=A0primary_conninfo=C2=A0= directive in=C2=A0recovery.conf=C2=A0and=C2=A0pg_hba.conf=C2=A0entries on the master to permit=C2=A0<= span style=3D"font-size:10.0pt;font-family:Consolas;color:#242729;border:no= ne windowtext 1.0pt;padding:0cm;background:#eff0f1">replicationconnections. You also need=C2=A0wal_keep_segments=C2=A0and some other options.

"Log shipping" refers to periodic sendi= ng of WAL records as whole WAL archives via a file transfer protocol to an = archive location from which the replica can then fetch them. It's confi= gured with a=C2=A0restore_command=C2=A0directive in=C2=A0= recovery.= conf=C2=A0and an=C2=A0archive_command=C2=A0in the master. PostgreSQL doesn't care where the files a= re or how they're transferred, only that the=C2=A0archive_command<= span style=3D"font-size:11.5pt;font-family:"Arial",sans-serif;col= or:#242729">=C2=A0puts them there and the=C2=A0restore_command=C2=A0fetches the required archive.

Streaming replication doesn't have as muc= h lag, as records are sent as they are generated. However, it requires both= master and replica to be online and able to communicate directly. It also = requires the replica to keep up well enough that the master still has on-di= sk copies of the WAL the replica needs, and generally requires you to spend= extra=C2=A0pg_xlog=C2=A0space on retaining extra WAL for= the replica.

=C2=A0

<= div>

Thanks = & Regards,
Shreeyansh DBA Team
www.shreeyansh= .com

=C2=A0

=C2=A0

On Tue, Feb 26, 2019 at 2:56 PM To= m=C3=A1=C5=A1 Uko <uk= o@avast.com> wrote:

Hi all= ,

=C2=A0

We have recently found weird issue with WA= L being still present after recovery (In fact, they are never deleted), thi= s problem is on several version (starting from 9.4 up to 9.6, possibly late= r).

Our setup is this:

-=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 Master = in one DC, with wal shipping to different storage/server

o=C2=A0=C2=A0 Wal shipping v= ia archive_command (pigz and scp=C2=A0 - and we check return codes J )

-=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 Se= veral replicas in different DCs, configured use streaming replication as we= ll as wal restore from that storage with archive_mode =3D 'on'

=

o=C2=A0=C2=A0 = snippet of recovery.conf:

standby_mode =3D 'on'

primary_conninfo =3D 'host=3DX= Y port=3D5432 user=3DAAA password=3DPASSWORD sslmode=3Dverify-full'

restore= _command =3D '~/bin/wal_handler.sh -r -h REMOTE_STORAGE -f %f -p %p -d = LOCATION_ON_REMOTE_STORAGE'

=C2=A0

This = custom script does this:

=C2=A0 [ -f =E2=80=9CPARAM_P/PARAM_F " ] && { ec= ho "Logfile PARAM_P/PARAM_F already exists"; }

=C2=A0 echo "Rest= oring xlog PARAM_F "

=C2=A0 scp -i $SshKey -o PasswordAuthentication=3Dno = -o StrictHostKeyChecking=3Dno REMOTE_STORAGE:LOCATION_ON_REMOTE_STORAGE/PAR= AM_F.gz PARAM_P

=C2=A0 [ $? =3D=3D 0 ] || { echo "Failed to retrieve log P= ARAM_F from REMOTE_STORAGE" && exit 1; }

=C2=A0 unpigz -f PARAM_P/= PARAM_F.gz

=C2=A0 [ $? =3D=3D 0 ] || { echo "Failed to unpack log to PARAM= _P/PARAM_F.gz" && exit 1; }

=C2=A0

When our master became under some massive DML workload (daily bases) so= me of replicas stops using streaming replication and switch to wal restore = (so far good). Message in logs:

=C2=A0

2019-02-25 23:10:03.087 CET, pid: = 2100971, client: , db: , usr: ; LOG:=C2=A0 recovery restart point at CEA9/3= 007188

2019-02-25 23:10:03.087 CET, pid: 2100971, client: , db: , usr: ; DETAIL= :=C2=A0 last completed transaction was at log time 2019-02-25 22:27:14.0595= 33+01

2019-02-25 23:10:47.832 CET, pid: 2100974, clie= nt: , db: , usr: ; FATAL:=C2=A0 could not receive data from WAL stream: ERR= OR:=C2=A0 requested WAL segment 000000020000CEA90000008A has already been r= emoved

=C2=A0

But once they start restoring = wals, they never deletes afterwards. We=E2=80=99ve discovered when there is= restore point, it creates next wal segment in sequence (in pg_xlog dir), w= hich is immediately overwritten by restore.

With overwrite ena= bled logs are full of:

Restoring xlog 000000020000CE3900000029

Restoring xlog 000000020000= CE390000002A

Restoring xlog 000000020000CE390000002B

Restoring xlog 000000020000CE3= 90000002C

Restoring xlog 000000020000CE390000002D

Restoring xlog 000000020000CE3900= 00002E

And once if catches up:

scp: /LOCATION_ON_REMOTE_STORAGE/000000= 020000CE8B00000017.gz: No such file or directory

Failed to retrieve log 0000000= 20000CE8B00000017 from REMOTE_STORAGE

2019-02-25 09:09:28.490 CET, pid: 2090891= , client: , db: , usr: ; LOG:=C2=A0 started streaming WAL from primary at C= E8B/17000000 on timeline 2

=C2=A0

When we di= sabled overriding of WALs during restore we git this error message

2019-02-25 23:10:03= .086 CET, pid: 2100971, client: , db: , usr: ; LOG:=C2=A0 restartpoint comp= lete: wrote 142421 buffers (18.1%); 0 transaction log file(s) added, 68 rem= oved, 0 recycled; write=3D24.086 s, sync=3D0.022 s, total=3D24.424 s; sync = files=3D74, longest=3D0.005 s, average=3D0.000 s; distance=3D1114130 kB, es= timate=3D1114148 kB

2019-02-25 23:10:03.087 CET, pid: 2100971, client: , db: , = usr: ; LOG:=C2=A0 recovery restart point at CEA9/3007188

2019-02-25 23:10:03.08= 7 CET, pid: 2100971, client: , db: , usr: ; DETAIL:=C2=A0 last completed tr= ansaction was at log time 2019-02-25 22:27:14.059533+01

2019-02-25 23:10:36.82= 9 CET, pid: 2100971, client: , db: , usr: ; LOG:=C2=A0 restartpoint startin= g: xlog

Logfile pg_xlog/000000020000CEA90000008A already exists

Restoring xlog 0000= 00020000CEA90000008A

unpigz: abort: write error on pg_xlog/000000020000CEA90000= 008A (Inappropriate ioctl for device)

Which means, wal f= ile is present in this xlog directory

=C2=A0

Thanks= for any advice

=C2=A0

=C2=A0

=C2=A0

=C2=A0

--000000000000682e370582dbacf5--