Обсуждение: [ADMIN] Strange times in WAL files in archive directory (9.3)

Поиск
Список
Период
Сортировка

[ADMIN] Strange times in WAL files in archive directory (9.3)

От
Achilleas Mantzios
Дата:
Hello,
we are running PostgreSQL 9.3 on a new VM running Linux 3.16.0-4-amd64 #1 SMP, Debian 8.6, and we setup WAL archiving
yesterday.We were planing to keep a window of 15 days worth of WAL files, so we  
thought of writing a script to delete files older than 15 days. The settings used were rather common :
archive_mode = on
archive_command = '/usr/bin/scp %p sma:/smadb/pgsql/pitr/%f'
archive_timeout=240
However, this morning, to my surprise I saw this by doing ls on the archive directory :
# ls -l /smadb/pgsql/pitr/ | less
total 12680296
-rw------- 1 postgres postgres 16777216 Jan 24 03:44 000000020000070100000000
-rw------- 1 postgres postgres 16777216 Jan 24 03:50 000000020000070100000001
-rw------- 1 postgres postgres 16777216 Jan 24 03:54 000000020000070100000002
-rw------- 1 postgres postgres 16777216 Jan 24 04:00 000000020000070100000003
-rw------- 1 postgres postgres 16777216 Jan 24 04:00 000000020000070100000004
-rw------- 1 postgres postgres 16777216 Jan 24 04:04 000000020000070100000005
-rw------- 1 postgres postgres 16777216 Jan 24 04:09 000000020000070100000006
-rw------- 1 postgres postgres 16777216 Jan 24 04:14 000000020000070100000007
-rw------- 1 postgres postgres 16777216 Jan 24 04:20 000000020000070100000008
-rw------- 1 postgres postgres 16777216 Jan 24 04:20 000000020000070100000009
-rw------- 1 postgres postgres 16777216 Jan 24 04:25 00000002000007010000000A
-rw------- 1 postgres postgres 16777216 Jan 24 04:29 00000002000007010000000B
-rw------- 1 postgres postgres 16777216 Jan 24 04:34 00000002000007010000000C
-rw------- 1 postgres postgres 16777216 Jan 24 04:39 00000002000007010000000D
-rw------- 1 postgres postgres 16777216 Jan 24 04:39 00000002000007010000000E
-rw------- 1 postgres postgres 16777216 Jan 24 04:44 00000002000007010000000F
...........
-rw------- 1 postgres postgres 16777216 Jan 24 09:48 0000000200000701000000EF
-rw------- 1 postgres postgres 16777216 Jan 24 09:48 0000000200000701000000F0
-rw------- 1 postgres postgres 16777216 Jan 24 09:48 0000000200000701000000F1  <------
-rw------- 1 postgres postgres 16777216 Jan 23 13:04 0000000200000701000000F2 <------ time jumps
-rw------- 1 postgres postgres 16777216 Jan 23 13:05 0000000200000701000000F3
-rw------- 1 postgres postgres 16777216 Jan 23 13:06 0000000200000701000000F4

So IMHO either the naming of the WAL filename got damaged somehow or the one of the servers got wrong time or something
Imiss. "Jan 23 13:04" is indeed the time that we started the server for WAL  
archiving.
By sorting by time I get :
ls -ltr /smadb/pgsql/pitr/ | less
-rw------- 1 postgres postgres 16777216 Jan 23 13:04 0000000200000701000000F2
-rw------- 1 postgres postgres 16777216 Jan 23 13:05 0000000200000701000000F3
-rw------- 1 postgres postgres 16777216 Jan 23 13:06 0000000200000701000000F4
-rw------- 1 postgres postgres 16777216 Jan 23 13:07 0000000200000701000000F5
-rw------- 1 postgres postgres 16777216 Jan 23 13:08 0000000200000701000000F6
-rw------- 1 postgres postgres 16777216 Jan 23 13:09 0000000200000701000000F7
-rw------- 1 postgres postgres 16777216 Jan 23 13:09 0000000200000701000000F8
-rw------- 1 postgres postgres 16777216 Jan 23 13:10 0000000200000701000000F9
-rw------- 1 postgres postgres 16777216 Jan 23 13:11 0000000200000701000000FA
-rw------- 1 postgres postgres 16777216 Jan 23 13:12 0000000200000701000000FB
-rw------- 1 postgres postgres 16777216 Jan 23 13:13 0000000200000701000000FC
........
-rw------- 1 postgres postgres 16777216 Jan 24 03:15 0000000200000702000000F9
-rw------- 1 postgres postgres 16777216 Jan 24 03:19 0000000200000702000000FA
-rw------- 1 postgres postgres 16777216 Jan 24 03:23 0000000200000702000000FB
-rw------- 1 postgres postgres 16777216 Jan 24 03:27 0000000200000702000000FC
-rw------- 1 postgres postgres 16777216 Jan 24 03:31 0000000200000702000000FD
-rw------- 1 postgres postgres 16777216 Jan 24 03:35 0000000200000702000000FE
-rw------- 1 postgres postgres 16777216 Jan 24 03:39 0000000200000702000000FF
-rw------- 1 postgres postgres 16777216 Jan 24 03:43 000000020000070300000000
-rw------- 1 postgres postgres 16777216 Jan 24 03:44 000000020000070100000000 <----- problem begins
-rw------- 1 postgres postgres 16777216 Jan 24 03:47 000000020000070300000001
-rw------- 1 postgres postgres 16777216 Jan 24 03:50 000000020000070100000001
-rw------- 1 postgres postgres 16777216 Jan 24 03:51 000000020000070300000002
-rw------- 1 postgres postgres 16777216 Jan 24 03:54 000000020000070100000002
........ (same pattern goes on 0000000200000703 mixing with 0000000200000701 )
-rw------- 1 postgres postgres 16777216 Jan 24 09:42 0000000200000701000000EE
-rw------- 1 postgres postgres 16777216 Jan 24 09:45 0000000200000703000000EF
-rw------- 1 postgres postgres 16777216 Jan 24 09:47 0000000200000703000000F0
-rw------- 1 postgres postgres 16777216 Jan 24 09:48 0000000200000703000000F1
-rw------- 1 postgres postgres 16777216 Jan 24 09:48 0000000200000701000000EF
-rw------- 1 postgres postgres 16777216 Jan 24 09:48 0000000200000701000000F0
-rw------- 1 postgres postgres 16777216 Jan 24 09:48 0000000200000701000000F1 <----- problem ends
-rw------- 1 postgres postgres 16777216 Jan 24 09:50 0000000200000703000000F2
-rw------- 1 postgres postgres 16777216 Jan 24 09:52 0000000200000703000000F3
-rw------- 1 postgres postgres 16777216 Jan 24 09:56 0000000200000703000000F4

