Thread: Odd transaction timestamp sequence issue

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?

Jeff Amiel <jamiel@istreamimaging.com> writes:
> 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!

How is the "when" column determined?  You did not show it in your SQL
commands.

If it's being driven off now() or CURRENT_TIMESTAMP, then the above
isn't all that surprising, because the value is the time of transaction
start not the time at which the update was made.

            regards, tom lane

On Fri, Apr 21, 2006 at 09:43:55AM -0500, Jeff Amiel wrote:
> 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.

now() returns the same time throughout the transaction i.e. the
transaction start time. If you want a time independant of transaction
status, perhaps you want timeofday(). Check the docs for the specifics.

Have a nice day,
--
Martijn van Oosterhout   <kleptog@svana.org>   http://svana.org/kleptog/
> From each according to his ability. To each according to his ability to litigate.

it is done using now()....
But what I don't understand is how the transaction that started first
could 'see' the record that hadn't been changed yet by the initial
update to 'COMPLETE'?
I thought:
"Each transaction sees a snapshot (database version) as of its
starttime, no matter what other transactions are doing while it runs"


> How is the "when" column determined?  You did not show it in your SQL
> commands.
>
> If it's being driven off now() or CURRENT_TIMESTAMP, then the above
> isn't all that surprising, because the value is the time of transaction
> start not the time at which the update was made.
>
>

Jeff Amiel <jamiel@istreamimaging.com> writes:
> I thought:
> "Each transaction sees a snapshot (database version) as of its
> starttime, no matter what other transactions are doing while it runs"

That's a correct statement in SERIALIZABLE mode, but in the default
READ COMMITTED mode, it's more complicated --- a new snapshot is taken
for each command within a transaction.  See the docs.

            regards, tom lane