Thread: Does my pg_xlog directory look right?

Does my pg_xlog directory look right?

From
Dave Stibrany
Date:
Hey all,

My pg_xlog directory looks kind of messed up. Specifically:

1) There's more segment files than I would expect; 
2) Segment files appear to be out of order with respect to filename and timestamp

System info:
--------------
OS: Ubuntu 14.04 Linux 3.13.0-83-generic
PG Version: 9.3.11
- I have streaming replication set up to one remote, and am archiving to another remote.

postgresql.conf
--------------
wal_level = hot_standby
checkpoint_segments = 32
checkpoint_completion_target = 0.7
archive_mode = on
archive_command = 'rsync -a %p user@host:/dir/to/barman/main/incoming/%f'
wal_keep_segments = 32

Here is an `ls -l` of the xlog directory:

-rw------- 1 postgres postgres       43 Oct 10  2014 00000002.history
-rw------- 1 postgres postgres       43 Oct 10  2014 00000003.history
-rw------- 1 postgres postgres       43 Mar  9  2015 00000004.history
-rw------- 1 postgres postgres       87 Mar 10  2015 00000005.history
-rw------- 1 postgres postgres      131 Aug 16  2015 00000006.history
-rw------- 1 postgres postgres      175 Aug 17  2015 00000007.history
-rw------- 1 postgres postgres      220 Dec 20 09:17 00000008.history
-rw------- 1 postgres postgres      265 Dec 21 01:17 00000009.history
-rw------- 1 postgres postgres      310 Jan 19 01:49 0000000A.history
-rw------- 1 postgres postgres      356 Jan 19 02:37 0000000B.history
-rw------- 1 postgres postgres      402 Feb 22 01:59 0000000C.history
-rw------- 1 postgres postgres      448 Feb 22 02:51 0000000D.history
-rw------- 1 postgres postgres      494 Mar 27 04:10 0000000E.history
-rw------- 1 postgres postgres      540 Mar 27 08:20 0000000F.history
-rw------- 1 postgres postgres      586 Mar 27 22:32 00000010.history
-rw------- 1 postgres postgres      632 Apr  3 23:03 00000011.history
-rw------- 1 postgres postgres      327 May 20 02:21 000000120000037000000089.00000028.backup
-rw------- 1 postgres postgres 16777216 May 20 15:12 00000012000003720000002D
-rw------- 1 postgres postgres 16777216 May 20 15:15 00000012000003720000002E
-rw------- 1 postgres postgres 16777216 May 20 15:18 00000012000003720000002F
-rw------- 1 postgres postgres 16777216 May 20 15:21 000000120000037200000030
-rw------- 1 postgres postgres 16777216 May 20 15:22 000000120000037200000031
-rw------- 1 postgres postgres 16777216 May 20 15:24 000000120000037200000032
-rw------- 1 postgres postgres 16777216 May 20 15:26 000000120000037200000033
-rw------- 1 postgres postgres 16777216 May 20 15:28 000000120000037200000034
-rw------- 1 postgres postgres 16777216 May 20 15:32 000000120000037200000035
-rw------- 1 postgres postgres 16777216 May 20 15:33 000000120000037200000036
-rw------- 1 postgres postgres 16777216 May 20 15:35 000000120000037200000037
-rw------- 1 postgres postgres 16777216 May 20 15:37 000000120000037200000038
-rw------- 1 postgres postgres 16777216 May 20 15:38 000000120000037200000039
-rw------- 1 postgres postgres 16777216 May 20 15:39 00000012000003720000003A
-rw------- 1 postgres postgres 16777216 May 20 15:39 00000012000003720000003B
-rw------- 1 postgres postgres 16777216 May 20 15:39 00000012000003720000003C
-rw------- 1 postgres postgres 16777216 May 20 15:43 00000012000003720000003D
-rw------- 1 postgres postgres 16777216 May 20 15:45 00000012000003720000003E
-rw------- 1 postgres postgres 16777216 May 20 15:48 00000012000003720000003F
-rw------- 1 postgres postgres 16777216 May 20 15:50 000000120000037200000040
-rw------- 1 postgres postgres 16777216 May 20 15:52 000000120000037200000041
-rw------- 1 postgres postgres 16777216 May 20 15:52 000000120000037200000042
-rw------- 1 postgres postgres 16777216 May 20 15:53 000000120000037200000043
-rw------- 1 postgres postgres 16777216 May 20 15:54 000000120000037200000044
-rw------- 1 postgres postgres 16777216 May 20 15:55 000000120000037200000045
-rw------- 1 postgres postgres 16777216 May 20 15:56 000000120000037200000046
-rw------- 1 postgres postgres 16777216 May 20 15:58 000000120000037200000047
-rw------- 1 postgres postgres 16777216 May 20 16:01 000000120000037200000048
-rw------- 1 postgres postgres 16777216 May 20 16:02 000000120000037200000049
-rw------- 1 postgres postgres 16777216 May 20 16:02 00000012000003720000004A
-rw------- 1 postgres postgres 16777216 May 20 16:03 00000012000003720000004B
-rw------- 1 postgres postgres 16777216 May 20 16:03 00000012000003720000004C
-rw------- 1 postgres postgres 16777216 May 20 16:04 00000012000003720000004D
-rw------- 1 postgres postgres 16777216 May 20 16:04 00000012000003720000004E
-rw------- 1 postgres postgres 16777216 May 20 16:04 00000012000003720000004F
-rw------- 1 postgres postgres 16777216 May 20 16:04 000000120000037200000050
-rw------- 1 postgres postgres 16777216 May 20 16:04 000000120000037200000051
-rw------- 1 postgres postgres 16777216 May 20 16:04 000000120000037200000052
-rw------- 1 postgres postgres 16777216 May 20 16:04 000000120000037200000053
-rw------- 1 postgres postgres 16777216 May 20 16:04 000000120000037200000054
-rw------- 1 postgres postgres 16777216 May 20 16:04 000000120000037200000055
-rw------- 1 postgres postgres 16777216 May 20 16:04 000000120000037200000056
-rw------- 1 postgres postgres 16777216 May 20 16:05 000000120000037200000057
-rw------- 1 postgres postgres 16777216 May 20 16:06 000000120000037200000058
-rw------- 1 postgres postgres 16777216 May 20 16:06 000000120000037200000059
-rw------- 1 postgres postgres 16777216 May 20 16:06 00000012000003720000005A
-rw------- 1 postgres postgres 16777216 May 20 16:07 00000012000003720000005B
-rw------- 1 postgres postgres 16777216 May 20 16:07 00000012000003720000005C
-rw------- 1 postgres postgres 16777216 May 20 16:08 00000012000003720000005D
-rw------- 1 postgres postgres 16777216 May 20 14:12 00000012000003720000005E
-rw------- 1 postgres postgres 16777216 May 20 14:12 00000012000003720000005F
-rw------- 1 postgres postgres 16777216 May 20 14:12 000000120000037200000060
-rw------- 1 postgres postgres 16777216 May 20 14:12 000000120000037200000061
-rw------- 1 postgres postgres 16777216 May 20 14:13 000000120000037200000062
-rw------- 1 postgres postgres 16777216 May 20 14:15 000000120000037200000063
-rw------- 1 postgres postgres 16777216 May 20 14:12 000000120000037200000064
-rw------- 1 postgres postgres 16777216 May 20 14:12 000000120000037200000065
-rw------- 1 postgres postgres 16777216 May 20 14:12 000000120000037200000066
-rw------- 1 postgres postgres 16777216 May 20 14:19 000000120000037200000067
-rw------- 1 postgres postgres 16777216 May 20 14:17 000000120000037200000068
-rw------- 1 postgres postgres 16777216 May 20 14:19 000000120000037200000069
-rw------- 1 postgres postgres 16777216 May 20 14:19 00000012000003720000006A
-rw------- 1 postgres postgres 16777216 May 20 14:20 00000012000003720000006B
-rw------- 1 postgres postgres 16777216 May 20 14:20 00000012000003720000006C
-rw------- 1 postgres postgres 16777216 May 20 14:20 00000012000003720000006D
-rw------- 1 postgres postgres 16777216 May 20 14:21 00000012000003720000006E
-rw------- 1 postgres postgres 16777216 May 20 14:21 00000012000003720000006F
-rw------- 1 postgres postgres 16777216 May 20 14:21 000000120000037200000070
-rw------- 1 postgres postgres 16777216 May 20 14:21 000000120000037200000071
-rw------- 1 postgres postgres 16777216 May 20 14:22 000000120000037200000072
-rw------- 1 postgres postgres 16777216 May 20 14:24 000000120000037200000073
-rw------- 1 postgres postgres 16777216 May 20 14:27 000000120000037200000074
-rw------- 1 postgres postgres 16777216 May 20 14:25 000000120000037200000075
-rw------- 1 postgres postgres 16777216 May 20 14:25 000000120000037200000076
-rw------- 1 postgres postgres 16777216 May 20 14:30 000000120000037200000077
-rw------- 1 postgres postgres 16777216 May 20 14:32 000000120000037200000078
-rw------- 1 postgres postgres 16777216 May 20 14:34 000000120000037200000079
-rw------- 1 postgres postgres 16777216 May 20 14:36 00000012000003720000007A
-rw------- 1 postgres postgres 16777216 May 20 14:37 00000012000003720000007B
-rw------- 1 postgres postgres 16777216 May 20 14:40 00000012000003720000007C
-rw------- 1 postgres postgres 16777216 May 20 14:41 00000012000003720000007D
-rw------- 1 postgres postgres 16777216 May 20 14:43 00000012000003720000007E
-rw------- 1 postgres postgres 16777216 May 20 14:43 00000012000003720000007F
-rw------- 1 postgres postgres 16777216 May 20 14:43 000000120000037200000080
-rw------- 1 postgres postgres 16777216 May 20 14:44 000000120000037200000081
-rw------- 1 postgres postgres 16777216 May 20 14:45 000000120000037200000082
-rw------- 1 postgres postgres 16777216 May 20 14:45 000000120000037200000083
-rw------- 1 postgres postgres 16777216 May 20 14:45 000000120000037200000084
-rw------- 1 postgres postgres 16777216 May 20 14:45 000000120000037200000085
-rw------- 1 postgres postgres 16777216 May 20 14:50 000000120000037200000086
-rw------- 1 postgres postgres 16777216 May 20 14:51 000000120000037200000087
-rw------- 1 postgres postgres 16777216 May 20 14:55 000000120000037200000088
-rw------- 1 postgres postgres 16777216 May 20 14:49 000000120000037200000089
-rw------- 1 postgres postgres 16777216 May 20 15:06 00000012000003720000008A
-rw------- 1 postgres postgres 16777216 May 20 14:59 00000012000003720000008B
-rw------- 1 postgres postgres 16777216 May 20 15:10 00000012000003720000008C
-rw------- 1 postgres postgres 16777216 May 20 15:02 00000012000003720000008D
-rw------- 1 postgres postgres 16777216 May 20 15:08 00000012000003720000008E
-rw------- 1 postgres postgres      678 Apr  3 23:56 00000012.history
drwx------ 2 postgres postgres     4096 May 20 16:07 archive_status