Any thoughts about any explanation on this?

--
Achilleas Mantzios
IT DEV Lead
IT DEPT
Dynacom Tankers Mgmt



Re: [ADMIN] Strange times in WAL files in archive directory (9.3)

От
Achilleas Mantzios
Дата:
On 24/01/2017 11:12, Achilleas Mantzios wrote:
> Hello,
> we are running PostgreSQL 9.3 on a new VM running Linux 3.16.0-4-amd64 #1 SMP, Debian 8.6, and we setup WAL archiving
yesterday.We were planing to keep a window of 15 days worth of WAL files, so we  
> thought of writing a script to delete files older than 15 days. The settings used were rather common :
> archive_mode = on
> archive_command = '/usr/bin/scp %p sma:/smadb/pgsql/pitr/%f'
> archive_timeout=240
> However, this morning, to my surprise I saw this by doing ls on the archive directory :
> # ls -l /smadb/pgsql/pitr/ | less
> total 12680296
> -rw------- 1 postgres postgres 16777216 Jan 24 03:44 000000020000070100000000
> -rw------- 1 postgres postgres 16777216 Jan 24 03:50 000000020000070100000001
> -rw------- 1 postgres postgres 16777216 Jan 24 03:54 000000020000070100000002
> -rw------- 1 postgres postgres 16777216 Jan 24 04:00 000000020000070100000003
> -rw------- 1 postgres postgres 16777216 Jan 24 04:00 000000020000070100000004
> -rw------- 1 postgres postgres 16777216 Jan 24 04:04 000000020000070100000005
> -rw------- 1 postgres postgres 16777216 Jan 24 04:09 000000020000070100000006
> -rw------- 1 postgres postgres 16777216 Jan 24 04:14 000000020000070100000007
> -rw------- 1 postgres postgres 16777216 Jan 24 04:20 000000020000070100000008
> -rw------- 1 postgres postgres 16777216 Jan 24 04:20 000000020000070100000009
> -rw------- 1 postgres postgres 16777216 Jan 24 04:25 00000002000007010000000A
> -rw------- 1 postgres postgres 16777216 Jan 24 04:29 00000002000007010000000B
> -rw------- 1 postgres postgres 16777216 Jan 24 04:34 00000002000007010000000C
> -rw------- 1 postgres postgres 16777216 Jan 24 04:39 00000002000007010000000D
> -rw------- 1 postgres postgres 16777216 Jan 24 04:39 00000002000007010000000E
> -rw------- 1 postgres postgres 16777216 Jan 24 04:44 00000002000007010000000F
> ...........
> -rw------- 1 postgres postgres 16777216 Jan 24 09:48 0000000200000701000000EF
> -rw------- 1 postgres postgres 16777216 Jan 24 09:48 0000000200000701000000F0
> -rw------- 1 postgres postgres 16777216 Jan 24 09:48 0000000200000701000000F1  <------
> -rw------- 1 postgres postgres 16777216 Jan 23 13:04 0000000200000701000000F2 <------ time jumps
> -rw------- 1 postgres postgres 16777216 Jan 23 13:05 0000000200000701000000F3
> -rw------- 1 postgres postgres 16777216 Jan 23 13:06 0000000200000701000000F4
>
> So IMHO either the naming of the WAL filename got damaged somehow or the one of the servers got wrong time or
somethingI miss. "Jan 23 13:04" is indeed the time that we started the server for WAL  
> archiving.
> By sorting by time I get :
> ls -ltr /smadb/pgsql/pitr/ | less
> -rw------- 1 postgres postgres 16777216 Jan 23 13:04 0000000200000701000000F2
> -rw------- 1 postgres postgres 16777216 Jan 23 13:05 0000000200000701000000F3
> -rw------- 1 postgres postgres 16777216 Jan 23 13:06 0000000200000701000000F4
> -rw------- 1 postgres postgres 16777216 Jan 23 13:07 0000000200000701000000F5
> -rw------- 1 postgres postgres 16777216 Jan 23 13:08 0000000200000701000000F6
> -rw------- 1 postgres postgres 16777216 Jan 23 13:09 0000000200000701000000F7
> -rw------- 1 postgres postgres 16777216 Jan 23 13:09 0000000200000701000000F8
> -rw------- 1 postgres postgres 16777216 Jan 23 13:10 0000000200000701000000F9
> -rw------- 1 postgres postgres 16777216 Jan 23 13:11 0000000200000701000000FA
> -rw------- 1 postgres postgres 16777216 Jan 23 13:12 0000000200000701000000FB
> -rw------- 1 postgres postgres 16777216 Jan 23 13:13 0000000200000701000000FC
> ........
> -rw------- 1 postgres postgres 16777216 Jan 24 03:15 0000000200000702000000F9
> -rw------- 1 postgres postgres 16777216 Jan 24 03:19 0000000200000702000000FA
> -rw------- 1 postgres postgres 16777216 Jan 24 03:23 0000000200000702000000FB
> -rw------- 1 postgres postgres 16777216 Jan 24 03:27 0000000200000702000000FC
> -rw------- 1 postgres postgres 16777216 Jan 24 03:31 0000000200000702000000FD
> -rw------- 1 postgres postgres 16777216 Jan 24 03:35 0000000200000702000000FE
> -rw------- 1 postgres postgres 16777216 Jan 24 03:39 0000000200000702000000FF
> -rw------- 1 postgres postgres 16777216 Jan 24 03:43 000000020000070300000000
> -rw------- 1 postgres postgres 16777216 Jan 24 03:44 000000020000070100000000 <----- problem begins
> -rw------- 1 postgres postgres 16777216 Jan 24 03:47 000000020000070300000001
> -rw------- 1 postgres postgres 16777216 Jan 24 03:50 000000020000070100000001
> -rw------- 1 postgres postgres 16777216 Jan 24 03:51 000000020000070300000002
> -rw------- 1 postgres postgres 16777216 Jan 24 03:54 000000020000070100000002
> ........ (same pattern goes on 0000000200000703 mixing with 0000000200000701 )
> -rw------- 1 postgres postgres 16777216 Jan 24 09:42 0000000200000701000000EE
> -rw------- 1 postgres postgres 16777216 Jan 24 09:45 0000000200000703000000EF
> -rw------- 1 postgres postgres 16777216 Jan 24 09:47 0000000200000703000000F0
> -rw------- 1 postgres postgres 16777216 Jan 24 09:48 0000000200000703000000F1
> -rw------- 1 postgres postgres 16777216 Jan 24 09:48 0000000200000701000000EF
> -rw------- 1 postgres postgres 16777216 Jan 24 09:48 0000000200000701000000F0
> -rw------- 1 postgres postgres 16777216 Jan 24 09:48 0000000200000701000000F1 <----- problem ends
> -rw------- 1 postgres postgres 16777216 Jan 24 09:50 0000000200000703000000F2
> -rw------- 1 postgres postgres 16777216 Jan 24 09:52 0000000200000703000000F3
> -rw------- 1 postgres postgres 16777216 Jan 24 09:56 0000000200000703000000F4
>
> Any thoughts about any explanation on this?
>
By scrolling up the terminal on the database server (cause the said file is gone now from pg_xlog) I saw this :
$ ls -ltr ~/data/pg_xlog/0000000200000701000000F0
-rw------- 1 postgres postgres 16777216 Jan 23 13:01 /var/lib/pgsql/data/pg_xlog/0000000200000701000000F0
$ md5sum ~/data/pg_xlog/0000000200000701000000F0
8ce1917c86d3c9e41455ec13659c2689 /var/lib/pgsql/data/pg_xlog/0000000200000701000000F0

