PostgreSQL 8.1.2 on i386-portbld-freebsd6.0, compiled by GCC cc (GCC)
3.4.4 [FreeBSD] 20050518
We have triggers on each of our tables that create audit table entries
on each insert/update/delete.
The audit table (in addition to containing information about the change
that was made) contains a timestamp field and a serial as the primary key.
The timestamp is generated by calling now() inside the audit trigger, so
should contain the timestamp of when the transaction (that yielded the
insert/update/delete) began.
We have a single (and very important) table that we perform the majority
of our operations on..I'll simplify the definition of the table to this:
CREATE TABLE thetable
(
id int8 NOT NULL DEFAULT nextval('thetable_id_seq'::regclass),
flag char(1) NOT NULL,
state char(8) NOT NULL
}
we have a scenario where a batch process takes records from this table
in a certain state and one by one, moves them to a new state.
update thetable set state='COMPLETE', flag='X' where state='INITIAL' and
id=?
Another batch process is looking for any records in that new state...and
then updates certain elements of it.
update thetable set flag='Y' where id in (select id from thetable where
state='COMPLETE')
This update statement is run as it's own transaction (there is nothing
else done in the transaction).
The audit logs for some transactions show something very odd.
For example, for id 210210 we have an audit trail that looks like this...
audit_id record_id when column old_val
new_val
-------- ----------- -------------- ------- -------
-------
1 210210 2006-04-20 12:49:03.92 state INITIAL
COMPLETE
2 210210 2006-04-20 12:49:03.74 flag X Y
By looking at the timestamps, the second update started BEFORE the first
update even though the second update cannot occur if the state hasn't
been changed and committed by the first one!
Even weirder is that the order of the sequence (audit_id) shows them
occurring in the opposite order....
Am I missing something obvious here?