joe <joe at avsupport.com> writes:
> Greetings all, sorry for the long post, but hopefully you can shed some
> light on my dilemma here:
> 	Last Friday I started replication on our production servers after an
> extensive playing period on some test servers, and everything seemed to
> be fine before i left for the weekend, the data set had apparently
> finished copying over from the subscribe set etc. and things seemed to
> be humming along just fine. 
> 	I came into work this morning and found the master db server to be dog
> slow (load average had been above 10 since Saturday sometime).  After a
> bit of investigation I think that the slony replication service is
> causing it.
>
> postgres 19983 22.8  3.4 83488 69508 ?       S    Jan07 1140:0 postgres:
> postgres pl ::ffff:216.239.10.115 FETCH
> postgres 20073 23.5  3.4 83480 69524 ?       S    Jan07 1169:57
> postgres: postgres pl ::ffff:216.239.10.116 FETCH
>
>>From postgres I found that those 2 processes are running the following
> queries:
>
> 19983 | fetch 100 from LOG;
> 20073 | fetch 100 from LOG; 
>
> Which I'm guessing is slony grabbing things from the transaction log for
> replication.  So I figured I'd check to see how many tuples were in the
> log.

Your guess is absolutely right.

> pl=# select reltuples::int from pg_class where relname='sl_log_1';
>  reltuples 
> -----------
>   16945348
> (1 row)
>
> pl=# select reltuples::int from pg_class where relname='sl_log_2';
>  reltuples 
> -----------
>          0
>
> To confirm that replication is falling behind I checked one of the
> replicated tables on the slaves to see if it was in sync with the master
>
> Master: pl=# select activity_id from pl02_activity_table order by
> activity_id desc limit 1;
>  activity_id 
> -------------
>     13835041
> (1 row)
>
> Slave1: pl=# select activity_id from pl02_activity_table order by
> activity_id desc limit 1;
>  activity_id 
> -------------
>     13818012
> (1 row)
>
> Slave2: pl=# select activity_id from pl02_activity_table order by
> activity_id desc limit 1;
>  activity_id 
> -------------
>     13818008
> (1 row)
>
> Software versions:
> Slony-1.05
> postgres 7.4.6
> MasterDB: 3.8 Ghz Pentium 4
> 	  6GB of RAM 
> 	  5 36GB 10K SCSI in HW RAID5
> 	  RedHat 9
> Slave1 & Slave2:  Dual Opteron 246
> 	  8 GB Ram
> 	  6 73GB 15k FC drives in HW RAID 1+0 (512 MB battery-backed cache on
> controller)
> 	  SLES 8 for AMD64
>
> DB-size on Master: 78 GB
> 	"" Slave1: 74 GB
> 	"" Slave2: 69 GB
>
> Are things removed from the log once they're replicated or do they stay
> in there for a while?

They are removed after a while.  Loosely, I think the rule now is that
in the cleanup thread that runs after 10 minutes has passed after
SYNCs have been confirmed on all the nodes, then the data for those
SYNCs can get cleaned out.

You can look in the logs for the word "cleanup"; you'll see something like the following:

% grep cleanup /somewhere/some.log
DEBUG1 cleanupThread:    0.038 seconds for cleanupEvent()
DEBUG1 cleanupThread:    0.175 seconds for delete logs
DEBUG2 cleanupThread:    0.726 seconds for vacuuming
DEBUG1 cleanupThread:    0.022 seconds for cleanupEvent()
DEBUG1 cleanupThread:    0.107 seconds for delete logs
DEBUG2 cleanupThread:   16.842 seconds for vacuuming
DEBUG1 cleanupThread:    0.025 seconds for cleanupEvent()
DEBUG1 cleanupThread:    0.073 seconds for delete logs
DEBUG2 cleanupThread:   63.245 seconds for vacuuming
DEBUG1 cleanupThread:    0.044 seconds for cleanupEvent()
DEBUG1 cleanupThread:    0.265 seconds for delete logs
DEBUG2 cleanupThread:   38.443 seconds for vacuuming
DEBUG1 cleanupThread:    0.048 seconds for cleanupEvent()
DEBUG1 cleanupThread:    0.302 seconds for delete logs
DEBUG2 cleanupThread:   27.043 seconds for vacuuming
DEBUG1 cleanupThread:    0.052 seconds for cleanupEvent()
DEBUG1 cleanupThread:    0.409 seconds for delete logs
DEBUG2 cleanupThread:  112.645 seconds for vacuuming

