3

I'm running PostgreSQL 9.3.9, Docker 1.8.2 and Ubuntu 14.04. I have an issue where my hot standby keeps failing with the following error message:

incorrect resource manager data checksum in record at 46F/6A7B6D28

After turning on DEBUG2, this is now the log I see:

2015-10-02 06:56:34.033 UTCDEBUG:  sending write 477/1E9C9990 flush 477/1E9C6700 apply 477/1E9C6700
2015-10-02 06:56:34.078 UTCDEBUG:  sending write 477/1E9C9990 flush 477/1E9C9990 apply 477/1E9C6700
2015-10-02 06:56:34.078 UTCDEBUG:  sendtime 2015-10-02 06:56:34.027356+00 receipttime 2015-10-02 06:56:34.078378+00 replication apply delay 0 ms transfer latency 51 ms
2015-10-02 06:56:34.078 UTCLOG:  incorrect resource manager data checksum in record at 477/1E9C8488
2015-10-02 06:56:34.078 UTCDEBUG:  sending write 477/1E9CE560 flush 477/1E9C9990 apply 477/1E9C8488
2015-10-02 06:56:34.095 UTCDEBUG:  sending write 477/1E9CE560 flush 477/1E9CE560 apply 477/1E9C8488
2015-10-02 06:56:34.095 UTCFATAL:  terminating walreceiver process due to administrator command
2015-10-02 06:56:34.195 UTCDEBUG:  switched WAL source from stream to archive after failure
2015-10-02 06:56:34.195 UTCLOG:  incorrect resource manager data checksum in record at 477/1E9C8488
2015-10-02 06:56:34.195 UTCDEBUG:  switched WAL source from archive to stream after failure
2015-10-02 06:56:34.196 UTCLOG:  incorrect resource manager data checksum in record at 477/1E9C8488
2015-10-02 06:56:39.200 UTCDEBUG:  switched WAL source from stream to archive after failure
2015-10-02 06:56:39.200 UTCDEBUG:  incorrect resource manager data checksum in record at 477/1E9C8488
2015-10-02 06:56:39.200 UTCDEBUG:  switched WAL source from archive to stream after failure

Or this log upon failure:

