On Wednesday 27 August 2008 04:32:44 pm Glyn Astill wrote:
> > > If it's
> > > stuck,  how do I unstick it?
> >
> > Have a look at the log files.  Slony is pretty good about
> > logging why
> > it's unable to replicate.
>
> Also a peek in pg_stat_activity and a "ps -ax" may shed some light...

Here's a screenful of the intermixed logfiles.  I notice that I have about 
10 "slon" processes per node;  is that normal?  Nothing jumps out as 
obviously being a problem in the logs...

==> slony1/node2/pgbench_slave-2008-08-27_16:55:57.log <==
2008-08-27 16:59:50 EDT DEBUG2 remoteListenThread_1: queue event 1,6996 SYNC
2008-08-27 16:59:50 EDT DEBUG2 remoteWorkerThread_1: Received event 1,6996 
SYNC
2008-08-27 16:59:50 EDT DEBUG2 calc sync size - last time: 1 last length: 
17357 ideal: 3 proposed size: 3
2008-08-27 16:59:50 EDT DEBUG2 remoteWorkerThread_1: SYNC 6996 processing
2008-08-27 16:59:50 EDT DEBUG2 remoteWorkerThread_1: syncing set 1 with 4 
table(s) from provider 1
2008-08-27 16:59:50 EDT DEBUG2  ssy_action_list length: 0
2008-08-27 16:59:50 EDT DEBUG2 remoteWorkerThread_1: current local log_status 
is 0
2008-08-27 16:59:50 EDT DEBUG2 remoteWorkerThread_1_1: current remote 
log_status = 0
2008-08-27 16:59:50 EDT DEBUG2 remoteHelperThread_1_1: 0.001 seconds delay for 
first row
2008-08-27 16:59:50 EDT DEBUG2 remoteHelperThread_1_1: 0.001 seconds until 
close cursor
2008-08-27 16:59:50 EDT DEBUG2 remoteHelperThread_1_1: inserts=0 updates=0 
deletes=0
2008-08-27 16:59:50 EDT DEBUG2 remoteWorkerThread_1: new sl_rowid_seq value: 
1000000000002442
2008-08-27 16:59:50 EDT DEBUG2 remoteWorkerThread_1: SYNC 6996 done in 0.006 
seconds

