PostgreSQL replication lag without obvious bottleneck

Question

We have PostgreSQL 14.2 running on Ubuntu 18.04 with physical (asynchronous) replication set up. The standby is on an AWS EC2 instance with an EBS volume. When I test inserting data as fast as possible replication lag keeps growing and I'm unsure what the bottleneck is. In the latest case, I ran a transaction that inserted a lot of data, finishing over 2 days ago, with no other activity since, and the standby is still trying to catch up - replication lag hit a peak of 75GB and is now down to 29GB.

When I run repmgr node status multiple times the last received LSN is not changing, only the last replayed LSN:

 Last received LSN: 2DE/86000000
 Last replayed LSN: 2D7/A7B75278
repmgr node status
...
 Last received LSN: 2DE/86000000
 Last replayed LSN: 2D7/B35D0328

I can also see this directly with a query:

select application_name, client_addr, state, pg_wal_lsn_diff(pg_current_wal_insert_lsn(), replay_lsn) from pg_stat_replication;

This returns state=streaming and pg_wal_lsn_diff=~29G.

nethogs also shows virtually no network activity. This implies to me that there is no problem in receiving data from the primary and the bottleneck is in replaying the changes, but I'm not sure what it is. CPU usage is ~20% (constant). Memory usage is 10 GB out of 15.5 GB. iotop shows reads of 10-20 MB/s and writes of 10-15 MB/s (sometimes with peaks of up to 70 MB/s for "actual disk write").

I've already tried changing the EBS volume type from gp2 with 1500 IOPS to gp3 with 3000 IOPS and this didn't seem to make any difference. How do I figure out what the bottleneck is here and fix it?

The log file on the standby doesn't have any errors that I can see. There are many messages like this:

2022年03月07日 06:16:15.814 UTC [30320] LOG: restartpoint complete: wrote 345 buffers (2.1%); 0 WAL file(s) added, 27 removed, 0 recycled; write=269.658 s, sync=0.532 s, total=270.456 s; sync files=19, longest=0.167 s, average=0.028 s; distance=443765 kB, estimate=531639 kB
2022年03月07日 06:16:15.814 UTC [30320] LOG: recovery restart point at 2D6/C8237E70
2022年03月07日 06:16:15.814 UTC [30320] DETAIL: Last completed transaction was at log time 2022年03月04日 23:47:59.635064+00.

The latest is

2022年03月07日 08:27:09.653 UTC [30320] DETAIL: Last completed transaction was at log time 2022年03月05日 00:02:47.410576+00.

so it is still over 2 days behind!

• jjanes: 3000IOPS * 8kB = 23.43 MB/s. You report reads of 10-20 MB/s. And of course you also need to do writes. It sounds like you have no IOPS to spare.
• jjanes: "Memory usage is 10 GB out of 15.5 GB" Who is using that? Is the rest cached files or totally unused?

Answer 1

I maxed out the EBS volume specs to 16000 IOPS and 1000 MB/s throughput and it coped OK. I also doubled the EC2 instance size (from t3a.xlarge to t3a.2xlarge) to be sure, but I think it was the EBS volume speed, most likely IOPS, as jjanes pointed out in a comment.

I did not fully test this, because we redesigned our application to write much less and now the original specs (t3a.xlarge, 3000 IOPS, 125 MB/s throughput) seem to cope OK.

Answer 2

You are measuring the difference to replay_lsn. If there is a delay, that doesn't mean that there is a lag in transferring WAL; for that, you'd have to use write_lsn or flush_lsn.

If there is a lag in replay, but not in WAL transfer, that means that replay is delayed by a replication conflict. You can change that behavior by tuning max_standby_streaming_delay.

• EM0: write_lsn and flush_lsn are both "2DE/86000000", i.e. the value reported by repmgr as "Last received LSN". max_standby_streaming_delay is at the default 30 seconds, but we're not running any queries on the standby. Nothing was happening on the cluster except that one big data insert (on the primary, obviously).
• Laurenz Albe: Perhaps a look at the standby's log file could tell you why it is not replaying.
• EM0: Well, it is replaying, just too slowly. It doesn't have any errors. I edited into the question the messages I see in the log.