Re: Automatic checkpoints not running on streaming slave

Hey Everyone,
With my investigations into our streaming slave having a continuously
growing pg_xlog directory (
http://archives.postgresql.org/pgsql-general/2012-08/msg00124.php) I think
I've hit upon what's going on.

Using pg_controldata I've found that our streaming slave hasn't run a
checkpoint for over 2 weeks. Or I suppose more specifically hasn't
completed a checkpoint in 2 weeks. The server was synced and started up
on the 27th so there was 4 days where it looks like the checkpoints where
happening correctly. I have attempted a manual checkpoint on the slave with
no effect (it returns instantly to me in the client but the pg_controldata
never shows any change). On my testing system the automatic checkpoint
runs successfully every 5 minutes and removes the wal logs it no longer
needs to get to that restartpoint.

pg_control version number: 903
Catalog version number: 201105231
Database system identifier: 5680552055141687295
Database cluster state: in archive recovery
*pg_control last modified: Tue 31 Jul 2012 12:43:59 PM MDT*
Latest checkpoint location: 178/5344C730
Prior checkpoint location: 178/4E8C1938
Latest checkpoint's REDO location: 178/4FC5E8E0
Latest checkpoint's TimeLineID: 10
Latest checkpoint's NextXID: 0/291590955
Latest checkpoint's NextOID: 67986575
Latest checkpoint's NextMultiXactId: 122827
Latest checkpoint's NextMultiOffset: 296304
Latest checkpoint's oldestXID: 64713442
Latest checkpoint's oldestXID's DB: 16408
Latest checkpoint's oldestActiveXID: 260568245
*Time of latest checkpoint: Tue 31 Jul 2012 12:35:53 PM MDT*
Minimum recovery ending location: 199/EC6C0BA0
Backup start location: 0/0
Current wal_level setting: hot_standby
Current max_connections setting: 600
Current max_prepared_xacts setting: 0
Current max_locks_per_xact setting: 256
Maximum data alignment: 8
Database block size: 8192
Blocks per segment of large relation: 131072
WAL block size: 8192
Bytes per WAL segment: 16777216
Maximum length of identifiers: 64
Maximum columns in an index: 32
Maximum size of a TOAST chunk: 1996
Date/time type storage: 64-bit integers
Float4 argument passing: by value
Float8 argument passing: by value

Compared to our master

pg_control version number: 903
Catalog version number: 201105231
Database system identifier: 5680552055141687295
Database cluster state: in production
pg_control last modified: Mon 13 Aug 2012 11:35:35 AM MDT
Latest checkpoint location: 199/EC5E4218
Prior checkpoint location: 199/EBEFB120
Latest checkpoint's REDO location: 199/EC033110
Latest checkpoint's TimeLineID: 10
Latest checkpoint's NextXID: 0/291590955
Latest checkpoint's NextOID: 75744399
Latest checkpoint's NextMultiXactId: 122877
Latest checkpoint's NextMultiOffset: 296404
Latest checkpoint's oldestXID: 91782681
Latest checkpoint's oldestXID's DB: 16408
Latest checkpoint's oldestActiveXID: 291583665
Time of latest checkpoint: Mon 13 Aug 2012 11:31:35 AM MDT
Minimum recovery ending location: 0/0
Backup start location: 0/0
Current wal_level setting: hot_standby
Current max_connections setting: 600
Current max_prepared_xacts setting: 0
Current max_locks_per_xact setting: 256
Maximum data alignment: 8
Database block size: 8192
Blocks per segment of large relation: 131072
WAL block size: 8192
Bytes per WAL segment: 16777216
Maximum length of identifiers: 64
Maximum columns in an index: 32
Maximum size of a TOAST chunk: 1996
Date/time type storage: 64-bit integers
Float4 argument passing: by value
Float8 argument passing: by value

Which appears to correctly be running it's automated checkpoints every 5
minutes. Our checkpoint configuration is currently:

checkpoint_completion_target | 0.8 |
Time spent flushing dirty buffers during checkpoint, as fraction of
checkpoint interval.
checkpoint_segments | 128 |
Sets the maximum distance in log segments between automatic WAL checkpoints.
checkpoint_timeout | 5min |
Sets the maximum time between automatic WAL checkpoints.
checkpoint_warning | 30s |
Enables warnings if checkpoint segments are filled more frequently than
this.

The settings are the same on both the slave and the master.

We don't currently have log_checkpoints enabled on our slave (I'm going to
make the change and schedule a resync for this evening to see if the log
reveals anything)