In the archive's host I see this :
# ls -ltr /smadb/pgsql/pitr/0000000200000701000000F0
-rw------- 1 postgres postgres 16777216 Jan 24 09:48 /smadb/pgsql/pitr/0000000200000701000000F0
# md5sum /smadb/pgsql/pitr/0000000200000701000000F0
8ce1917c86d3c9e41455ec13659c2689 /smadb/pgsql/pitr/0000000200000701000000F0

Same file, different mod times, so, this makes me think that maybe there was some flushing that the postgresql server
did,prior to deleting or recycling some old WAL files. Also I see this : 
# ls -ltr /smadb/pgsql/pitr/0000000200000701000000*
-rw------- 1 postgres postgres 16777216 Jan 23 13:04 /smadb/pgsql/pitr/0000000200000701000000F2
-rw------- 1 postgres postgres 16777216 Jan 23 13:05 /smadb/pgsql/pitr/0000000200000701000000F3
-rw------- 1 postgres postgres 16777216 Jan 23 13:06 /smadb/pgsql/pitr/0000000200000701000000F4
-rw------- 1 postgres postgres 16777216 Jan 23 13:07 /smadb/pgsql/pitr/0000000200000701000000F5
-rw------- 1 postgres postgres 16777216 Jan 23 13:08 /smadb/pgsql/pitr/0000000200000701000000F6
-rw------- 1 postgres postgres 16777216 Jan 23 13:09 /smadb/pgsql/pitr/0000000200000701000000F7
-rw------- 1 postgres postgres 16777216 Jan 23 13:09 /smadb/pgsql/pitr/0000000200000701000000F8
-rw------- 1 postgres postgres 16777216 Jan 23 13:10 /smadb/pgsql/pitr/0000000200000701000000F9
-rw------- 1 postgres postgres 16777216 Jan 23 13:11 /smadb/pgsql/pitr/0000000200000701000000FA
-rw------- 1 postgres postgres 16777216 Jan 23 13:12 /smadb/pgsql/pitr/0000000200000701000000FB
-rw------- 1 postgres postgres 16777216 Jan 23 13:13 /smadb/pgsql/pitr/0000000200000701000000FC
-rw------- 1 postgres postgres 16777216 Jan 23 13:14 /smadb/pgsql/pitr/0000000200000701000000FD
-rw------- 1 postgres postgres 16777216 Jan 23 13:15 /smadb/pgsql/pitr/0000000200000701000000FE
-rw------- 1 postgres postgres 16777216 Jan 23 13:16 /smadb/pgsql/pitr/0000000200000701000000FF
-rw------- 1 postgres postgres 16777216 Jan 24 03:44 /smadb/pgsql/pitr/000000020000070100000000 <---- time jump
-rw------- 1 postgres postgres 16777216 Jan 24 03:50 /smadb/pgsql/pitr/000000020000070100000001
-rw------- 1 postgres postgres 16777216 Jan 24 03:54 /smadb/pgsql/pitr/000000020000070100000002
-rw------- 1 postgres postgres 16777216 Jan 24 04:00 /smadb/pgsql/pitr/000000020000070100000003
-rw------- 1 postgres postgres 16777216 Jan 24 04:00 /smadb/pgsql/pitr/000000020000070100000004
......
-rw------- 1 postgres postgres 16777216 Jan 24 09:42 /smadb/pgsql/pitr/0000000200000701000000EE
-rw------- 1 postgres postgres 16777216 Jan 24 09:48 /smadb/pgsql/pitr/0000000200000701000000EF
-rw------- 1 postgres postgres 16777216 Jan 24 09:48 /smadb/pgsql/pitr/0000000200000701000000F0
-rw------- 1 postgres postgres 16777216 Jan 24 09:48 /smadb/pgsql/pitr/0000000200000701000000F1