2015-10-02 00:55:19.838 UTCDEBUG:  sendtime 2015-10-02 00:55:19.836191+00 receipttime 2015-10-02 00:55:19.838961+00 replication apply delay 0 ms transfer latency 2 ms
2015-10-02 00:55:19.839 UTCDEBUG:  sending write 476/E48058A0 flush 476/E4805798 apply 476/E4805798
2015-10-02 00:55:19.878 UTCDEBUG:  attempting to remove WAL segments older than log file 0000000000000472000000FB
2015-10-02 00:55:19.878 UTCDEBUG:  sending write 476/E48058A0 flush 476/E48058A0 apply 476/E4805798
2015-10-02 00:55:19.879 UTCDEBUG:  SlruScanDirectory invoking callback on pg_multixact/offsets/0000
2015-10-02 00:55:19.879 UTCDEBUG:  SlruScanDirectory invoking callback on pg_multixact/offsets/0002
2015-10-02 00:55:19.879 UTCDEBUG:  SlruScanDirectory invoking callback on pg_multixact/offsets/0001
2015-10-02 00:55:19.879 UTCDEBUG:  SlruScanDirectory invoking callback on pg_multixact/members/0000
2015-10-02 00:55:19.879 UTCDEBUG:  SlruScanDirectory invoking callback on pg_multixact/members/0004
2015-10-02 00:55:19.879 UTCDEBUG:  SlruScanDirectory invoking callback on pg_multixact/members/0002
2015-10-02 00:55:19.879 UTCDEBUG:  SlruScanDirectory invoking callback on pg_multixact/members/0001
2015-10-02 00:55:19.879 UTCDEBUG:  SlruScanDirectory invoking callback on pg_multixact/members/0003
2015-10-02 00:55:19.879 UTCDEBUG:  SlruScanDirectory invoking callback on pg_multixact/members/0005
2015-10-02 00:55:19.879 UTCDEBUG:  SlruScanDirectory invoking callback on pg_multixact/offsets/0000
2015-10-02 00:55:19.879 UTCDEBUG:  SlruScanDirectory invoking callback on pg_multixact/offsets/0002
2015-10-02 00:55:19.879 UTCDEBUG:  SlruScanDirectory invoking callback on pg_multixact/offsets/0001
2015-10-02 00:55:19.879 UTCDEBUG:  SlruScanDirectory invoking callback on pg_subtrans/0D6D
2015-10-02 00:55:19.879 UTCDEBUG:  recovery restart point at 476/E410F7E0
2015-10-02 00:55:19.879 UTCDETAIL:  last completed transaction was at log time 2015-10-02 00:55:19.835728+00
2015-10-02 00:55:20.177 UTCDEBUG:  sendtime 2015-10-02 00:55:20.174799+00 receipttime 2015-10-02 00:55:20.177888+00 replication apply delay 0 ms transfer latency 3 ms
2015-10-02 00:55:20.177 UTCDEBUG:  sending write 476/E4806570 flush 476/E48058A0 apply 476/E48058A0
2015-10-02 00:55:20.211 UTCDEBUG:  sending write 476/E4806570 flush 476/E4806570 apply 476/E48058A0
2015-10-02 00:55:20.212 UTCDEBUG:  sendtime 2015-10-02 00:55:20.181054+00 receipttime 2015-10-02 00:55:20.212069+00 replication apply delay 0 ms transfer latency 31 ms
2015-10-02 00:55:20.212 UTCDEBUG:  sending write 476/E4809808 flush 476/E4806570 apply 476/E4806570
2015-10-02 00:55:20.254 UTCDEBUG:  sending write 476/E4809808 flush 476/E4809808 apply 476/E4806570
2015-10-02 00:55:20.254 UTCDEBUG:  sendtime 2015-10-02 00:55:20.182113+00 receipttime 2015-10-02 00:55:20.254256+00 replication apply delay 0 ms transfer latency 72 ms
2015-10-02 00:55:20.254 UTCDEBUG:  sendtime 2015-10-02 00:55:20.195848+00 receipttime 2015-10-02 00:55:20.254304+00 replication apply delay 0 ms transfer latency 58 ms
2015-10-02 00:55:20.254 UTCDEBUG:  sendtime 2015-10-02 00:55:20.226562+00 receipttime 2015-10-02 00:55:20.254326+00 replication apply delay 0 ms transfer latency 27 ms
2015-10-02 00:55:20.254 UTCDEBUG:  sending write 476/E480F1D0 flush 476/E4809808 apply 476/E4809808
2015-10-02 00:55:20.271 UTCDEBUG:  sending write 476/E480F1D0 flush 476/E480F1D0 apply 476/E4809808
2015-10-02 00:55:20.479 UTCDEBUG:  sendtime 2015-10-02 00:55:20.476873+00 receipttime 2015-10-02 00:55:20.479711+00 replication apply delay 0 ms transfer latency 2 ms
2015-10-02 00:55:20.479 UTCDEBUG:  sending write 476/E480F2D8 flush 476/E480F1D0 apply 476/E480F1D0
2015-10-02 00:55:20.534 UTCDEBUG:  sending write 476/E480F2D8 flush 476/E480F2D8 apply 476/E480F1D0
2015-10-02 00:55:20.534 UTCLOG:  record with zero length at 476/E480F1D0
2015-10-02 00:55:20.534 UTCDEBUG:  sendtime 2015-10-02 00:55:20.477442+00 receipttime 2015-10-02 00:55:20.534532+00 replication apply delay 0 ms transfer latency 57 ms
2015-10-02 00:55:20.534 UTCDEBUG:  sendtime 2015-10-02 00:55:20.485564+00 receipttime 2015-10-02 00:55:20.534891+00 replication apply delay 0 ms transfer latency 49 ms
2015-10-02 00:55:20.534 UTCDEBUG:  sending write 476/E4814EF0 flush 476/E480F2D8 apply 476/E480F1D0
2015-10-02 00:55:20.575 UTCDEBUG:  sending write 476/E4814EF0 flush 476/E4814EF0 apply 476/E480F1D0
2015-10-02 00:55:20.575 UTCFATAL:  terminating walreceiver process due to administrator command
2015-10-02 00:55:20.675 UTCDEBUG:  switched WAL source from stream to archive after failure
2015-10-02 00:55:20.675 UTCLOG:  record with zero length at 476/E480F1D0
2015-10-02 00:55:20.675 UTCDEBUG:  switched WAL source from archive to stream after failure

