Using Postgresql logical replication, how do you know that the subscriber is caught up?

Question

Postgresql has some interesting monitoring tools for monitoring the new logical replication system's progress, but I don't really understand them. The two tools I'm aware of are:

pg_stat_replication

and it's sibling:

pg_stat_subscription

I've read the documentation for these, but they don't say how to know if a replica is actually synced, and interpreting these tables didn't seem obvious to me. Can anybody explain?

Answer 1

I used replication on Postgres 10 last year and I had the same problem understanding how to monitor the process, as documentation is not clear enough. Anyway, I'll try to give you an example to check if monitoring is going on.

On the publisher side there are few things you can check:

• pg_catalog.pg_publication;
• pg_catalog.pg_publication_tables;
• pg_current_wal_lsn();

I'll create a publication "test_publication" with two tables: t_1 and t_2. I won't cover the prerequisites (user, roles and so on).

test_logical_replication=# create publication test_publication for table t_1, t_2;  
CREATE PUBLICATION  
test_logical_replication=# select * from pg_catalog.pg_publication;  
pubname      | pubowner | puballtables | pubinsert | pubupdate | pubdelete  
-----------------+----------+--------------+-----------+-----------+-----------  
test_publication |       10 | f            | t         | t         | t  
(1 row) 

test_logical_replication=# select * from pg_publication_tables;    
    pubname      | schemaname | tablename  
    ------------------+------------+-----------  
     test_publication | public     | t_1  
     test_publication | public     | t_2  
    (2 rows)  

On the subscriber side:

test_logical_replication_subscriber=# create subscription test_subscription CONNECTION 'dbname=test_logical_replication host=XXX user=repuser' PUBLICATION test_publication;  
NOTICE:  created replication slot "test_subscription" on publisher   
CREATE SUBSCRIPTION 

Interesting information is in the table pg_catalog.pg_stat_subscription.
Here the important columns are:

• received_lsn: Last write-ahead log location received .
• last_msg_send_time: send time of last message received from the publisher.
• last_msg_receipt_time: Receipt time of last message received from the publisher.
• latest_end_lsn: Last write-ahead log location reported to the publisher.
• latest_end_time: Time of last write-ahead log location reported to the publisher.

You have to check these columns to catch what is happening.
First, check if the two databases are in sync;

Publisher side:

test_logical_replication=> select pg_current_wal_lsn();  
 pg_current_wal_lsn  
--------------------  
 0/8EB83768     

This shows the location in the WAL file where we are now, before starting a new insert.

We can check on the subscriber that at this moment the two database are in sync, because the value returned by pg_current_wal_lsn() on the publisher matches the value in the columns received_lsn and latest_end_lsn on the subscriber:

test_logical_replication_subscriber=# select received_lsn, latest_end_lsn from pg_catalog.pg_stat_subscription;  

received_lsn    | latest_end_lsn  
----------------+------------------     
 0/8EB83768     | 0/8EB83768        

I'll add 4000 rows to table t_1, and see what happens on the publisher:

test_logical_replication=> insert into t_1 select id+1, txt||'--BB' from t_1;  
INSERT 0 4000  


test_logical_replication=> select pg_current_wal_lsn();  
 pg_current_wal_lsn
--------------------
 0/8EC4B9D0             <<< this value in increasing
(1 row)

test_logical_replication=> select pg_current_wal_lsn();
 pg_current_wal_lsn
--------------------
 0/8EC4DE78             <<< this value in increasing
(1 row)

test_logical_replication=> select pg_current_wal_lsn();
 pg_current_wal_lsn
--------------------
 0/8EC4DEB0             <<< this value in increasing
(1 row) 

test_logical_replication=> select pg_current_wal_lsn();
 pg_current_wal_lsn
--------------------
 0/8EC4DEB0            <<< same value, WAL sending has finished
(1 row)  

Let's look how pg_catalog.pg_stat_subscription values change during replication on the subscriber:

test_logical_replication_subscriber=# select received_lsn,last_msg_send_time,last_msg_receipt_time,latest_end_lsn,latest_end_time from pg_catalog.pg_stat_subscription;
 received_lsn |      last_msg_send_time       |    last_msg_receipt_time     | latest_end_lsn |        latest_end_time  
