If you using slony for PostgreSQL replication for more than one node (multiple replicas or cascading); then occasionally you might experience delays in replication if any one node is lagging behind.
This normally happens when you add new node or big table or large table-set to existing cluster or for some reason node is behind due to maintenance. Because of this; slony keeps all log events ( in sl_log_1 and sl_log_2 ) and can’t rotate/truncate log tables periodically as scheduled.
For optimal SYNC events, one should ensure sl_log_1 and sl_log_2 rows to be limited to less than 5M rows (depending on environment), else each SYNC might take longer time, and can increase over the period of time as these log tables starts growing, eventually slowing down everything and can lead to situation where the subscribers can’t keep up with the master node.
In general, each SYNC should take less than 1-2 secs for optimal performance. For example, lets consider the following cluster setup (name: prodcluster) using PostgreSQL 8.4 + Slony 2.0.x:
 |
|
So, any lag in NODE 4, can cause everything to stale. And here is an example SYNC events to consider at NODE 7, where each SYNC from Node 4 is taking ~10-11 SECS
|
1 2 3 4 5 6 7 8 9 10 11 12 13 |
grep 'SYNC .* done' /var/log/slony/slon_log|tail 2012-03-11 10:05:13 CDTINFO remoteWorkerThread_6: SYNC 5004941896 done in 0.024 seconds 2012-03-11 10:05:15 CDTINFO remoteWorkerThread_6: SYNC 5004941897 done in 0.726 seconds 2012-03-11 10:05:21 CDTINFO remoteWorkerThread_4: SYNC 5002699968 done in 11.095 seconds 2012-03-11 10:05:29 CDTINFO remoteWorkerThread_6: SYNC 5004941898 done in 0.008 seconds 2012-03-11 10:05:32 CDTINFO remoteWorkerThread_4: SYNC 5002699973 done in 10.681 seconds 2012-03-11 10:05:37 CDTINFO remoteWorkerThread_6: SYNC 5004941899 done in 0.008 seconds 2012-03-11 10:05:42 CDTINFO remoteWorkerThread_4: SYNC 5002699979 done in 10.590 seconds 2012-03-11 10:05:45 CDTINFO remoteWorkerThread_6: SYNC 5004941900 done in 0.008 seconds 2012-03-11 10:05:53 CDTINFO remoteWorkerThread_4: SYNC 5002699984 done in 10.682 seconds 2012-03-11 10:05:59 CDTINFO remoteWorkerThread_6: SYNC 5004941901 done in 0.013 seconds |
As you can see, each SYNC from node 4 is taking ~10-11 secs. By looking at the slony daemon log files in NODE 4, we can find out that logs are not getting truncated due to locking issue (simulated for demonstration, in real-world you normally get into rotation issues when slaves are lagging).
|
1 2 3 |
NOTICE: Slony-I: could not lock sl_log_1 - sl_log_1 not truncated |
So, we need to find the root cause to see why there is a pending LOCK or why the events are not yet consumed by the subscriber. Slony daemon logs are good source of information for troubleshooting. Another easiest way to get around the issue is to delete any old events that has been already SYNCed to subscribers, especially this is important when adding a new node or big tables to cluster. You can get current SYNC information, by using the following query:
|
1 2 3 4 5 6 7 8 9 10 11 12 13 |
db1=# select ev_origin, ev_seqno, "pg_catalog".txid_snapshot_xmin(ev_snapshot) from _prodcluster.sl_event where (ev_origin, ev_seqno) in (select ev_origin, min(ev_seqno) from _prodcluster.sl_event where ev_type = 'SYNC' group by ev_origin); ev_origin | ev_seqno | txid_snapshot_xmin -----------+------------+-------------------- 6 | 5004941853 | 302628906 7 | 5000000122 | 66475860 4 | 5002699761 | 277114491 13 | 5000000010 | 1499335 (4 rows) |
Means, any sequence less than 5002699761 has been SYNCed to all subscribers from Node 4; which means those records if exists can be deleted safely from slony log tables:
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 |
db1=# select count(1) from _prodcluster.sl_log_1; count --------- 8061398 (1 row) db1=# select count(1) from _prodcluster.sl_log_2; count --------- 6415322 (1 row) db1=# select count(1) from _prodcluster.sl_log_1 where log_origin=4 and log_txid < 5002699761; count --------- 8061398 (1 row) db1=# select count(1) from _prodcluster.sl_log_2 where log_origin=4 and log_txid < 5002699761; count --------- 6433414 (1 row) |
That’s pretty much 90% of the table’s data and can be deleted and vacuumed. And, doing so ..
|
1 2 3 4 5 6 7 8 9 10 |
db1=# delete from _prodcluster.sl_log_1 where log_origin=4 and log_txid < 5002699761; DELETE 8061398 db1=# delete from _prodcluster.sl_log_2 where log_origin=4 and log_txid < 5002699761; DELETE 6533972 db1=# vacuum _prodcluster.sl_log_1; VACUUM db1=# vacuum _prodcluster.sl_log_2; VACUUM |
And immediately we can see SYNC performing much much better, and slave will be caught up pretty soon until the log tables starts growing again (and if the table can’t be rotated + truncated )
|
1 2 3 4 5 6 7 8 9 10 11 12 13 |
grep 'SYNC .* done' /var/log/slony/slon_log|tail 2012-03-11 10:45:01 CDTINFO remoteWorkerThread_4: SYNC 5002701126 done in 1.294 seconds 2012-03-11 10:45:04 CDTINFO remoteWorkerThread_6: SYNC 5004942153 done in 0.010 seconds 2012-03-11 10:45:06 CDTINFO remoteWorkerThread_4: SYNC 5002701128 done in 1.583 seconds 2012-03-11 10:45:10 CDTINFO remoteWorkerThread_4: SYNC 5002701130 done in 1.530 seconds 2012-03-11 10:45:15 CDTINFO remoteWorkerThread_4: SYNC 5002701133 done in 1.453 seconds 2012-03-11 10:45:16 CDTINFO remoteWorkerThread_6: SYNC 5004942154 done in 0.010 seconds 2012-03-11 10:45:19 CDTINFO remoteWorkerThread_4: SYNC 5002701135 done in 1.291 seconds 2012-03-11 10:45:23 CDTINFO remoteWorkerThread_4: SYNC 5002701137 done in 1.269 seconds 2012-03-11 10:45:26 CDTINFO remoteWorkerThread_6: SYNC 5004942155 done in 0.010 seconds 2012-03-11 10:45:27 CDTINFO remoteWorkerThread_4: SYNC 5002701139 done in 1.270 seconds |
Its one easy way to get around the problem especially when you add new node to cluster or have lot of backlog (Its part of what cleanupevent() does).
linux whoami…
[…]Venu Anuganti Blog » PostgreSQL : Slony Replication Lag – Manual Log Tables Cleanup[…]…
I want to know the lag difference between slave and master in terms of rows ? I mean master has inserted suppose 100 rows and from that only 20 rows are processed and still 80 rows are remaining so how can i get that difference ?
Kirit, look at sl_status table from Slony’s application database; particularly st_lag_num_events should help you.
Thanks Venu I will check and let you know
Hi Venu,
I have checked and it is giving lag information (st_lag_num_events).
One more questions
How can i find out number of slony clusters available in one database ?
e.g. I have one database db1
I have created two slony cluster under db1 database says slonycluster1, slonycluster2
In which table can i find out this information ? regarding how many cluster with cluster name in database db1 ?