If the vacuums are running long, that's a sign of the table getting
big; any time "delete logs" takes a long time, that suggests that it
got around to clearing out a bunch of data.  None of the above shows
off much deleting :-(.

> Am I correct in guessing that for some reason its attempting to do a
> seq scan on the sl_log_1 table to look for new rows to update, and
> thats why those processes are taking forever?

No, that shouldn't be.

> Is this expected? or is it possible that I goofed something during the
> install?
>
> If more information is needed let me know and i'll do my best to provide
> it.

Take a look in the logs on a subscriber node.  The following lines are
the relevant ones:

DEBUG2 remoteWorkerThread_1: SYNC 4464054 processing
DEBUG2 remoteWorkerThread_1: syncing set 1 with 38 table(s) from provider 1
DEBUG2 remoteWorkerThread_1: syncing set 25506 with 6 table(s) from provider 1
DEBUG2 remoteHelperThread_1_1: 0.035 seconds delay for first row
DEBUG2 remoteHelperThread_1_1: 0.036 seconds until close cursor
DEBUG2 remoteWorkerThread_1: new sl_rowid_seq value: 1000000000026599
DEBUG2 remoteWorkerThread_1: SYNC 4464054 done in 0.136 seconds

What you are doubtless seeing is that the "delay for first row" is
WAY, WAY MORE than 0.035 seconds.

It's probably worth doing an overview of things.

% egrep "SYNC [0-9]+ done in" /somewhere/some.log | tail
DEBUG2 remoteWorkerThread_1: SYNC 4464070 done in 0.123 seconds
DEBUG2 remoteWorkerThread_1: SYNC 4464071 done in 0.165 seconds
DEBUG2 remoteWorkerThread_1: SYNC 4464072 done in 0.153 seconds
DEBUG2 remoteWorkerThread_1: SYNC 4464073 done in 0.142 seconds
DEBUG2 remoteWorkerThread_1: SYNC 4464074 done in 0.175 seconds
DEBUG2 remoteWorkerThread_1: SYNC 4464075 done in 0.138 seconds
DEBUG2 remoteWorkerThread_1: SYNC 4464076 done in 0.162 seconds
DEBUG2 remoteWorkerThread_1: SYNC 4464077 done in 0.148 seconds
DEBUG2 remoteWorkerThread_1: SYNC 4464078 done in 0.149 seconds
DEBUG2 remoteWorkerThread_1: SYNC 4464079 done in 0.138 seconds

In the above, you can see that the SYNCs are being done one by one, in
order, and are taking a brief time.

If replication falls behind, it is not unusual for several SYNCs to
get processed together.  So you might see 4464070, then 4464078, then
4464086, with somewhat longer times.

See if the logs are telling you that:
 a) Things are catching up;
 b) Things are falling behind;
 c) Things are a bit behind, but not getting worse.

If sl_log_1 and sl_seqlog aren't getting cleared out, that tends to be
the result of one of a few things:

 1.  Have you got a node shut down or otherwise not replicating?
 
     The logs won't get purged until that node receives the changes.

 2.  Have you got an old node that hasn't gotten cleared out of the
     configuration?

     This used to be quite a problem in 1.0.2; there are big
     improvements in 1.0.5.

 3.  You might take a peek at sl_confirm on any of the nodes.

     If it has some Way Old entries, that tends to be useful for
     determining what to be suspicious of.

But the first secret is to look at the logs...
-- 
"cbbrowne","@","ca.afilias.info"
<http://cbbrowne.com/info/slony.html>
Christopher Browne
(416) 673-4124 (land)