--------------+-------------------------------+------------------------------+----------------+-------------------------------
 0/8EC4B9D0   | 2018-12-17 11:39:56.014564+01 | 2018-12-17 11:39:56.07322+01 | 0/8EC4B9D0     | 2018-12-17 11:39:56.014564+01
(1 row)  

test_logical_replication_subscriber=# select received_lsn,last_msg_send_time,last_msg_receipt_time,latest_end_lsn,latest_end_time from pg_catalog.pg_stat_subscription;
 received_lsn |      last_msg_send_time       |     last_msg_receipt_time     | latest_end_lsn |        latest_end_time
--------------+-------------------------------+-------------------------------+----------------+-------------------------------
 0/8EC4BA08   | 2018-12-17 11:39:56.737101+01 | 2018-12-17 11:39:56.736303+01 | 0/8EC4BA08     | 2018-12-17 11:39:56.737101+01  
(1 row)  

test_logical_replication_subscriber=# select received_lsn,last_msg_send_time,last_msg_receipt_time,latest_end_lsn,latest_end_time from pg_catalog.pg_stat_subscription;
 received_lsn |      last_msg_send_time       |     last_msg_receipt_time     | latest_end_lsn |        latest_end_time
--------------+-------------------------------+-------------------------------+----------------+-------------------------------
 0/8EC4DE78   | 2018-12-17 11:40:04.184765+01 | 2018-12-17 11:40:04.183937+01 | 0/8EC4DE78     | 2018-12-17 11:40:04.184765+01
(1 row)  

 test_logical_replication_subscriber=# select received_lsn,last_msg_send_time,last_msg_receipt_time,latest_end_lsn,latest_end_time from pg_catalog.pg_stat_subscription;
 received_lsn |      last_msg_send_time       |   last_msg_receipt_time    | latest_end_lsn |        latest_end_time
--------------+-------------------------------+----------------------------+----------------+-------------------------------
 0/8EC4DEB0   | 2018-12-17 11:40:17.153797+01 | 2018-12-17 11:40:17.153+01 | 0/8EC4DEB0     | 2018-12-17 11:40:17.153797+01
(1 row)   

As you can see, on the subscriber the four columns shows how WAL is arriving from the publisher and how it is applied. The difference in time in the columns last_msg_send_time and last_msg_receipt_time can give information about the lag between the publisher and subscriber.
In this case, the two servers are on different subnets in the same data centre.

Take into account that the two servers I used are test servers and ARE NOT perfect in sync between them. (The subscriber server has not an NTP server configured at all).

Answer 2

On publisher(provider) side check output of this SQL(for version>=PG10) to get lags:

select   pid, client_addr, state, sync_state,  
         pg_wal_lsn_diff(sent_lsn, write_lsn) as write_lag,  
         pg_wal_lsn_diff(sent_lsn, flush_lsn) as flush_lag,  
         pg_wal_lsn_diff(sent_lsn, replay_lsn) as replay_lag
from pg_stat_replication;

And if you're using pglogical extension, you can check replication status of your tables. If following query returns tables having problems (for exp. consistency problem) on subscriber side:

SELECT sub.sub_name, sync_kind, sync_relname, sync_status 
  FROM pglogical.local_sync_status stat 
  JOIN pglogical.subscription sub ON sub.sub_id = stat.sync_subid 
 WHERE sync_status!='r'

Answer 3

It doesn't seem like anyone has mentioned checking the postgre log files yet, but these contain the details of any logical replication worker errors that explicitly identify any replication errors that occur. These logs are stored by default under <Postgre Install folder>\data\log e.g. C:\Program Files\PostgreSQL\15\data\log\

It's useful also to set the log_destination property in the postgresql.conf file to add jsonlog so that you get nice log objects instead of just a stdout-style log file. I import this into my application and present them to read more easily:

Answer 4

Whether the replica is synced or not could change from nanosecond to nanosecond, so there is generally no way of getting a definitive answer to that which you know will still be accurate at the time you see it. (Other than setting synchronous_commit to a high enough value so that you know they are always in sync)

Answer 5

SELECT subscription_name, status FROM pglogical.show_subscription_status();

where status is current

updated: this actually doesn't work for (current versions of?) pglogical either. i read about it in a blog post but I don't think it's the actual behavior. see:

• this comment https://github.com/2ndQuadrant/pglogical/issues/208#issuecomment-573636728
• my question to pglogical here: https://github.com/2ndQuadrant/pglogical/issues/252