So this makes me believe that all the files before 0000000200000701000000F2 were present before WAL archiving was
setup.So I want to ask : 

1) Do you find this behavior normal?
2) From now on, can we assume a monotonic relation between file names and creation times in order to base our
maintenancescripts on this? 

--
Achilleas Mantzios
IT DEV Lead
IT DEPT
Dynacom Tankers Mgmt



Re: [ADMIN] Strange times in WAL files in archive directory (9.3)

От
Tom Lane
Дата:
Achilleas Mantzios <achill@matrix.gatewaynet.com> writes:
> 1) Do you find this behavior normal?

It's normal operation.  Once a WAL file is not needed anymore, it's
typically renamed into place to be a future WAL file; that's cheaper
than deleting the file and creating/filling a new one.  So those ones
that have older timestamps do not contain useful data right this instant,
but they're ready to accept data once the write pointer advances to them.

> 2) From now on, can we assume a monotonic relation between file names and creation times in order to base our
maintenancescripts on this? 

I wouldn't.  You risk deleting a file just as it starts to be used.
You could possibly look into pg_control to see the current LSN and
avoid touching any files >= that point, but of course this complicates
the maintenance logic quite a bit.

The larger issue here is that you're confusing the function of an archive
area with that of the active WAL directory.  The server will prune what is
in the active WAL directory and does not want your help.  In an archive
directory, I'd expect the files to have monotonic timestamps corresponding
to the times you copied them over to the archive, so you could rely on
the timestamp sequence there.

            regards, tom lane


Re: [ADMIN] Strange times in WAL files in archive directory (9.3)

От
David Steele
Дата:
Hi Achilleas,

On 1/24/17 8:29 AM, Tom Lane wrote:
> Achilleas Mantzios <achill@matrix.gatewaynet.com> writes:
>
>> 2) From now on, can we assume a monotonic relation between file names and creation times in order to base our
maintenancescripts on this? 
>
> I wouldn't.  You risk deleting a file just as it starts to be used.
> You could possibly look into pg_control to see the current LSN and
> avoid touching any files >= that point, but of course this complicates
> the maintenance logic quite a bit.
>
> The larger issue here is that you're confusing the function of an archive
> area with that of the active WAL directory.  The server will prune what is
> in the active WAL directory and does not want your help.  In an archive
> directory, I'd expect the files to have monotonic timestamps corresponding
> to the times you copied them over to the archive, so you could rely on
> the timestamp sequence there.

Agreed, that should work.

However, this just the beginning of the complexities you will encounter
when dealing with WAL archiving and expiration.  You should consider
using a mature third-party solution like pgBackRest or Barman.

--
-David
david@pgmasters.net


Re: [ADMIN] Strange times in WAL files in archive directory (9.3)

От
Achilleas Mantzios
Дата:
Hi Tom,

On 24/01/2017 15:29, Tom Lane wrote:
> The larger issue here is that you're confusing the function of an archive area with that of the active WAL directory.
Theserver will prune what is in the active WAL directory and does not want your  
> help. In an archive directory, I'd expect the files to have monotonic timestamps corresponding to the times you
copiedthem over to the archive, so you could rely on the timestamp sequence there.  
> regards, tom lane
I would be silly to mess around with pg_xlog. I was talking about the archive directory. *There* is where I noticed the
inconsistencies.In my second post in this thread I used pg_xlog to show the  
difference in timestamp of the same md5-wise files between the two systems (pg_xlog vs archive dir).