There are 98 WAL segments in the directory currently.

From the documentation, I understand that the number of WAL files can go as high as (3 * checkpoint_segments + 1) segment files, which would be 97 in my case, but I seem to be consistently at this number or even higher (sometimes over 110 files) and I don't think I've ever seen the directory smaller than ~97 segment files.

Regarding the ordering of segments, my understanding is that segment 0000012000003720000008B would be written to after 00000012000003720000008A, but the timestamps (14:59 and 15:06, respectively) appear to show otherwise. There are several cases like this. Does this mean that 00000012000003720000008A has newer WAL records than 00000012000003720000008B??

It may be that there's nothing wrong here and this behaviour is natural. If that is the case, I'd still like to better understand this phenomena.

Thanks!

Dave Stibrany

Re: Does my pg_xlog directory look right?

From
Tom Lane
Date:
Dave Stibrany <dstibrany@gmail.com> writes:
> There are 98 WAL segments in the directory currently.

> From the documentation, I understand that the number of WAL files can go as
> high as (3 * checkpoint_segments + 1) segment files, which would be 97 in
> my case, but I seem to be consistently at this number or even higher
> (sometimes over 110 files) and I don't think I've ever seen the directory
> smaller than ~97 segment files.

I don't believe there's any aggressive attempt to remove segment files
after transient peak usage (what happens to them instead is explained
below).  If you had many times the expected number of segments, I'd be
worried, but these numbers sound pretty normal to me.

