Logged statement apparently did not commited...

From: Ioana Danes <ioanasoftware@yahoo.ca>
Subject: [GENERAL] Logged statement apparently did not commited...
To: pgsql-general@postgresql.org
Received: Friday, February 18, 2011, 1:43 PM
Hello Everyone,

I would like to kindly ask for your help regarding a
strange situation I meet yesterday. It might not be a
postgres issue but I run out of ideas on what to test or
check and so far I could not reproduce the behavior.

I have 2 (master - slave) postgres 9.0.3 databases running
on SLES 11 PATCHLEVEL 1 (x86_64). For the slave I am using a
statement based replication (terracotta)...

I have a cron that runs at 1:00am and checks if the dbs are
in sync (it exports the data on a text file and makes a diff
on the files generated on the 2 dbs).

2 days ago I've got differences for a table and I started
to investigate the problem.

Postgres log is enabled on both dbs and I could compare the
statements. The same statements appear in postgres log on
both dbs in the same order, no errors or weird stuff. So the
dbs should be in sync.

That table holds temporary information for an item. So
there are inserts and updates on that table for an item
(key1) and whenever that item expires all the data for that
item gets deleted:

insert into mytable (key1, key2, keyval) values (1019, 1,
50);
insert into mytable (key1, key2, keyval) values (1019, 2,
100);
insert into mytable (key1, key2, keyval) values (1019, 3,
10);
update mytable set keyval = 51 where key1 =1019 and key2 =
1;
update mytable set keyval = 102 where key1 =1019 and key2 =
2;
insert into mytable (key1, key2, keyval) values (1019, 4,
10);
...
delete from mytable where key1 = 1019;

From the script that compares the 2 dbs it looks like the
delete statement for a particular item did not commited on
the slave. On the master there were no records for the item
with key1 = 1019 but on db2 there were all the records
generated by the insert and update statements....(I did
extracted the insert and update statement from the log and
it is exactly what the difference is). So it looks pretty
clear that the delete did not commited on the slave. The
delete statement appears in postgres log with begin and
commit transaction and no errors.

The autovacuum is on and it gives a little information on
what happened between 2 autovacuums:

before autovacuum there are 19 records in the key table for
key1= 1019

first autovacuum:
2011-02-16 13:12:41.088
CST,,,10691,,4d5c21a9.29c3,1,,2011-02-16 13:12:41
CST,5/9551,0,LOG,00000,"automatic vacuum of table ""..."":
index scans: 1
pages: 0 removed, 1 remain
tuples: 65 removed, 19 remain

between the autovacuums there are:

14 inserts for key1 = 1019
47 updates for key1 = 1019

25 inserts for key1 = 1021
98 updates for key1 = 1021

33 records deleted for key1 = 1019

the second autovacuum:
2011-02-16 13:52:20.358
CST,,,10868,,4d5c2af4.2a74,1,,2011-02-16 13:52:20
CST,5/9795,0,LOG,00000,"automatic vacuum of table ""..."":
index scans: 1
pages: 0 removed, 2 remain
tuples: 98 removed, 58 remain

It looks like autovacuum only removed the dead tuples
generated by the 98 updates on key 1021 and none of the dead
tuples generated by the update and delete on item 1019...

Can this be on any help? Does anyone have an idea where
else to look for clues?

Thank you for your time,
Ioana

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general