--
Achilleas Mantzios
IT DEV Lead
IT DEPT
Dynacom Tankers Mgmt



Re: [ADMIN] Strange times in WAL files in archive directory (9.3)

От
Tom Lane
Дата:
Achilleas Mantzios <achill@matrix.gatewaynet.com> writes:
> On 24/01/2017 15:29, Tom Lane wrote:
>> The larger issue here is that you're confusing the function of an archive area with that of the active WAL
directory.The server will prune what is in the active WAL directory and does not want your  
>> help. In an archive directory, I'd expect the files to have monotonic timestamps corresponding to the times you
copiedthem over to the archive, so you could rely on the timestamp sequence there.  

> I would be silly to mess around with pg_xlog. I was talking about the
> archive directory. *There* is where I noticed the inconsistencies.

If you copied the files to the archive directory when the server told you
they were ready, it should be impossible for them to have non-sequential
timestamps.  I'm wondering if you tried to short-circuit that, perhaps
by hard-linking them instead of copying.  That won't work at all, since
the server will reuse (overwrite) the files once it thinks you've
copied them.

            regards, tom lane


Re: [ADMIN] Strange times in WAL files in archive directory (9.3)

От
Achilleas Mantzios
Дата:
On 24/01/2017 16:14, Tom Lane wrote:
Achilleas Mantzios <achill@matrix.gatewaynet.com> writes:
On 24/01/2017 15:29, Tom Lane wrote:
The larger issue here is that you're confusing the function of an archive area with that of the active WAL directory. The server will prune what is in the active WAL directory and does not want your 
help. In an archive directory, I'd expect the files to have monotonic timestamps corresponding to the times you copied them over to the archive, so you could rely on the timestamp sequence there. 
I would be silly to mess around with pg_xlog. I was talking about the
archive directory. *There* is where I noticed the inconsistencies.
If you copied the files to the archive directory when the server told you
they were ready, it should be impossible for them to have non-sequential
timestamps.  I'm wondering if you tried to short-circuit that, perhaps
by hard-linking them instead of copying.  That won't work at all, since
the server will reuse (overwrite) the files once it thinks you've
copied them.
I provided the archive_command in the 1st post. The copy is against another host (called sma in the command) :
archive_command = '/usr/bin/scp %p sma:/smadb/pgsql/pitr/%f'
I didn't do any scp by hand. My suspicion is that PostreSQL (before recycling them) just flushed via the archive command those files which were created before PITR was setup, i.e. before the server was restarted to begin WAL archiving. The timestamps observed on the sequence of files make me believe so.
First thing this morning, by seeing that, made me skeptical of whether the obvious assumption on the monotonicity between filenames/tiemstamps is valid. However for the last 7 hours (after the last file with the *oldish* filenames was written) I have not witnessed anything weird.
		regards, tom lane




-- 
Achilleas Mantzios
IT DEV Lead
IT DEPT
Dynacom Tankers Mgmt

Re: [ADMIN] Strange times in WAL files in archive directory (9.3)

От
Stephen Frost
Дата:
Greetings,

* Achilleas Mantzios (achill@matrix.gatewaynet.com) wrote:
> I provided the archive_command in the 1st post. The copy is against another host (called sma in the command) :
> archive_command = '/usr/bin/scp %p sma:/smadb/pgsql/pitr/%f'

Note that this is not a recommended archive command- there is no
guarantee that the copied WAL files are sync'd to disk on the 'sma' host
and you could end up losing, potentially, a significant amount of your
WAL on a failure.

It's also, sadly, quite slow, with no way to be parallelized (PG will
not start a new archive_command until the prior one completes, meaning
that you could end up with a large backlog of un-archived WAL if the
archive_command can't keep up, potentially leading to an out-of-space
situation on your WAL filesystem, leading to a PANIC and crash).

There's also no compression with the proposed approach (in transit or at
rest).

Some of this is fixable with SSH (using ControlMaster, adding
compression options, though that would only compress in transit, not on
disk; if you wanted on-disk compression then you'd have to re-compress
it again), but not all of it (you aren't going to get scp to fsync the
WAL on the remote side, at least not by itself), but as noted by David
already, using a third-party solution which has addressed all of these
issues is really a better option than hand-rolling your own system.

Thanks!

Stephen

Вложения

Re: [ADMIN] Strange times in WAL files in archive directory (9.3)

От
Achilleas Mantzios
Дата:
On 24/01/2017 16:55, Stephen Frost wrote:
> Greetings,
>
> * Achilleas Mantzios (achill@matrix.gatewaynet.com) wrote:
>> I provided the archive_command in the 1st post. The copy is against another host (called sma in the command) :
>> archive_command = '/usr/bin/scp %p sma:/smadb/pgsql/pitr/%f'
> Note that this is not a recommended archive command- there is no
> guarantee that the copied WAL files are sync'd to disk on the 'sma' host
> and you could end up losing, potentially, a significant amount of your
> WAL on a failure.
I had changed that already to
/usr/bin/rsync -a --ignore-existing %p sma:/smadb/pgsql/pitr/%f