I've done some googling and can't really see anything that will allow me to
see the status of the checkpoints in progress currently.

Just for more info we're running postgres 9.1.1 build from source on 2 X64
Cent OS5.8 machines. The total size of our /data directory is currently
94.5 gigs which is currently all in 1 DB with 2193 schemas (each of which
has around 1300 objects).. From the what I'm able to pull of the slave
there isn't constant IO happening like the checkpoints are running and just
thrashing the disks. If there's any other information that may be helpful
I can pull it.

Anyone have any suggestions as to next roads to take (besides turning on
the checkpoint logging and trying to see what's going on)?

Thanks

Since the streaming slave has come back up it appears that we've now hit
the same issue again. With the checkpoint logging on I now have some more
information.

Everything was working as expected for the first 2 days (with a 5 minute
auto checkpoint time the log contains the expected 288 restart points).
And if I manually requested a checkpoint the expected log entry would be
entered

LOG: restartpoint starting: immediate force wait

I noticed on our monitoring system that the xlog storage was beginning to
grow on the slave I went to check the log file and the last checkpoint that
happened was started at 8:25 and finished at 8:29 (our .8 completion_target)

2012-08-16 08:25:20.004 MDT [24039]: [2565-1] LOG: restartpoint starting:
time
2012-08-16 08:29:20.240 MDT [24039]: [2566-1] LOG: restartpoint complete:
wrote 6943 buffers (0.7%); 0 transaction log file(s) added, 0 removed, 7
recycled; write=240.135 s, sync=0.098 s, total=240.236 s; sync files=1488,
longest=0.025 s, average=0.000 s
2012-08-16 08:29:20.240 MDT [24039]: [2567-1] LOG: recovery restart point
at 1A0/8B8DF820
2012-08-16 08:29:20.240 MDT [24039]: [2568-1] DETAIL: last completed
transaction was at log time 2012-08-16 08:29:19.94531-06

Now if I manually try to trigger a checkpoint no log message shows up.

So it seems like whatever runs the checkpoints has frozen up and is no
longer responding.

The only information in the log on the slave are the checkpoints from the
midnight log rotation to the last record at 8:29, and a couple slow query
logs from a nightly dataload to our data wharehouse that runs overnight.
There are no regular querying happening against the slave other then the
DW load which finishes around 4 AM.

The logging itself does appear to still be working as if I send a invalid
query against the system it does show up in the log.

I check dmesg and /var/log/messages and there are no IO errors or any other
messages.

Any one have a idea of where I should go from here?

Thanks

On Mon, Aug 13, 2012 at 12:14 PM, Mike Roest <mike(dot)roest(at)replicon(dot)com>wrote:

> Hey Everyone,
> With my investigations into our streaming slave having a continuously
> growing pg_xlog directory (
> http://archives.postgresql.org/pgsql-general/2012-08/msg00124.php) I
> think I've hit upon what's going on.
>
>
> Using pg_controldata I've found that our streaming slave hasn't run a
> checkpoint for over 2 weeks. Or I suppose more specifically hasn't
> completed a checkpoint in 2 weeks. The server was synced and started up
> on the 27th so there was 4 days where it looks like the checkpoints where
> happening correctly. I have attempted a manual checkpoint on the slave with
> no effect (it returns instantly to me in the client but the pg_controldata
> never shows any change). On my testing system the automatic checkpoint
> runs successfully every 5 minutes and removes the wal logs it no longer
> needs to get to that restartpoint.
>
> pg_control version number: 903
> Catalog version number: 201105231
> Database system identifier: 5680552055141687295
> Database cluster state: in archive recovery
> *pg_control last modified: Tue 31 Jul 2012 12:43:59 PM MDT*
> Latest checkpoint location: 178/5344C730
> Prior checkpoint location: 178/4E8C1938
> Latest checkpoint's REDO location: 178/4FC5E8E0
> Latest checkpoint's TimeLineID: 10
> Latest checkpoint's NextXID: 0/291590955
> Latest checkpoint's NextOID: 67986575
> Latest checkpoint's NextMultiXactId: 122827
> Latest checkpoint's NextMultiOffset: 296304
> Latest checkpoint's oldestXID: 64713442
> Latest checkpoint's oldestXID's DB: 16408
> Latest checkpoint's oldestActiveXID: 260568245
> *Time of latest checkpoint: Tue 31 Jul 2012 12:35:53 PM MDT*
> Minimum recovery ending location: 199/EC6C0BA0
> Backup start location: 0/0
> Current wal_level setting: hot_standby
> Current max_connections setting: 600
> Current max_prepared_xacts setting: 0
> Current max_locks_per_xact setting: 256
> Maximum data alignment: 8
> Database block size: 8192
> Blocks per segment of large relation: 131072
> WAL block size: 8192
> Bytes per WAL segment: 16777216
> Maximum length of identifiers: 64
> Maximum columns in an index: 32
> Maximum size of a TOAST chunk: 1996
> Date/time type storage: 64-bit integers
> Float4 argument passing: by value
> Float8 argument passing: by value
>
> Compared to our master
>
> pg_control version number: 903
> Catalog version number: 201105231
> Database system identifier: 5680552055141687295
> Database cluster state: in production
> pg_control last modified: Mon 13 Aug 2012 11:35:35 AM MDT
> Latest checkpoint location: 199/EC5E4218
> Prior checkpoint location: 199/EBEFB120
> Latest checkpoint's REDO location: 199/EC033110
> Latest checkpoint's TimeLineID: 10
> Latest checkpoint's NextXID: 0/291590955
> Latest checkpoint's NextOID: 75744399
> Latest checkpoint's NextMultiXactId: 122877
> Latest checkpoint's NextMultiOffset: 296404
> Latest checkpoint's oldestXID: 91782681
> Latest checkpoint's oldestXID's DB: 16408
> Latest checkpoint's oldestActiveXID: 291583665
> Time of latest checkpoint: Mon 13 Aug 2012 11:31:35 AM MDT
> Minimum recovery ending location: 0/0
> Backup start location: 0/0
> Current wal_level setting: hot_standby
> Current max_connections setting: 600
> Current max_prepared_xacts setting: 0
> Current max_locks_per_xact setting: 256
> Maximum data alignment: 8
> Database block size: 8192
> Blocks per segment of large relation: 131072
> WAL block size: 8192
> Bytes per WAL segment: 16777216
> Maximum length of identifiers: 64
> Maximum columns in an index: 32
> Maximum size of a TOAST chunk: 1996
> Date/time type storage: 64-bit integers
> Float4 argument passing: by value
> Float8 argument passing: by value
>
>
> Which appears to correctly be running it's automated checkpoints every 5
> minutes. Our checkpoint configuration is currently:
>
> checkpoint_completion_target | 0.8 |
> Time spent flushing dirty buffers during checkpoint, as fraction of
> checkpoint interval.
> checkpoint_segments | 128 |
> Sets the maximum distance in log segments between automatic WAL checkpoints.
> checkpoint_timeout | 5min |
> Sets the maximum time between automatic WAL checkpoints.
> checkpoint_warning | 30s |
> Enables warnings if checkpoint segments are filled more frequently than
> this.
>
> The settings are the same on both the slave and the master.
>
> We don't currently have log_checkpoints enabled on our slave (I'm going to
> make the change and schedule a resync for this evening to see if the log
> reveals anything)
>
> I've done some googling and can't really see anything that will allow me
> to see the status of the checkpoints in progress currently.
>
> Just for more info we're running postgres 9.1.1 build from source on 2 X64
> Cent OS5.8 machines. The total size of our /data directory is currently
> 94.5 gigs which is currently all in 1 DB with 2193 schemas (each of which
> has around 1300 objects).. From the what I'm able to pull of the slave
> there isn't constant IO happening like the checkpoints are running and just
> thrashing the disks. If there's any other information that may be helpful
> I can pull it.
>
> Anyone have any suggestions as to next roads to take (besides turning on
> the checkpoint logging and trying to see what's going on)?
>
>
> Thanks
>