Combing through the logs, I have the SQL that slon was performing when it
encountered the duplicate primary key error. It shows that there sl_log_1
entries are being reprocessed, specifically those with log_actionseq 7865731
through 7865736.
I've removed the SQL for privacy/brevity.
Any ideas?
========================================================
------------ can see data from the master.sl_log_1 being copied
2006-01-31 20:11:30 PST 17563 32021 LOG: statement:
insert into "_replication".sl_log_1 (log_origin, log_xid,
log_tableid, log_actionseq, log_cmdtype, log_cmddata) values ('1',
'255888029', '21', '7865730', 'U',
insert into "_replication".sl_log_1 (log_origin, log_xid,
log_tableid, log_actionseq, log_cmdtype, log_cmddata) values
('1', '255888034', '21', '7865731', 'U',
insert into "_replication".sl_log_1 (log_origin, log_xid,
log_tableid, log_actionseq, log_cmdtype, log_cmddata) values
('1', '255888039', '24', '7865732', 'I',
insert into "_replication".sl_log_1 (log_origin, log_xid,
log_tableid, log_actionseq, log_cmdtype, log_cmddata) values
('1', '255888041', '24', '7865733', 'U', < sl_log_1 data.... >
insert into "_replication".sl_log_1 (log_origin, log_xid,
log_tableid, log_actionseq, log_cmdtype, log_cmddata) values
('1', '255888045', '21', '7865734', 'U',
insert into "_replication".sl_log_1 (log_origin, log_xid,
log_tableid, log_actionseq, log_cmdtype, log_cmddata) values
('1', '255888049', '21', '7865735', 'U',
insert into "_replication".sl_log_1 (log_origin, log_xid,
log_tableid, log_actionseq, log_cmdtype, log_cmddata) values
('1', '255888048', '153', '7865736', 'I',
------------ data from sl_log_1 being processed
2006-01-31 20:11:30 PST 17563 32022 LOG: duration: 0.604 ms
2006-01-31 20:11:30 PST 17563 32023 LOG: statement:
update only "public".
update only "public".
insert into "public". < huge sql statements from sl_log_1... >
update only "public".
update only "public".
update only "public".
insert into "public".
-------------- interim activity (nothing has been removed )
2006-01-31 20:11:30 PST 17563 32024 LOG: duration: 23.090 ms
2006-01-31 20:11:30 PST 17563 32025 LOG: statement: update
"_replication".sl_setsync set ssy_seqno = '208362', ssy_minxid =
'255887638', ssy_maxxid = '255888058', ssy_xip =
'''255887852'',''255888056'',''255888055'',''255888054'',''255888052'',''255888007'',''255888040'',''255887638''',
ssy_action_list = '' where ssy_setid in (1,175) and ssy_seqno < '208362';
2006-01-31 20:11:30 PST 17563 32026 LOG: duration: 0.570 ms
2006-01-31 20:11:30 PST 17563 32027 LOG: statement: insert into
"_replication".sl_seqlog (seql_seqid, seql_origin, seql_ev_seqno,
seql_last_value) values (0, 1, '208362', '1000000000000000');
2006-01-31 20:11:30 PST 17563 32028 LOG: duration: 0.126 ms
2006-01-31 20:11:30 PST 17563 32029 LOG: statement: notify
"_replication_Event"; notify "_replication_Confirm"; insert into
"_replication".sl_event (ev_origin, ev_seqno, ev_timestamp, ev_minxid,
ev_maxxid, ev_xip, ev_type ) values ('1', '208362', '2006-01-31
20:11:30.401831', '255887638', '255888058',
'''255887852'',''255888056'',''255888055'',''255888054'',''255888052'',''255888007'',''255888040'',''255887638''',
'SYNC'); insert into "_replication".sl_confirm (con_origin,
con_received, con_seqno, con_timestamp) values (1, 2, '208362', now());
commit transaction;
2006-01-31 20:11:30 PST 17563 32030 LOG: duration: 11.882 ms
2006-01-31 20:11:30 PST 17563 32031 LOG: statement: begin transaction; set
transaction isolation level serializable;
2006-01-31 20:11:30 PST 17563 32032 LOG: duration: 0.194 ms
2006-01-31 20:11:30 PST 17563 32033 LOG: statement: select SSY.ssy_setid,
SSY.ssy_seqno, SSY.ssy_minxid, SSY.ssy_maxxid, SSY.ssy_xip,
SSY.ssy_action_list from "_replication".sl_setsync SSY where SSY.ssy_seqno <
'208363' and SSY.ssy_setid in (1,175);
2006-01-31 20:11:30 PST 17563 32034 LOG: duration: 0.473 ms
2006-01-31 20:11:30 PST 17563 32035 LOG: statement: select T.tab_id,
T.tab_set, "_replication".slon_quote_input('"' || PGN.nspname || '"."' ||
PGC.relname || '"') as tab_fqname from "_replication".sl_table T,
"pg_catalog".pg_class PGC, "pg_catalog".pg_namespace PGN where T.tab_set =
175 and PGC.oid = T.tab_reloid and PGC.relnamespace = PGN.oid;
2006-01-31 20:11:30 PST 17563 32036 LOG: duration: 0.666 ms
2006-01-31 20:11:30 PST 17563 32037 LOG: statement: select T.tab_id,
T.tab_set, "_replication".slon_quote_input('"' || PGN.nspname || '"."' ||
PGC.relname || '"') as tab_fqname from "_replication".sl_table T,
"pg_catalog".pg_class PGC, "pg_catalog".pg_namespace PGN where T.tab_set =
1 and PGC.oid = T.tab_reloid and PGC.relnamespace = PGN.oid;
2006-01-31 20:11:30 PST 17563 32038 LOG: duration: 4.618 ms
2006-01-31 20:11:30 PST 17562 4725 LOG: statement: start transaction; set
transaction isolation level serializable;
2006-01-31 20:11:30 PST 17562 4726 LOG: duration: 0.072 ms
2006-01-31 20:11:30 PST 17562 4727 LOG: statement: select ev_seqno,
ev_timestamp, ev_minxid, ev_maxxid, ev_xip, ev_type,
ev_data1, ev_data2, ev_data3, ev_data4, ev_data5, ev_data6, ev_data7,
ev_data8 from "_replication".sl_event where ev_origin = '2' and
ev_seqno > '26565' order by ev_seqno
2006-01-31 20:11:30 PST 17601 2911 LOG: statement: select ev_origin,
ev_seqno, ev_timestamp, ev_minxid, ev_maxxid, ev_xip, ev_type,
ev_data1, ev_data2, ev_data3, ev_data4, ev_data5, ev_data6,
ev_data7, ev_data8 from "_replication".sl_event e where (e.ev_origin = '2'
and e.ev_seqno > '26565') order by e.ev_origin, e.ev_seqno
2006-01-31 20:11:30 PST 17601 2912 LOG: duration: 0.384 ms
2006-01-31 20:11:30 PST 17601 2913 LOG: statement: select con_origin,
con_received, max(con_seqno) as con_seqno, max(con_timestamp) as
con_timestamp from "_replication".sl_confirm where con_received <> 1 group by
con_origin, con_received
2006-01-31 20:11:30 PST 17562 4728 LOG: duration: 0.975 ms
2006-01-31 20:11:30 PST 17562 4729 LOG: statement: rollback transaction;
2006-01-31 20:11:30 PST 17562 4730 LOG: duration: 0.061 ms
2006-01-31 20:11:30 PST 17601 2914 LOG: duration: 1.417 ms
2006-01-31 20:11:31 PST 17563 32039 LOG: statement: update
"_replication".sl_setsync set ssy_seqno = '208363', ssy_minxid =
'255887638', ssy_maxxid = '255888041', ssy_xip =
'''255887852'',''255888034'',''255888038'',''255888030'',''255888007'',''255888039'',''255887638''',
ssy_action_list = '' where ssy_setid in (1,175) and ssy_seqno < '208363';
2006-01-31 20:11:31 PST 17563 32040 LOG: duration: 0.429 ms
2006-01-31 20:11:31 PST 17563 32041 LOG: statement: insert into
"_replication".sl_seqlog (seql_seqid, seql_origin, seql_ev_seqno,
seql_last_value) values (0, 1, '208363', '1000000000000000');
2006-01-31 20:11:31 PST 17563 32042 LOG: duration: 0.093 ms
2006-01-31 20:11:31 PST 17563 32043 LOG: statement: notify
"_replication_Event"; notify "_replication_Confirm"; insert into
"_replication".sl_event (ev_origin, ev_seqno, ev_timestamp, ev_minxid,
ev_maxxid, ev_xip, ev_type ) values ('1', '208363', '2006-01-31
20:11:30.319947', '255887638', '255888041',
'''255887852'',''255888034'',''255888038'',''255888030'',''255888007'',''255888039'',''255887638''',
'SYNC'); insert into "_replication".sl_confirm (con_origin, con_received,
con_seqno, con_timestamp) values (1, 2, '208363', now()); commit transaction;
2006-01-31 20:11:31 PST 17563 32044 LOG: duration: 1.067 ms
2006-01-31 20:11:31 PST 17563 32045 LOG: statement: begin transaction; set
transaction isolation level serializable; lock table
"_replication".sl_config_lock; select "_replication".mergeSet_int(1, 175);
notify "_replication_Event"; notify "_replication_Confirm"; insert into
"_replication".sl_event (ev_origin, ev_seqno, ev_timestamp, ev_minxid,
ev_maxxid, ev_xip, ev_type , ev_data1, ev_data2 ) values ('1', '208364',
'2006-01-31 20:11:30.319947', '255887638', '255888041',
'''255887852'',''255888034'',''255888038'',''255888030'',''255888007'',''255888039'',''255887638''',
'MERGE_SET', '1', '175'); insert into "_replication".sl_confirm
(con_origin, con_received, con_seqno, con_timestamp) values (1, 2, '208364',
now()); commit transaction;
2006-01-31 20:11:31 PST 17562 4731 LOG: statement: start transaction; set
transaction isolation level serializable;
2006-01-31 20:11:31 PST 17562 4732 LOG: duration: 0.094 ms
2006-01-31 20:11:31 PST 17562 4733 LOG: statement: select ev_seqno,
ev_timestamp, ev_minxid, ev_maxxid, ev_xip, ev_type,
ev_data1, ev_data2, ev_data3, ev_data4, ev_data5, ev_data6, ev_data7,
ev_data8 from "_replication".sl_event where ev_origin = '2' and
ev_seqno > '26565' order by ev_seqno
2006-01-31 20:11:31 PST 17562 4734 LOG: duration: 1.034 ms
2006-01-31 20:11:31 PST 17562 4735 LOG: statement: rollback transaction;
2006-01-31 20:11:31 PST 17562 4736 LOG: duration: 0.087 ms
2006-01-31 20:11:31 PST 17563 32046 LOG: duration: 14.967 ms
2006-01-31 20:11:31 PST 17562 4737 LOG: statement: start transaction; set
transaction isolation level serializable;
2006-01-31 20:11:31 PST 17562 4738 LOG: duration: 0.064 ms
2006-01-31 20:11:31 PST 17562 4739 LOG: statement: select ev_seqno,
ev_timestamp, ev_minxid, ev_maxxid, ev_xip, ev_type,
ev_data1, ev_data2, ev_data3, ev_data4, ev_data5, ev_data6, ev_data7,
ev_data8 from "_replication".sl_event where ev_origin = '2' and
ev_seqno > '26565' order by ev_seqno
2006-01-31 20:11:31 PST 17601 2915 LOG: statement: select ev_origin,
ev_seqno, ev_timestamp, ev_minxid, ev_maxxid, ev_xip, ev_type,
ev_data1, ev_data2, ev_data3, ev_data4, ev_data5, ev_data6,
ev_data7, ev_data8 from "_replication".sl_event e where (e.ev_origin = '2'
and e.ev_seqno > '26565') order by e.ev_origin, e.ev_seqno
2006-01-31 20:11:31 PST 17601 2916 LOG: duration: 0.386 ms
2006-01-31 20:11:31 PST 17601 2917 LOG: statement: select con_origin,
con_received, max(con_seqno) as con_seqno, max(con_timestamp) as
con_timestamp from "_replication".sl_confirm where con_received <> 1 group by
con_origin, con_received
2006-01-31 20:11:31 PST 17562 4740 LOG: duration: 1.020 ms
2006-01-31 20:11:31 PST 17562 4741 LOG: statement: rollback transaction;
2006-01-31 20:11:31 PST 17562 4742 LOG: duration: 0.083 ms
2006-01-31 20:11:31 PST 17601 2918 LOG: duration: 1.270 ms
2006-01-31 20:11:31 PST 17563 32047 LOG: statement: begin transaction; set
transaction isolation level serializable;
2006-01-31 20:11:31 PST 17563 32048 LOG: duration: 0.103 ms
2006-01-31 20:11:31 PST 17563 32049 LOG: statement: select SSY.ssy_setid,
SSY.ssy_seqno, SSY.ssy_minxid, SSY.ssy_maxxid, SSY.ssy_xip,
SSY.ssy_action_list from "_replication".sl_setsync SSY where SSY.ssy_seqno <
'208365' and SSY.ssy_setid in (1);
2006-01-31 20:11:31 PST 17563 32050 LOG: duration: 0.361 ms
2006-01-31 20:11:31 PST 17563 32051 LOG: statement: select T.tab_id,
T.tab_set, "_replication".slon_quote_input('"' || PGN.nspname || '"."' ||
PGC.relname || '"') as tab_fqname from "_replication".sl_table T,
"pg_catalog".pg_class PGC, "pg_catalog".pg_namespace PGN where T.tab_set =
1 and PGC.oid = T.tab_reloid and PGC.relnamespace = PGN.oid;
2006-01-31 20:11:31 PST 17563 32052 LOG: duration: 4.538 ms
2006-01-31 20:11:31 PST 17564 4847 LOG: statement: start transaction;set
transaction isolation level serializable;select last_value from
"_replication".sl_action_seq;
2006-01-31 20:11:31 PST 17564 4848 LOG: duration: 0.216 ms
2006-01-31 20:11:31 PST 17564 4849 LOG: statement: rollback transaction;
2006-01-31 20:11:31 PST 17564 4850 LOG: duration: 0.066 ms
----------- now the all but one sl_log_1 entries are re-fetched
2006-01-31 20:11:31 PST 17563 32053 LOG: statement:
insert into "_replication".sl_log_1 (log_origin, log_xid,
log_tableid, log_actionseq, log_cmdtype, log_cmddata) values
('1', '255888034', '21', '7865731', 'U',
insert into "_replication".sl_log_1 (log_origin, log_xid,
log_tableid, log_actionseq, log_cmdtype, log_cmddata) values
('1', '255888039', '24', '7865732', 'I',
insert into "_replication".sl_log_1 (log_origin, log_xid,
log_tableid, log_actionseq, log_cmdtype, log_cmddata) values
('1', '255888041', '24', '7865733', 'U',
insert into "_replication".sl_log_1 (log_origin, log_xid,
log_tableid, log_actionseq, log_cmdtype, log_cmddata) values
('1', '255888045', '21', '7865734', 'U',
insert into "_replication".sl_log_1 (log_origin, log_xid,
log_tableid, log_actionseq, log_cmdtype, log_cmddata) values
('1', '255888049', '21', '7865735', 'U',
insert into "_replication".sl_log_1 (log_origin, log_xid,
log_tableid, log_actionseq, log_cmdtype, log_cmddata) values
('1', '255888048', '153', '7865736', 'I',
insert into "_replication".sl_log_1 (log_origin, log_xid,
log_tableid, log_actionseq, log_cmdtype, log_cmddata) values
('1', '255888052', '23', '7865737', 'U',
insert into "_replication".sl_log_1 (log_origin, log_xid,
log_tableid, log_actionseq, log_cmdtype, log_cmddata) values
('1', '255888054', '24', '7865738', 'U',
insert into "_replication".sl_log_1 (log_origin, log_xid,
log_tableid, log_actionseq, log_cmdtype, log_cmddata) values
('1', '255888052', '156', '7865739', 'U',
insert into "_replication".sl_log_1 (log_origin, log_xid,
log_tableid, log_actionseq, log_cmdtype, log_cmddata) values
('1', '255888056', '21', '7865740', 'U',
2006-01-31 20:11:31 PST 17563 32054 LOG: duration: 0.932 ms
----------- and are re-performed
2006-01-31 20:11:31 PST 17563 32055 LOG: statement:
update only "public".
insert into "public".
update only "public".
update only "public".
update only "public". < huge sql statements from sl_log_1... >
insert into "public".
update only "public".
update only "public".
update only "public".
update only "public".
----------- boom
2006-01-31 20:11:31 PST 17563 32056 ERROR: duplicate key violates unique
constraint
2006-01-31 20:11:31 PST 17563 32057 LOG: statement: rollback transaction
2006-01-31 20:11:31 PST 17563 32058 LOG: duration: 0.036 ms
2006-01-31 20:11:32 PST 17564 4851 LOG: statement: start transaction;set
transaction isolation level serializable;select last_value from
"_replication".sl_action_seq;
2006-01-31 20:11:32 PST 17564 4852 LOG: duration: 0.227 ms
:
_______________________________________________
Slony1-general mailing list
[email protected]
http://gborg.postgresql.org/mailman/listinfo/slony1-general