The first time I got this message I read something which said I should regenerate the hot standby from the master. So I rsync'd everything back over and restarted. The hot standby connects to the master over a TINC VPN connection, tt connected successfully and was streaming changes.

It all seemed to be working fine until around 8am. This is when our system starts to get a bit busier. Then all I see in the logs is the above message and the last WAL file on the hotstandby is 000000010000046F0000006A. If I restart the hot standby, it will start catching up with the master, but it also spikes my CPU and brings everything grinding to a halt, and it never seems to catch up anyway.

I have just migrated the DB and hot standby to two new servers, and I am using the simple configuration from the previous servers on these new machines. On the previous servers, the databases were not dockerized, on this they are. I have other dockerized PostgreSQL installations which are running the replication fine, but these servers do not have as high a load as this one. I even replicated from the new master to the old, non-dockerized PostgreSQL server which used to be the main server. The same thing happened here. I had been using the replication between the old master and hot standby just fine over TINC VPN before the migration. So I don't think Docker or TINC are at fault.

Here is the PostgreSQL configuration for both master and hot standby:

listen_addresses          =  '*'
port                      =  5432

max_connections           =  600
shared_buffers            =  8GB
effective_cache_size      =  16GB
work_mem                  =  10MB
maintenance_work_mem      =  1638GB
max_locks_per_transaction =  256

hot_standby       =  on
archive_mode      =  on

wal_level         =  'hot_standby'
max_wal_senders   =  10
wal_keep_segments =  1000     # 80 GB required on pg_xlog

archive_command   =  'true'

And the additional recovery.conf on the hot standby:

standby_mode = 'on'
primary_conninfo = 'host=MY_IP port=MY_PORT user=MY_USER password=MY_PASSWORD'

Any help would be greatly appreciated! I need my hot standby!

Improve this question
6
  • postgresql.org/message-id/[email protected] says it's not necessary the problem itself, might be a symptom only. From what you describe, it's not fully clear, but seemingly the slave is on a not-strong-enough machine.
    – dezso
    Sep 30, 2015 at 10:45
  • Well, the replication was failing to the old live server also. That had been running the application right up until I switched over. So I think it should be able to handle the reduced load of just being the hot standby. I also saw that answer. I don't think it is the case with me since I do not see any new WAL segments being created on the hot standby machine. Perhaps the configuration needs more wal senders or something? I honestly do not know.
    – David Jacob
    Sep 30, 2015 at 10:57
  • AFAIK WAL is not created on a standby - what it would be good for?
    – dezso
    Sep 30, 2015 at 11:54
  • They're created on my hot standbys. And when I get the above error, they are no longer created. I'm not sure of the internal details of what they're good for on the hot standby but they're there for me. :-/
    – David Jacob
    Sep 30, 2015 at 12:02
  • So you get WAL files on a standby which are not present/generated on the master? That sounds interesting.
    – dezso
    Sep 30, 2015 at 12:09

1 Answer 1

Reset to default
3

Ok, I finally figured it out (for the most part)!

The important detail I left out in the question was that I was running PostgreSQL on btrfs and was streaming to a different server with ext4. There seemed to be some race condition during high load periods that caused the data being streamed to be corrupted or read incorrectly. I don't know exactly what. Sometimes it failed after 30 seconds, sometimes 30 minutes.

So last night I shut down the system, backed everything up on a separate HDD, reformated my btrfs partition to ext4, moved everything back and brought the system back up. Once I restarted the live replication it caught up and now 24 hours later it is still perfectly in sync, no errors!

So whatever was going on it was related to the btrfs partition. I've spent this entire week trying to figure this out so I hope this saves someone else some time. :-)

Improve this answer
1
  • I cannot tell at the moment exactly how, but we had also problems with PostgreSQL on btrfs - IIRC everything just freezed intermittently for a short time.
    – dezso
    Oct 5, 2015 at 5:53

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge that you have read and understand our privacy policy and code of conduct.

Not the answer you're looking for? Browse other questions tagged or ask your own question.