More information:

I can confirm that over the course of 3 or so hours, our sl_log_2 table 
grew from 1,000 rows to over 9 million rows. This is due to us doing 
huge table wide updates I believe.

So now sl_log_2 is huge, and the 'fetch 100 from LOG' is a query hitting 
the cursor LOG, which is defined as:

                                                  "declare LOG cursor 
for select "
                                                  "    log_origin, 
log_xid, log_tableid, "
                                                  "    log_actionseq, 
log_cmdtype, "
                                                  "    
octet_length(log_cmddata), "
                                                  "    case when 
octet_length(log_cmddata) <= %d "
                                                  "        then 
log_cmddata "
                                                  "        else null end "
                                                  "from %s.sl_log_2 %s 
order by log_actionseq; ",


Looking at the pg_stat_activity, it looks like 'fetch 1200 from LOG' has 
the same transaction start time as the query start time, which suggests 
that each time it fetches 100 from the log it is starting a new cursor, 
is this normal / expected?


select now() - xact_start as transaction_age, now() - query_start as 
query_age, current_query::varchar(80), waiting from pg_stat_activity 
where usename = 'slony' and current_query like '%LOG%';
  transaction_age |    query_age    |    current_query     | waiting
-----------------+-----------------+----------------------+---------
  00:27:01.652087 | 00:27:01.650933 | fetch 100 from LOG;  | f
(1 row)


So this has to be my issue. The query that hits sl_log_2 is a sequential 
scan, does this mean every time we retrieve 100 from the cursor, we do 
another sequential scan on the table to get the next 100 rows?

- Brian F


On 09/06/2012 03:09 PM, Brian Fehrle wrote:
> Hi all,
>
> postgresql 8.4
> slony 1.2
> centos system
>
> I have single master to single slave slony cluster where slony is very
> far behind. There are no errors in the logs or anything, but what looks
> to be happeneing is that queries slony is executing on the slony log
> table on the master are taking a long time to complete.
>
> The query is "fetch 100 from LOG;" which can take a long time to
> complete, over 15 minutes at times. Each time this happens we process 1
> event. This usually takes milliseconds to complete.
>
> At this point, the query on the master 'fetch 100 from log' takes about
> 20 minutes to complete, and after it completes the slave processes 1
> more event, and then 'fetch 100 from log' kicks off again and takes yet
> another 20 or so minutes. So the slave is processing an event about once
> per 20 minutes.
>
> As for a cause I believe it's due to the follow up work after adding a
> column to a table in replication. After adding the column, I believe
> that the table is being updated to set new values in the newly added
> column. This could result in millions of new items for slony to process,
> which may have caused the tables to become so large that they are
> resulting in sequential scans or something.
>
> I'm trying to dig in and see what exactly 'fetch 100 from log' is doing
> on the master, and if I can speed it up. Is this querying sl_log_<1/2>
> tables?
>
> the pg table pg_notify does not have outstanding dead rows, it's at 0.
> also out of all the slony tables in the slony schema, the one with the
> most dead rows is at about 2K dead rows.
>
> sl_log_1 has 0 rows, sl_log_2 has about 9,326,260 rows (and zero dead rows).
>
> I'm going to see if we can reduce group size, see if for whatever reason
> that reduces the query result set so it does a index scan vs sequential
> (if that's even the issue).
>
> Any help is greatly appreciated.
>
> - Brian F
> _______________________________________________
> Slony1-general mailing list
> Slony1-general at lists.slony.info
> http://lists.slony.info/mailman/listinfo/slony1-general

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.slony.info/pipermail/slony1-general/attachments/20120906/ec9367a4/attachment.htm