David Rees escribió:
> On Fri, May 9, 2008 at 5:31 PM, Martin Marques
> <martin at marquesminen.com.ar> wrote:
> 
>> The other problems, and which are the things that make me think I may
>> have done something wrong is that the nodes, master and slaves, DB have
>> quite a good amount of load, mostly rolled-back slony transactions. It
>> doesn't bloat the server, but I was interested in knowing if all those
>> queries are right.
> 
> It kind of sounds like the subscription isn't succeeding and slony is
> just copying data to node 2, failing, and retrying. Are you sure that
> replication is working? What do the slony logs say?

Lets see. from node1 log I get:

2008-05-09 22:10:43 ART DEBUG2 calc sync size - last time: 1 last 
length: 11003 ideal: 5 proposed size: 3
2008-05-09 22:10:43 ART DEBUG2 remoteWorkerThread_2: SYNC 2029 processing
2008-05-09 22:10:43 ART DEBUG2 remoteWorkerThread_2: no sets need 
syncing for this event
2008-05-09 22:10:43 ART DEBUG2 remoteWorkerThread_2: forward confirm 
1,2029 received by 2
2008-05-09 22:10:50 ART DEBUG2 syncThread: new sl_action_seq 11 - SYNC 2030
2008-05-09 22:10:52 ART DEBUG2 localListenThread: Received event 1,2030 SYNC
2008-05-09 22:10:54 ART DEBUG2 remoteListenThread_2: queue event 2,2030 SYNC
2008-05-09 22:10:54 ART DEBUG2 remoteWorkerThread_2: Received event 
2,2030 SYNC

 From node2 log:

2008-05-09 22:25:26 ART DEBUG2 remoteListenThread_1: queue event 1,2117 SYNC
2008-05-09 22:25:26 ART DEBUG2 remoteWorkerThread_1: Received event 
1,2117 SYNC
2008-05-09 22:25:26 ART DEBUG2 calc sync size - last time: 1 last 
length: 11008 ideal: 5 proposed size: 3
2008-05-09 22:25:26 ART DEBUG2 remoteWorkerThread_1: SYNC 2117 processing
2008-05-09 22:25:26 ART DEBUG2 remoteWorkerThread_1: syncing set 1 with 
3 table(s) from provider 1
2008-05-09 22:25:26 ART DEBUG2  ssy_action_list length: 0
2008-05-09 22:25:26 ART DEBUG2 remoteWorkerThread_1: current local 
log_status is 0
2008-05-09 22:25:26 ART DEBUG2 remoteWorkerThread_1_1: current remote 
log_status = 0
2008-05-09 22:25:26 ART DEBUG2 remoteHelperThread_1_1: 0.001 seconds 
delay for first row
2008-05-09 22:25:26 ART DEBUG2 remoteHelperThread_1_1: 0.002 seconds 
until close cursor
2008-05-09 22:25:26 ART DEBUG2 remoteHelperThread_1_1: inserts=0 
updates=0 deletes=0
2008-05-09 22:25:26 ART DEBUG2 remoteWorkerThread_1: new sl_rowid_seq 
value: 1000000000000000
2008-05-09 22:25:26 ART DEBUG2 remoteWorkerThread_1: SYNC 2117 done in 
0.007 seconds

These happen each 10 seconds.

On postgresql.log I get:

2008-05-09 22:25:26 ART [27507]: [28515-1] LOG:  sentencia: select 
ev_origin, ev_seqno, ev_timestamp,        ev_minxid, ev_maxxid, ev_xip, 
        e
v_type,        ev_data1, ev_data2,        ev_data3, ev_data4, 
ev_data5, ev_data6,        ev_data7, ev_data8 from 
"_replicaprueba".sl_event e
  where (e.ev_origin = '1' and e.ev_seqno > '2116') order by 
e.ev_origin, e.ev_seqno
2008-05-09 22:25:26 ART [27507]: [28516-1] LOG:  duración: 0.607 ms
2008-05-09 22:25:26 ART [27507]: [28517-1] LOG:  sentencia: select 
con_origin, con_received,     max(con_seqno) as con_seqno, 
max(con_timestamp
) as con_timestamp from "_replicaprueba".sl_confirm where con_received 
<> 2 group by con_origin, con_received
2008-05-09 22:25:26 ART [27507]: [28518-1] LOG:  duración: 0.493 ms
2008-05-09 22:25:26 ART [27507]: [28519-1] LOG:  sentencia: select 
ev_origin, ev_seqno, ev_timestamp,        ev_minxid, ev_maxxid, ev_xip, 
        e
v_type,        ev_data1, ev_data2,        ev_data3, ev_data4, 
ev_data5, ev_data6,        ev_data7, ev_data8 from 
"_replicaprueba".sl_event e
  where (e.ev_origin = '1' and e.ev_seqno > '2117') order by 
e.ev_origin, e.ev_seqno
2008-05-09 22:25:26 ART [27507]: [28520-1] LOG:  duración: 0.428 ms
2008-05-09 22:25:26 ART [27507]: [28521-1] LOG:  sentencia: select 
con_origin, con_received,     max(con_seqno) as con_seqno, 
max(con_timestamp
) as con_timestamp from "_replicaprueba".sl_confirm where con_received 
<> 2 group by con_origin, con_received
2008-05-09 22:25:26 ART [27507]: [28522-1] LOG:  duración: 0.428 ms
2008-05-09 22:25:26 ART [27516]: [29549-1] LOG:  sentencia: start 
transaction; set enable_seqscan = off; set enable_indexscan = on;
2008-05-09 22:25:26 ART [27516]: [29550-1] LOG:  duración: 0.142 ms
2008-05-09 22:25:26 ART [27516]: [29551-1] LOG:  sentencia: select 
last_value from "_replicaprueba".sl_log_status
2008-05-09 22:25:26 ART [27516]: [29552-1] LOG:  duración: 0.209 ms
2008-05-09 22:25:26 ART [27516]: [29553-1] LOG:  sentencia: 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) <= 8192         then log_cmddata         else 
null end from "_r
eplicaprueba".sl_log_1 where log_origin = 1 and (  (
          log_tableid in (1,2,3)
             and (log_xid < '128705')
             and (log_xid >= '128702')
         ) ) order by log_actionseq;
2008-05-09 22:25:26 ART [27516]: [29554-1] LOG:  duración: 0.445 ms
2008-05-09 22:25:26 ART [27516]: [29555-1] LOG:  sentencia: fetch 100 
from LOG;
2008-05-09 22:25:26 ART [27516]: [29556-1] LOG:  duración: 0.101 ms
2008-05-09 22:25:26 ART [27516]: [29557-1] LOG:  sentencia: close LOG;
2008-05-09 22:25:26 ART [27516]: [29558-1] LOG:  duración: 0.061 ms
2008-05-09 22:25:26 ART [27516]: [29559-1] LOG:  sentencia: rollback 
transaction; set enable_seqscan = default; set enable_indexscan = default;
2008-05-09 22:25:26 ART [27516]: [29560-1] LOG:  duración: 0.118 ms

What are these?