> Regarding the ordering of segments, my understanding is that segment
> 0000012000003720000008B would be written to after 00000012000003720000008A,
> but the timestamps (14:59 and 15:06, respectively) appear to show
> otherwise. There are several cases like this. Does this mean that
> 00000012000003720000008A has newer WAL records than
> 00000012000003720000008B??

No, it probably means that neither one has been written at all yet.
Typically, when a WAL segment is deemed no longer needed, the file isn't
physically removed but is merely renamed into place as a future segment.
The idea is to reduce unnecessary filesystem work as we create and delete
WAL segments.  You could check this out if you have pg_xlogdump at hand,
by seeing whether the WAL file's first page header claims to belong to the
segment indicated by the file name, or to some much-older segment.

            regards, tom lane


Re: Does my pg_xlog directory look right?

From
Alvaro Herrera
Date:
Tom Lane wrote:

> No, it probably means that neither one has been written at all yet.
> Typically, when a WAL segment is deemed no longer needed, the file isn't
> physically removed but is merely renamed into place as a future segment.
> The idea is to reduce unnecessary filesystem work as we create and delete
> WAL segments.  You could check this out if you have pg_xlogdump at hand,
> by seeing whether the WAL file's first page header claims to belong to the
> segment indicated by the file name, or to some much-older segment.