So you say that scp does not perform a sync on the destination file? So that in case of a remote crash it might return
0while the file isn't written? 
>
> It's also, sadly, quite slow, with no way to be parallelized (PG will
> not start a new archive_command until the prior one completes, meaning
> that you could end up with a large backlog of un-archived WAL if the
> archive_command can't keep up, potentially leading to an out-of-space
> situation on your WAL filesystem, leading to a PANIC and crash).
>
> There's also no compression with the proposed approach (in transit or at
> rest).
>
> Some of this is fixable with SSH (using ControlMaster, adding
> compression options, though that would only compress in transit, not on
> disk; if you wanted on-disk compression then you'd have to re-compress
> it again), but not all of it (you aren't going to get scp to fsync the
> WAL on the remote side, at least not by itself), but as noted by David
> already, using a third-party solution which has addressed all of these
> issues is really a better option than hand-rolling your own system.
Thanks for the suggestions. We have been using a wal archiving + base backups + streaming replication combination for
years,so I guess we'll be alright for the time being. Point is that we recently  
moved to a cloud environment and we have to "port" our traditional operations to the utilities/tools provided by the
cloudprovider. 

Anyway, if there is any theory or confirmation on my assumptions for the main question of this thread?
> Thanks!
>
> Stephen


--
Achilleas Mantzios
IT DEV Lead
IT DEPT
Dynacom Tankers Mgmt



Re: [ADMIN] Strange times in WAL files in archive directory (9.3)

От
Stephen Frost
Дата:
Greetings,

* Achilleas Mantzios (achill@matrix.gatewaynet.com) wrote:
> On 24/01/2017 16:55, Stephen Frost wrote:
> >* Achilleas Mantzios (achill@matrix.gatewaynet.com) wrote:
> >>I provided the archive_command in the 1st post. The copy is against another host (called sma in the command) :
> >>archive_command = '/usr/bin/scp %p sma:/smadb/pgsql/pitr/%f'
> >Note that this is not a recommended archive command- there is no
> >guarantee that the copied WAL files are sync'd to disk on the 'sma' host
> >and you could end up losing, potentially, a significant amount of your
> >WAL on a failure.
> I had changed that already to
> /usr/bin/rsync -a --ignore-existing %p sma:/smadb/pgsql/pitr/%f

--ignore-existing is actually a *bad* idea, really.  There can be cases
where PG will end up calling archive_command on the same file, but in
those cases you should really be checking that the two WAL files are
IDENTICAL, otherwise you may have a misconfigured system and are pushing
the WAL for two different PG systems to the same directory.

> So you say that scp does not perform a sync on the destination file? So that in case of a remote crash it might
return0 while the file isn't written? 

Yes, if the remote system crashes right after rsync (or scp) has
returned, the WAL file may not have been sync'd to reliable storage and
will be lost.

> Thanks for the suggestions. We have been using a wal archiving +
> base backups + streaming replication combination for years, so I
> guess we'll be alright for the time being. Point is that we recently
> moved to a cloud environment and we have to "port" our traditional
> operations to the utilities/tools provided by the cloud provider.

I would not go on the assumption that since it's been working that it
won't ever fail in an unfortunate way.

Also, always, always, always test your backups.  All of them, ideally,
otherwise they may not work when you need them most.

> Anyway, if there is any theory or confirmation on my assumptions for the main question of this thread?

At first blush, I'd guess that someone else put those files there or
that the time changed on one of the systems involved.

Thanks!

Stephen

Вложения

Re: [ADMIN] Strange times in WAL files in archive directory (9.3)

От
Achilleas Mantzios
Дата:
On 24/01/2017 17:55, Stephen Frost wrote:
> Greetings,
>
> * Achilleas Mantzios (achill@matrix.gatewaynet.com) wrote:
>> On 24/01/2017 16:55, Stephen Frost wrote:
>>> * Achilleas Mantzios (achill@matrix.gatewaynet.com) wrote:
>>>> I provided the archive_command in the 1st post. The copy is against another host (called sma in the command) :
>>>> archive_command = '/usr/bin/scp %p sma:/smadb/pgsql/pitr/%f'
>>> Note that this is not a recommended archive command- there is no
>>> guarantee that the copied WAL files are sync'd to disk on the 'sma' host
>>> and you could end up losing, potentially, a significant amount of your
>>> WAL on a failure.
>> I had changed that already to
>> /usr/bin/rsync -a --ignore-existing %p sma:/smadb/pgsql/pitr/%f
> --ignore-existing is actually a *bad* idea, really.  There can be cases
> where PG will end up calling archive_command on the same file, but in
> those cases you should really be checking that the two WAL files are
> IDENTICAL, otherwise you may have a misconfigured system and are pushing
> the WAL for two different PG systems to the same directory.
>
>> So you say that scp does not perform a sync on the destination file? So that in case of a remote crash it might
return0 while the file isn't written? 
> Yes, if the remote system crashes right after rsync (or scp) has
> returned, the WAL file may not have been sync'd to reliable storage and
> will be lost.
>
>> Thanks for the suggestions. We have been using a wal archiving +
>> base backups + streaming replication combination for years, so I
>> guess we'll be alright for the time being. Point is that we recently
>> moved to a cloud environment and we have to "port" our traditional
>> operations to the utilities/tools provided by the cloud provider.
> I would not go on the assumption that since it's been working that it
> won't ever fail in an unfortunate way.
>
> Also, always, always, always test your backups.  All of them, ideally,
> otherwise they may not work when you need them most.
>
>> Anyway, if there is any theory or confirmation on my assumptions for the main question of this thread?
> At first blush, I'd guess that someone else put those files there or
> that the time changed on one of the systems involved.
No one else worked on this, and ntp has been running correctly for both systems. This was my first guess as well but
no.
I guess PostgreSQL just flushed them to the archive before deleting/renaming them. Does it make any sense?
>
> Thanks!
>
> Stephen