==> postgresql.log <==
[2008-08-27 16:59:53 EDT] 48b5bf5d.62d8.14 (postgres@) LOG:  duration: 
2890.479 ms  statement: notify "_replication_Event"; insert 
into "_replication".sl_event     (ev_origin, ev_seqno, ev_timestamp,      
ev_minxid, ev_maxxid, ev_xip, ev_type     ) values ('2', '6770', '2008-08-27 
16:59:43.239217', '2046164', '2046166', '''2046164''', 'SYNC'); insert 
into "_replication".sl_confirm       (con_origin, con_received, con_seqno, 
con_timestamp)    values (2, 1, '6770', now()); commit transaction;
[2008-08-27 16:59:53 EDT] 48b5bf5d.62fe.15 (postgres@) LOG:  duration: 
2878.348 ms  statement: notify "_replication_Event"; insert 
into "_replication".sl_event     (ev_origin, ev_seqno, ev_timestamp,      
ev_minxid, ev_maxxid, ev_xip, ev_type     ) values ('1', '6996', '2008-08-27 
16:59:43.235193', '2046164', '2046165', '', 'SYNC'); insert 
into "_replication".sl_confirm  (con_origin, con_received, con_seqno, 
con_timestamp)    values (1, 2, '6996', now()); commit transaction;

==> slony1/node1/pgbench_master-2008-08-27_16:55:52.log <==
2008-08-27 16:59:53 EDT DEBUG2 syncThread: new sl_action_seq 12203 - SYNC 6997
2008-08-27 16:59:54 EDT DEBUG2 localListenThread: Received event 1,6997 SYNC
2008-08-27 16:59:54 EDT DEBUG2 remoteListenThread_2: queue event 2,6771 SYNC
2008-08-27 16:59:54 EDT DEBUG2 remoteWorkerThread_2: Received event 2,6771 
SYNC
2008-08-27 16:59:54 EDT DEBUG2 calc sync size - last time: 1 last length: 3781 
ideal: 15 proposed size: 3
2008-08-27 16:59:54 EDT DEBUG2 remoteWorkerThread_2: SYNC 6771 processing
2008-08-27 16:59:54 EDT DEBUG2 remoteWorkerThread_2: no sets need syncing for 
this event

==> slony1/node2/pgbench_slave-2008-08-27_16:55:57.log <==
2008-08-27 16:59:53 EDT DEBUG2 syncThread: new sl_action_seq 1 - SYNC 6771
2008-08-27 16:59:54 EDT DEBUG2 remoteListenThread_1: queue event 1,6997 SYNC
2008-08-27 16:59:54 EDT DEBUG2 remoteWorkerThread_1: Received event 1,6997 
SYNC
2008-08-27 16:59:54 EDT DEBUG2 calc sync size - last time: 1 last length: 3776 
ideal: 15 proposed size: 3
2008-08-27 16:59:54 EDT DEBUG2 remoteWorkerThread_1: SYNC 6997 processing
2008-08-27 16:59:54 EDT DEBUG2 remoteWorkerThread_1: syncing set 1 with 4 
table(s) from provider 1
2008-08-27 16:59:54 EDT DEBUG2  ssy_action_list length: 0
2008-08-27 16:59:54 EDT DEBUG2 remoteWorkerThread_1: current local log_status 
is 0
2008-08-27 16:59:54 EDT DEBUG2 remoteWorkerThread_1_1: current remote 
log_status = 0
2008-08-27 16:59:54 EDT DEBUG2 remoteHelperThread_1_1: 0.001 seconds delay for 
first row
2008-08-27 16:59:54 EDT DEBUG2 remoteHelperThread_1_1: 0.001 seconds until 
close cursor
2008-08-27 16:59:54 EDT DEBUG2 remoteHelperThread_1_1: inserts=0 updates=0 
deletes=0
2008-08-27 16:59:54 EDT DEBUG2 remoteWorkerThread_1: new sl_rowid_seq value: 
1000000000002442
2008-08-27 16:59:54 EDT DEBUG2 remoteWorkerThread_1: SYNC 6997 done in 0.006 
seconds
2008-08-27 16:59:54 EDT DEBUG2 localListenThread: Received event 2,6771 SYNC

==> postgresql.log <==
[2008-08-27 16:59:58 EDT] 48b5bf5d.62d8.15 (postgres@) LOG:  duration: 
3901.927 ms  statement: notify "_replication_Event"; insert 
into "_replication".sl_event     (ev_origin, ev_seqno, ev_timestamp,      
ev_minxid, ev_maxxid, ev_xip, ev_type     ) values ('2', '6771', '2008-08-27 
16:59:53.94613', '2046352', '2046353', '', 'SYNC'); insert 
into "_replication".sl_confirm   (con_origin, con_received, con_seqno, 
con_timestamp)    values (2, 1, '6771', now()); commit transaction;
[2008-08-27 16:59:58 EDT] 48b5bf5d.62fe.16 (postgres@) LOG:  duration: 
3930.953 ms  statement: notify "_replication_Event"; insert 
into "_replication".sl_event     (ev_origin, ev_seqno, ev_timestamp,      
ev_minxid, ev_maxxid, ev_xip, ev_type     ) values ('1', '6997', '2008-08-27 
16:59:53.928121', '2046351', '2046352', '', 'SYNC'); insert 
into "_replication".sl_confirm  (con_origin, con_received, con_seqno, 
con_timestamp)    values (1, 2, '6997', now()); commit transaction;

==> slony1/node1/pgbench_master-2008-08-27_16:55:52.log <==
2008-08-27 16:59:58 EDT DEBUG2 remoteWorkerThread_2: forward confirm 1,6996 
received by 2

==> slony1/node2/pgbench_slave-2008-08-27_16:55:57.log <==
2008-08-27 16:59:58 EDT DEBUG2 remoteWorkerThread_1: forward confirm 2,6770 
received by 1


-- 

David L. Lambert
  Software Developer,  Precision Motor Transport Group, LLC
  Work phone 517-349-3011 x215
  Cell phone 586-873-8813