This may be a good time to point out that pg_xlogdump fails completely
when a file's contents does not match the file name, with no indication
about what a better file name would be.  In other words, if a file has
been recycled and not written to yet under the new name, it doesn't tell
you anything useful.  This is pretty annoying.

--
Álvaro Herrera                http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services


Re: Does my pg_xlog directory look right?

From
dstibrany@gmail.com
Date:
Thanks for the response and the pg_xlogdump tip.

Dave

> On May 20, 2016, at 2:35 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>
> Dave Stibrany <dstibrany@gmail.com> writes:
>> There are 98 WAL segments in the directory currently.
>
>> From the documentation, I understand that the number of WAL files can go as
>> high as (3 * checkpoint_segments + 1) segment files, which would be 97 in
>> my case, but I seem to be consistently at this number or even higher
>> (sometimes over 110 files) and I don't think I've ever seen the directory
>> smaller than ~97 segment files.
>
> I don't believe there's any aggressive attempt to remove segment files
> after transient peak usage (what happens to them instead is explained
> below).  If you had many times the expected number of segments, I'd be
> worried, but these numbers sound pretty normal to me.
>
>> Regarding the ordering of segments, my understanding is that segment
>> 0000012000003720000008B would be written to after 00000012000003720000008A,
>> but the timestamps (14:59 and 15:06, respectively) appear to show
>> otherwise. There are several cases like this. Does this mean that
>> 00000012000003720000008A has newer WAL records than
>> 00000012000003720000008B??
>
> No, it probably means that neither one has been written at all yet.
> Typically, when a WAL segment is deemed no longer needed, the file isn't
> physically removed but is merely renamed into place as a future segment.
> The idea is to reduce unnecessary filesystem work as we create and delete
> WAL segments.  You could check this out if you have pg_xlogdump at hand,
> by seeing whether the WAL file's first page header claims to belong to the
> segment indicated by the file name, or to some much-older segment.
>
>            regards, tom lane