--
Achilleas Mantzios
IT DEV Lead
IT DEPT
Dynacom Tankers Mgmt



Re: [ADMIN] Strange times in WAL files in archive directory (9.3)

От
Achilleas Mantzios
Дата:
Just an observation on this. By looking at the timestamps of the files I see a pattern :

-rw------- 1 postgres postgres 16777216 Jan 23 13:04 0000000200000701000000F2
-rw------- 1 postgres postgres 16777216 Jan 23 13:05 0000000200000701000000F3
-rw------- 1 postgres postgres 16777216 Jan 23 13:06 0000000200000701000000F4
-rw------- 1 postgres postgres 16777216 Jan 23 13:07 0000000200000701000000F5
-rw------- 1 postgres postgres 16777216 Jan 23 13:08 0000000200000701000000F6
-rw------- 1 postgres postgres 16777216 Jan 23 13:09 0000000200000701000000F7
.....
-rw------- 1 postgres postgres 16777216 Jan 24 03:07 0000000200000702000000F7
-rw------- 1 postgres postgres 16777216 Jan 24 03:11 0000000200000702000000F8
-rw------- 1 postgres postgres 16777216 Jan 24 03:15 0000000200000702000000F9
-rw------- 1 postgres postgres 16777216 Jan 24 03:19 0000000200000702000000FA
-rw------- 1 postgres postgres 16777216 Jan 24 03:23 0000000200000702000000FB
-rw------- 1 postgres postgres 16777216 Jan 24 03:27 0000000200000702000000FC
-rw------- 1 postgres postgres 16777216 Jan 24 03:31 0000000200000702000000FD
-rw------- 1 postgres postgres 16777216 Jan 24 03:35 0000000200000702000000FE
-rw------- 1 postgres postgres 16777216 Jan 24 03:39 0000000200000702000000FF
-rw------- 1 postgres postgres 16777216 Jan 24 03:43 000000020000070300000000
-rw------- 1 postgres postgres 16777216 Jan 24 03:44 000000020000070100000000  <---- logno >> 32 == 701 file appears,
nowstarts the pattern 
-rw------- 1 postgres postgres 16777216 Jan 24 03:47 000000020000070300000001
-rw------- 1 postgres postgres 16777216 Jan 24 03:50 000000020000070100000001
-rw------- 1 postgres postgres 16777216 Jan 24 03:51 000000020000070300000002
-rw------- 1 postgres postgres 16777216 Jan 24 03:54 000000020000070100000002
-rw------- 1 postgres postgres 16777216 Jan 24 03:55 000000020000070300000003
-rw------- 1 postgres postgres 16777216 Jan 24 03:59 000000020000070300000004
-rw------- 1 postgres postgres 16777216 Jan 24 04:00 000000020000070100000003
-rw------- 1 postgres postgres 16777216 Jan 24 04:00 000000020000070100000004
-rw------- 1 postgres postgres 16777216 Jan 24 04:03 000000020000070300000005
-rw------- 1 postgres postgres 16777216 Jan 24 04:04 000000020000070100000005
-rw------- 1 postgres postgres 16777216 Jan 24 04:07 000000020000070300000006
-rw------- 1 postgres postgres 16777216 Jan 24 04:09 000000020000070100000006
-rw------- 1 postgres postgres 16777216 Jan 24 04:11 000000020000070300000007
-rw------- 1 postgres postgres 16777216 Jan 24 04:14 000000020000070100000007
-rw------- 1 postgres postgres 16777216 Jan 24 04:15 000000020000070300000008
-rw------- 1 postgres postgres 16777216 Jan 24 04:19 000000020000070300000009
-rw------- 1 postgres postgres 16777216 Jan 24 04:20 000000020000070100000008
-rw------- 1 postgres postgres 16777216 Jan 24 04:20 000000020000070100000009
-rw------- 1 postgres postgres 16777216 Jan 24 04:23 00000002000007030000000A
......
-rw------- 1 postgres postgres 16777216 Jan 24 04:43 00000002000007030000000F
-rw------- 1 postgres postgres 16777216 Jan 24 04:44 00000002000007010000000F
-rw------- 1 postgres postgres 16777216 Jan 24 04:47 000000020000070300000010
-rw------- 1 postgres postgres 16777216 Jan 24 04:50 000000020000070100000010
-rw------- 1 postgres postgres 16777216 Jan 24 04:51 000000020000070300000011
-rw------- 1 postgres postgres 16777216 Jan 24 04:55 000000020000070300000012
-rw------- 1 postgres postgres 16777216 Jan 24 04:56 000000020000070100000011
-rw------- 1 postgres postgres 16777216 Jan 24 04:56 000000020000070100000012
-rw------- 1 postgres postgres 16777216 Jan 24 04:59 000000020000070300000013
-rw------- 1 postgres postgres 16777216 Jan 24 04:59 000000020000070100000013
-rw------- 1 postgres postgres 16777216 Jan 24 05:01 000000020000070300000014
-rw------- 1 postgres postgres 16777216 Jan 24 05:02 000000020000070300000015
-rw------- 1 postgres postgres 16777216 Jan 24 05:04 000000020000070300000016
-rw------- 1 postgres postgres 16777216 Jan 24 05:05 000000020000070300000017
-rw------- 1 postgres postgres 16777216 Jan 24 05:07 000000020000070300000018
-rw------- 1 postgres postgres 16777216 Jan 24 05:08 000000020000070300000019
-rw------- 1 postgres postgres 16777216 Jan 24 05:08 000000020000070100000015
-rw------- 1 postgres postgres 16777216 Jan 24 05:08 000000020000070100000014
-rw------- 1 postgres postgres 16777216 Jan 24 05:08 000000020000070100000016
-rw------- 1 postgres postgres 16777216 Jan 24 05:08 000000020000070100000017
-rw------- 1 postgres postgres 16777216 Jan 24 05:08 000000020000070100000018
-rw------- 1 postgres postgres 16777216 Jan 24 05:08 000000020000070100000019
-rw------- 1 postgres postgres 16777216 Jan 24 05:09 00000002000007030000001A
-rw------- 1 postgres postgres 16777216 Jan 24 05:09 00000002000007030000001B
-rw------- 1 postgres postgres 16777216 Jan 24 05:10 00000002000007030000001C
-rw------- 1 postgres postgres 16777216 Jan 24 05:10 00000002000007030000001D
-rw------- 1 postgres postgres 16777216 Jan 24 05:10 00000002000007030000001E
-rw------- 1 postgres postgres 16777216 Jan 24 05:11 00000002000007030000001F
-rw------- 1 postgres postgres 16777216 Jan 24 05:11 000000020000070300000020
-rw------- 1 postgres postgres 16777216 Jan 24 05:12 000000020000070300000021
-rw------- 1 postgres postgres 16777216 Jan 24 05:12 000000020000070300000022
-rw------- 1 postgres postgres 16777216 Jan 24 05:12 00000002000007010000001E
-rw------- 1 postgres postgres 16777216 Jan 24 05:12 00000002000007010000001A
-rw------- 1 postgres postgres 16777216 Jan 24 05:12 00000002000007010000001B
-rw------- 1 postgres postgres 16777216 Jan 24 05:12 00000002000007010000001C
-rw------- 1 postgres postgres 16777216 Jan 24 05:12 00000002000007010000001D
-rw------- 1 postgres postgres 16777216 Jan 24 05:12 00000002000007010000001F
-rw------- 1 postgres postgres 16777216 Jan 24 05:12 000000020000070100000020
-rw------- 1 postgres postgres 16777216 Jan 24 05:12 000000020000070100000021
-rw------- 1 postgres postgres 16777216 Jan 24 05:12 000000020000070100000022

