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.

Also, going through the logs, starting at about 3 and continuing up
through now (~137000 lines) I see this group of log lines repeated with
no "SYNC xxx done in yyy" between.

2005-09-28 03:18:06 CDT DEBUG3 remoteHelperThread_1_1: got 100 log rows
2005-09-28 03:18:06 CDT DEBUG3 remoteHelperThread_1_1: 10 log buffers
delivered
2005-09-28 03:18:06 CDT DEBUG4 remoteHelperThread_1_1: allocate lines
2005-09-28 03:18:06 CDT DEBUG4 remoteHelperThread_1_1: have 10 line
buffers
 
I'm guessing that it found a big transaction and this is probably the
cause of my performance issues?


-Joe

-------------- next part --------------
pl=# explain analyze
pl-# select     log_origin, log_xid, log_tableid,     log_actionseq,
pl-# log_cmdtype, log_cmddata from "_pl_replication".sl_log_1 where log_origin = 1 and (  (
pl(#  log_tableid in
pl(#  (89,85,7,8,107,88,90,9,10,11,12,13,113,55,114,67,68,69,70,71,72,73,74,75,76,77,1,2,3,4,5,6,78,79,80,81,82,83,84,86,87,97,98,99,
pl(#  100,101,102,103,104,105,106,110,112,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,42,44,45,46,47
pl(#  ,48,49,50,51,52,53,54,56,57,58,59,60,61,62,63,64,65,66,14,41,43,96,94,109,111,91,92,93,95,108)
pl(#  and (log_xid < '358550506' and "_pl_replication".xxid_lt_snapshot(log_xid,
pl(#  '358260643:358550506:''358549588'',''358260643'''))
pl(#  and (log_xid >= '358260643' and "_pl_replication".xxid_ge_snapshot(log_xid,
pl(# '358260643:358550429:''358549588'',''358260643'''))
pl(# ) ) order by log_actionseq;
           QUERY PLAN          
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Sort  (cost=1582953.41..1583838.86 rows=354181 width=129) (actual time=114267.532..114267.532 rows=0 loops=1)
   Sort Key: log_actionseq
   ->  Index Scan using sl_log_1_idx2 on sl_log_1  (cost=0.00..1535780.32 rows=354181 width=129) (actual time=114267.464..114267.464 rows=0 loops=1)
         Index Cond: ((log_xid < '358550506'::_pl_replication.xxid) AND (log_xid >= '358260643'::_pl_replication.xxid))
         Filter: ((log_origin = 1) AND ((log_tableid = 89) OR (log_tableid = 85) OR (log_tableid = 7) OR (log_tableid = 8) OR (log_tableid = 107) OR (log_tableid = 88) OR (log_tableid = 90) OR (log_tableid = 9) OR (log_tableid = 10) OR (log_tableid = 11) OR (log_tableid = 12) OR (log_tableid = 13) OR (log_tableid = 113) OR (log_tableid = 55) OR (log_tableid = 114) OR (log_tableid = 67) OR (log_tableid = 68) OR (log_tableid = 69) OR (log_tableid = 70) OR (log_tableid = 71) OR (log_tableid = 72) OR (log_tableid = 73) OR (log_tableid = 74) OR (log_tableid = 75) OR (log_tableid = 76) OR (log_tableid = 77) OR (log_tableid = 1) OR (log_tableid = 2) OR (log_tableid = 3) OR (log_tableid = 4) OR (log_tableid = 5) OR (log_tableid = 6) OR (log_tableid = 78) OR (log_tableid = 79) OR (log_tableid = 80) OR (log_tableid = 81) OR (log_tableid = 82) OR (log_tableid = 83) OR (log_tableid = 84) OR (log_tableid = 86) OR (log_tableid = 87) OR (log_tableid = 97) OR (log_tableid = 98) OR (log_tableid = 99) OR (log_tableid = 100) OR (log_tableid = 101) OR (log_tableid = 102) OR (log_tableid = 103) OR (log_tableid = 104) OR (log_tableid = 105) OR (log_tableid = 106) OR (log_tableid = 110) OR (log_tableid = 112) OR (log_tableid = 15) OR (log_tableid = 16) OR (log_tableid = 17) OR (log_tableid = 18) OR (log_tableid = 19) OR (log_tableid = 20) OR (log_tableid = 21) OR (log_tableid = 22) OR (log_tableid = 23) OR (log_tableid = 24) OR (log_tableid = 25) OR (log_tableid = 26) OR (log_tableid = 27) OR (log_tableid = 28) OR (log_tableid = 29) OR (log_tableid = 30) OR (log_tableid = 31) OR (log_tableid = 32) OR (log_tableid = 33) OR (log_tableid = 34) OR (log_tableid = 35) OR (log_tableid = 36) OR (log_tableid = 37) OR (log_tableid = 38) OR (log_tableid = 39) OR (log_tableid = 40) OR (log_tableid = 42) OR (log_tableid = 44) OR (log_tableid = 45) OR (log_tableid = 46) OR (log_tableid = 47) OR (log_tableid = 48) OR (log_tableid = 49) OR (log_tableid = 50) OR (log_tableid = 51) OR (log_tableid = 52) OR (log_tableid = 53) OR (log_tableid = 54) OR (log_tableid = 56) OR (log_tableid = 57) OR (log_tableid = 58) OR (log_tableid = 59) OR (log_tableid = 60) OR (log_tableid = 61) OR (log_tableid = 62) OR (log_tableid = 63) OR (log_tableid = 64) OR (log_tableid = 65) OR (log_tableid = 66) OR (log_tableid = 14) OR (log_tableid = 41) OR (log_tableid = 43) OR (log_tableid = 96) OR (log_tableid = 94) OR (log_tableid = 109) OR (log_tableid = 111) OR (log_tableid = 91) OR (log_tableid = 92) OR (log_tableid = 93) OR (log_tableid = 95) OR (log_tableid = 108)) AND _pl_replication.xxid_lt_snapshot(log_xid, '358260643:358550506:358549588,358260643'::_pl_replication.xxid_snapshot) AND _pl_replication.xxid_ge_snapshot(log_xid, '358260643:358550429:358549588,358260643'::_pl_replication.xxid_snapshot))
 Total runtime: 114267.772 ms
(6 rows)
-------------- next part --------------
pl=# set enable_indexscan to 0;
SET
pl=# explain analyze
pl-# select     log_origin, log_xid, log_tableid,     log_actionseq,
pl-# log_cmdtype, log_cmddata from "_pl_replication".sl_log_1 where log_origin = 1 and (  (
pl(#  log_tableid in
pl(#  (89,85,7,8,107,88,90,9,10,11,12,13,113,55,114,67,68,69,70,71,72,73,74,75,76,77,1,2,3,4,5,6,78,79,80,81,82,83,84,86,87,97,98,99,
pl(#  100,101,102,103,104,105,106,110,112,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,42,44,45,46,47
pl(#  ,48,49,50,51,52,53,54,56,57,58,59,60,61,62,63,64,65,66,14,41,43,96,94,109,111,91,92,93,95,108)
pl(#  and (log_xid < '358550506' and "_pl_replication".xxid_lt_snapshot(log_xid,
pl(#  '358260643:358550506:''358549588'',''358260643'''))
pl(#  and (log_xid >= '358260643' and "_pl_replication".xxid_ge_snapshot(log_xid,
pl(# '358260643:358550429:''358549588'',''358260643'''))
pl(# ) ) order by log_actionseq;
                                                              QUERY PLAN          
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Sort  (cost=5121638.15..5122962.02 rows=529548 width=129) (actual time=309438.764..309438.764 rows=0 loops=1)
   Sort Key: log_actionseq
   ->  Seq Scan on sl_log_1  (cost=0.00..5049572.96 rows=529548 width=129) (actual time=309438.754..309438.754 rows=0 loops=1)
         Filter: ((log_origin = 1) AND ((log_tableid = 89) OR (log_tableid = 85) OR (log_tableid = 7) OR (log_tableid = 8) OR (log_tableid = 107) OR (log_tableid = 88) OR (log_tableid = 90) OR (log_tableid = 9) OR (log_tableid = 10) OR (log_tableid = 11) OR (log_tableid = 12) OR (log_tableid = 13) OR (log_tableid = 113) OR (log_tableid = 55) OR (log_tableid = 114) OR (log_tableid = 67) OR (log_tableid = 68) OR (log_tableid = 69) OR (log_tableid = 70) OR (log_tableid = 71) OR (log_tableid = 72) OR (log_tableid = 73) OR (log_tableid = 74) OR (log_tableid = 75) OR (log_tableid = 76) OR (log_tableid = 77) OR (log_tableid = 1) OR (log_tableid = 2) OR (log_tableid = 3) OR (log_tableid = 4) OR (log_tableid = 5) OR (log_tableid = 6) OR (log_tableid = 78) OR (log_tableid = 79) OR (log_tableid = 80) OR (log_tableid = 81) OR (log_tableid = 82) OR (log_tableid = 83) OR (log_tableid = 84) OR (log_tableid = 86) OR (log_tableid = 87) OR (log_tableid = 97) OR (log_tableid = 98) OR (log_tableid = 99) OR (log_tableid = 100) OR (log_tableid = 101) OR (log_tableid = 102) OR (log_tableid = 103) OR (log_tableid = 104) OR (log_tableid = 105) OR (log_tableid = 106) OR (log_tableid = 110) OR (log_tableid = 112) OR (log_tableid = 15) OR (log_tableid = 16) OR (log_tableid = 17) OR (log_tableid = 18) OR (log_tableid = 19) OR (log_tableid = 20) OR (log_tableid = 21) OR (log_tableid = 22) OR (log_tableid = 23) OR (log_tableid = 24) OR (log_tableid = 25) OR (log_tableid = 26) OR (log_tableid = 27) OR (log_tableid = 28) OR (log_tableid = 29) OR (log_tableid = 30) OR (log_tableid = 31) OR (log_tableid = 32) OR (log_tableid = 33) OR (log_tableid = 34) OR (log_tableid = 35) OR (log_tableid = 36) OR (log_tableid = 37) OR (log_tableid = 38) OR (log_tableid = 39) OR (log_tableid = 40) OR (log_tableid = 42) OR (log_tableid = 44) OR (log_tableid = 45) OR (log_tableid = 46) OR (log_tableid = 47) OR (log_tableid = 48) OR (log_tableid = 49) OR (log_tableid = 50) OR (log_tableid = 51) OR (log_tableid = 52) OR (log_tableid = 53) OR (log_tableid = 54) OR (log_tableid = 56) OR (log_tableid = 57) OR (log_tableid = 58) OR (log_tableid = 59) OR (log_tableid = 60) OR (log_tableid = 61) OR (log_tableid = 62) OR (log_tableid = 63) OR (log_tableid = 64) OR (log_tableid = 65) OR (log_tableid = 66) OR (log_tableid = 14) OR (log_tableid = 41) OR (log_tableid = 43) OR (log_tableid = 96) OR (log_tableid = 94) OR (log_tableid = 109) OR (log_tableid = 111) OR (log_tableid = 91) OR (log_tableid = 92) OR (log_tableid = 93) OR (log_tableid = 95) OR (log_tableid = 108)) AND (log_xid < '358550506'::_pl_replication.xxid) AND _pl_replication.xxid_lt_snapshot(log_xid, '358260643:358550506:358549588,358260643'::_pl_replication.xxid_snapshot) AND (log_xid >= '358260643'::_pl_replication.xxid) AND _pl_replication.xxid_ge_snapshot(log_xid, '358260643:358550429:358549588,358260643'::_pl_replication.xxid_snapshot))
 Total runtime: 309438.991 ms
(5 rows)