On Thu, 2005-09-29 at 01:09 +0300, Hannu Krosing wrote:
> On K, 2005-09-28 at 12:37 -0500, Joe Markwardt wrote:
> > On Tue, 2005-09-27 at 21:08 -0400, Christopher Browne wrote:
> > > Joe Markwardt wrote:
> > > 
> > > >On Wed, 2005-09-28 at 01:20 +0300, Hannu Krosing wrote:
> > > >  
> > > >
> > > >>On T, 2005-09-27 at 16:37 -0500, Joe Markwardt wrote:
> > > >>
> > > >>    
> > > >>
> > > >>>Yep.  And I restarted the slon's as well, so they should be using the
> > > >>>index as long as the planner thinks it will help.  Is there anyway I can
> > > >>>see the query that slon is generating to create the cursor? If I could
> > > >>>see that query then I could do some explain analyze's and see what they
> > > >>>say...
> > > >>>      
> > > >>>
> > > >>I usually look at the queries in postgres log.
> > > >>
> > > >>In your case you could set up postgres to log only long queries, say
> > > >>over 50 sec, and then just tail -f the log.
> > > >>
> > > >>When analysing take notice that slon specially sets enable_seqsnam and
> > > >>enable_indexscan before running the query on sl_log_1.
> > > >>
> > > >>    
> > > >>
> > > >Thanks for the tip, but the only queries that are being logged are the
> > > >FETCH statements...I suppose I could set it up to log all queries (and
> > > >plans) and then restart slon, then turn off the query logging.
> > > >  
> > > >
> > > Right you are...
> > > 
> > > The interesting query is the one that sets up the cursor, and it doesn't
> > > take long :-(.
> > > 
> > > You can tell how many SYNCs are being processed together by looking at
> > > two consecutive lines that say "SYNC XXXX done in Y.xyz seconds"
> > > 
> > > (They'll have lines in between...)
> > > 
> > > If it's "SYNC 1610644 done in 119 seconds" followed (2 minutes later) by
> > > "SYNC 1610724 done in 119 seconds", then you know that it's doing groups
> > > of 80, and even if it's not catching up quickly, that's at least the
> > > right direction to go in.
> > > 
> > 
> > chris, going through the logs from yesterday afternoon it appears that
> > it is varying the number of SYNCs processed each time, isn't the -o0
> > supposed to force it to always do 80?
> > 
> > I keep getting log entries like this:
> > 
> > 2005-09-28 11:06:29 CDT DEBUG3 calc sync size - last time: 1 last
> > length: 127436 ideal: 80 proposed size: 2
> > 
> > with varying values for proposed size...
> > 
> > Attached you'll find the output of the explain analyze's from the cursor
> > declaration I got from the logs.  It appears that it is using the new
> > index, and the new index is indeed faster than a sequential scan on the
> > table.  I'm not sure if there is anything else that could be done to
> > make this query run faster while it's catching up, but i'll play around
> > some.
> 
> So it takes 114 secs for indexscan over ~300k xids worth of rows
> returning nothing. What hardware are you running on (RAM/disks/CPU) ?
> 
6 disk 15Krpm FC raid 1+0 array, dual opteron 246's, 8GB o ram

>From what I can tell from the plan its ~120 secs for an index scan over
~14 million rows, expecting to find 300K, but not finding any. Also,
according to vmstat and iostat, I'm not hitting the disk at all, so I'm
assuming that means the entire sl_log_1 table, or at least the index its
using for this query, is cached in memory...

> Depending on how big sl_log_1 is, you may want to do a reindex on
> sl_log_1.
> 
hmm well as part of my testing I dropped all the indexes on sl_log_1 and
recreated them, so this in essence has already been done,if I understand
the REINDEX command correctly

> Or maybe even
> cluster  sl_log_1_idx2 on sl_log_1;
> 

Thats an idea, I'll give it a try and see if it helps

> Otoh, if your client side prosessing needs allow it, you could just re-
> subscribe the biggest tables (preferrably drop all indexes except the PK
> or UNIQUE index used by slony before doing it). It is often faster than
> catching up.

I was hoping to find a way to get replication to catch up (and stay
resonably caught up) because from what I can tell while this update load
is unusuall for now, it looks like it could be becoming commonplace
within the next 6 months.  And while re-subscribing is way faster (takes
about 8 hours to complete for the entire set) its not a "good" thing to
do every weekend after the heavy updates run.  If thats what I have to
do to deal with single query's that change large numbers of rows and
maintain a decent lag time b/w the two nodes, then I guess thats what I
have to do.  It would be nice if slony could handle this edge case a
little nicer, (just replicate the 1 query instead of turning it into 5
million ) but I certainly can't see any way around it when you use
triggers, and it fits the rest of our needs well.  

Anyways it appears that it got over the 5 million line update
transaction finally, and now its flying along the way it usually does.

2005-09-29 08:36:15 CDT DEBUG2 remoteWorkerThread_1: SYNC 1691933 done
in 0.798 seconds

from the way things look it should be caught up before the end of the
day :-)

-Joe