it is pretty obvious that the current logno % (2^32) = 703, and for every 703-named file that is archived, wal archiver
triesto also archive all the unarchived files with filename of logno % (2^32) -  
2 = 701.
I should have kept a snapshot of data/pg_xlog/archive_status/ as well, unfortunately I didn't. I didn't have time to
lookthoroughly into the sources or even try to reproduce via gdb. Hope this helps  
a little bit.
I want to clarify once more than the pattern stopped after the last unarchived 701-file :0000000200000701000000F1 was
archived. 0000000200000701000000F2 was already archived, actually was the very  
first file to be archived as shown at the top of this mail.
:
-rw------- 1 postgres postgres 16777216 Jan 24 09:45 0000000200000703000000EF
-rw------- 1 postgres postgres 16777216 Jan 24 09:47 0000000200000703000000F0
-rw------- 1 postgres postgres 16777216 Jan 24 09:48 0000000200000703000000F1
-rw------- 1 postgres postgres 16777216 Jan 24 09:48 0000000200000701000000EF
-rw------- 1 postgres postgres 16777216 Jan 24 09:48 0000000200000701000000F0
-rw------- 1 postgres postgres 16777216 Jan 24 09:48 0000000200000701000000F1  <-- here
-rw------- 1 postgres postgres 16777216 Jan 24 09:50 0000000200000703000000F2
-rw------- 1 postgres postgres 16777216 Jan 24 09:52 0000000200000703000000F3
-rw------- 1 postgres postgres 16777216 Jan 24 09:56 0000000200000703000000F4
-rw------- 1 postgres postgres 16777216 Jan 24 09:59 0000000200000703000000F5
-rw------- 1 postgres postgres 16777216 Jan 24 10:03 0000000200000703000000F6
-rw------- 1 postgres postgres 16777216 Jan 24 10:07 0000000200000703000000F7
-rw------- 1 postgres postgres 16777216 Jan 24 10:11 0000000200000703000000F8
-rw------- 1 postgres postgres 16777216 Jan 24 10:14 0000000200000703000000F9
-rw------- 1 postgres postgres 16777216 Jan 24 10:17 0000000200000703000000FA
-rw------- 1 postgres postgres 16777216 Jan 24 10:20 0000000200000703000000FB



--
Achilleas Mantzios
IT DEV Lead
IT DEPT
Dynacom Tankers Mgmt