Обсуждение: currval() race condition on server?

Hi,

    I've run into an intermittent problem with our code recently. We have
the following set-up:

table A : some data table
table B : a history table for table A

A trigger copies the old version of a row into table B whenever an
update is done on table A. Both A and B contain an audit number, and the
trigger obtains an audit number from a sequence and inserts it into the
row inserted into table A.

For some bookkeeping purposes I need the new audit number back from the
update, so I submit a prepared statement through jdbc of the form

UPDATE A SET ....; SELECT currval('ip_audit_seq');

On the first call I get

  ERROR: currval of sequence "ip_audit_seq" is not yet defined in this
session

Note that this works without any trouble if I issue the commands in a
transaction through psql, and this used to work in earlier versions of
postgres.

We have a lot of users on very high latency links, so it is important
for the responsiveness of the application to try to do the update and
select in a single database trip.

So I'm wondering whether there is some type of race condition, where the
selection of the new value from ip_audit_seq is not available to the
currval function straight away? Anybody got any ideas on this?

Cheers,

Adriaan

Στις Δευτέρα 23 Οκτώβριος 2006 16:49, ο/η Adriaan Joubert έγραψε:
> Hi,
>
>     I've run into an intermittent problem with our code recently. We have
> the following set-up:
>
> table A : some data table
> table B : a history table for table A
>
> A trigger copies the old version of a row into table B whenever an
> update is done on table A. Both A and B contain an audit number, and the
> trigger obtains an audit number from a sequence and inserts it into the
> row inserted into table A.

What do you mean here? Inserts it into the row inserted....

>
> For some bookkeeping purposes I need the new audit number back from the
> update, so I submit a prepared statement through jdbc of the form
>
> UPDATE A SET ....; SELECT currval('ip_audit_seq');
>
> On the first call I get
>
>   ERROR: currval of sequence "ip_audit_seq" is not yet defined in this
> session

That normally means that no nextval has been called on the sequence during the
session in question.
Can you give us the trigger code?

>
> Note that this works without any trouble if I issue the commands in a
> transaction through psql, and this used to work in earlier versions of
> postgres.
>

In any case double check that the server version/JDBC version match.

> We have a lot of users on very high latency links, so it is important
> for the responsiveness of the application to try to do the update and
> select in a single database trip.
>
> So I'm wondering whether there is some type of race condition, where the
> selection of the new value from ip_audit_seq is not available to the
> currval function straight away? Anybody got any ideas on this?
>
> Cheers,
>
> Adriaan
>
> ---------------------------(end of broadcast)---------------------------
> TIP 4: Have you searched our list archives?
>
>                http://archives.postgresql.org

--
Achilleas Mantzios

Adriaan Joubert <a.joubert@albourne.com> writes:
> For some bookkeeping purposes I need the new audit number back from the
> update, so I submit a prepared statement through jdbc of the form
>
> UPDATE A SET ....; SELECT currval('ip_audit_seq');

It's not possible to put two SQL commands into one prepared statement
--- at least not for the normal server-side meaning of "prepared statement".
I dunno what the JDBC driver is doing with this, but I wonder if it's
silently dropping the UPDATE part :-(

            regards, tom lane

On 23-Oct-06, at 9:49 AM, Adriaan Joubert wrote:

> Hi,
>
>     I've run into an intermittent problem with our code recently. We
> have the following set-up:
>
> table A : some data table
> table B : a history table for table A
>
> A trigger copies the old version of a row into table B whenever an
> update is done on table A. Both A and B contain an audit number,
> and the trigger obtains an audit number from a sequence and inserts
> it into the row inserted into table A.
>
> For some bookkeeping purposes I need the new audit number back from
> the update, so I submit a prepared statement through jdbc of the form
>
> UPDATE A SET ....; SELECT currval('ip_audit_seq');
>
> On the first call I get
>
>  ERROR: currval of sequence "ip_audit_seq" is not yet defined in
> this session
currval is only defined after you call nextval in that connection.
>
> Note that this works without any trouble if I issue the commands in
> a transaction through psql, and this used to work in earlier
> versions of postgres.
>
> We have a lot of users on very high latency links, so it is
> important for the responsiveness of the application to try to do
> the update and select in a single database trip.
>
> So I'm wondering whether there is some type of race condition,
> where the selection of the new value from ip_audit_seq is not
> available to the currval function straight away? Anybody got any
> ideas on this?

There is no race condition
>
> Cheers,
>
> Adriaan
>
> ---------------------------(end of
> broadcast)---------------------------
> TIP 4: Have you searched our list archives?
>
>               http://archives.postgresql.org
>

Dave Cramer wrote:
>
> On 23-Oct-06, at 9:49 AM, Adriaan Joubert wrote:
>
>> Hi,
>>
>>     I've run into an intermittent problem with our code recently. We
>> have the following set-up:
>>
>> table A : some data table
>> table B : a history table for table A
>>
>> A trigger copies the old version of a row into table B whenever an
>> update is done on table A. Both A and B contain an audit number, and
>> the trigger obtains an audit number from a sequence and inserts it
>> into the row inserted into table A.
>>
>> For some bookkeeping purposes I need the new audit number back from
>> the update, so I submit a prepared statement through jdbc of the form
>>
>> UPDATE A SET ....; SELECT currval('ip_audit_seq');
>>
>> On the first call I get
>>
>>  ERROR: currval of sequence "ip_audit_seq" is not yet defined in this
>> session
> currval is only defined after you call nextval in that connection.

Yes, and this is done in a C trigger that is called as a result of the
update (it is a BEFORE INSERT OR DELETE OR UPDATE ... trigger). The C
code does a

   /* Find a plan for getting the next sequence number */
   plan = find_plan(sequence_name, &ExecPlans, &nExecPlans);
   if (plan->splan == NULL) {
     sprintf(query, "SELECT nextval('%s')", sequence_name);
     /* Prepare plan for query */
     pplan = SPI_prepare(query, 0, NULL);
     if (pplan == NULL)
       elog(ERROR, "audit(%s): SPI_prepare returned %d",
       sequence_name, SPI_result);
     pplan = SPI_saveplan(pplan);
     if (pplan == NULL)
       elog(ERROR, "audit(%s): SPI_saveplan returned %d",
       sequence_name, SPI_result);
     plan->splan = pplan;
   }
   /* Execute the plan */
   ret = SPI_execp(plan->splan, NULL, NULL, 0);
   if (ret < 0)
     elog(ERROR, "audit(%s): SPI_execp returned %d", sequence_name, ret);
   /* Get the new sequence number */
   new_seq = (int) DatumGetInt64
     ( SPI_getbinval( SPI_tuptable->vals[0], SPI_tuptable->tupdesc,
             1, &isnull) );


The update part of the trigger then inserts the sequence number into the
row (new_tuple being the tuple that is passed into the trigger)

     newtuple = SPI_modifytuple(rel, newtuple, 1, &i_audit,
                   (Datum *) &new_seq, NULL);

which puts the sequence number into the relation. As this is in a BEFORE
trigger, I would have through that it should be available to currval
before executing the second statement in the query.


As to Tom's question: the jdbc driver is executing the update without
any problems. On the java side I can do an

    PreparedStatement st = connection.prepareStatement(...);
    ...
    st.execute();
    nUpdated = st.getUpdateCount();
          if (nUpdated == 1 && st.getMoreResults()) {
                 ResultSet rs = st.getResultSet();
                 if (rs.next()) {
                     oldAudit_ = audit_;
                     setAudit(rs.getInt(1));
                 }
         }
         st.close();

which works well. So the real question is why currval is not working
even though the update succeeds? Or rather - the update does not
succeed, as the transaction is rolled back, but if I try to do the same
thing a second time it does.

Perhaps the assumption that the update has succeeded is incorrect - but
then, if the update statement fails, it should never attempt to execute
the SELECT currval(), should it? Certainly in updates that fail we do
not get an error from the SELECT currval().

Thanks for all your responses!

Adriaan

Tom Lane wrote:
> Adriaan Joubert <a.joubert@albourne.com> writes:
>
>>For some bookkeeping purposes I need the new audit number back from the
>>update, so I submit a prepared statement through jdbc of the form
>>
>>UPDATE A SET ....; SELECT currval('ip_audit_seq');
>
>
> It's not possible to put two SQL commands into one prepared statement
> --- at least not for the normal server-side meaning of "prepared statement".
> I dunno what the JDBC driver is doing with this, but I wonder if it's
> silently dropping the UPDATE part :-(

The driver should split this query on the semicolons and send
Parse/Bind/Execute for each part, followed by a Sync at the end. If it
ends up using named statements due to JDBC statement reuse, it should
use a different name for each part. Of course there might be unknown
bugs in there, but it has been designed to handle this sort of compound
statement..

To the OP: Is autocommit on or off? Can you reproduce the problem with a
URL parameter of loglevel=2 and see what it looks like? (that'll
generate a trace protocol-level messages)

-O

Oliver Jowett wrote:

> The driver should split this query on the semicolons and send
> Parse/Bind/Execute for each part, followed by a Sync at the end. If it
> ends up using named statements due to JDBC statement reuse, it should
> use a different name for each part. Of course there might be unknown
> bugs in there, but it has been designed to handle this sort of compound
> statement..
>
> To the OP: Is autocommit on or off? Can you reproduce the problem with a
> URL parameter of loglevel=2 and see what it looks like? (that'll
> generate a trace protocol-level messages)

autocommit is off.

I have not been able to reproduce this with logging on - even with
logging off the problem only occurs intermittently. Looking at the
output from the trace everything seems to happen as expected - see trace
below. Yet we are getting a few of these errors in our logs every day -
obviously only the first time we ask for the value of the sequence back.
Scary thought is that may be getting an older value back in other
instances. It feels an awful lot like a timing issue where the sequence
number is retrieved, but there is a delay until currval can use it. I'm
not sure how currval works.

I will continue to try to reproduce this with more logging, but would
appreciate any ideas.

Thanks!

Adriaan

<=BE CommandStatus(BEGIN)
  <=BE ParseComplete [null]
  <=BE BindComplete [null]
  <=BE RowDescription(1)
  <=BE DataRow
  <=BE CommandStatus(SELECT)
  <=BE ReadyForQuery(T)
simple execute,
handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@87e9bf,
maxRows=0, fetchSize=0, flags=1
  FE=> Parse(stmt=null,query="UPDATE prm SET ... AND
_audit=$16",oids={23,23,701,23,701,23,23,0,701,701,701,0,0,23,23,23})
  FE=>

Bind(stmt=null,portal=null,$1=<421>,$2=<1>,$3=<0.21927195726630877>,$4=<18>,$5=<0.376345008550404>,$6=<2>,$7=<1>,$8=<NULL>,$9=<0.045037791453060014>,$10=<0.020180805785169714>,$11=<1.0>,$12=<NULL>,$13=<NULL>,$14=<387>,$15=<435>,$16=<3382993>)
  FE=> Describe(portal=null)
  FE=> Execute(portal=null,limit=0)
  FE=> Parse(stmt=null,query=" SELECT currval('ip_audit_seq')",oids={})
  FE=> Bind(stmt=null,portal=null)
  FE=> Describe(portal=null)
  FE=> Execute(portal=null,limit=0)
  FE=> Sync
  <=BE ParseComplete [null]
  <=BE BindComplete [null]
  <=BE NoData
  <=BE CommandStatus(UPDATE 1)
  <=BE ParseComplete [null]
  <=BE BindComplete [null]
  <=BE RowDescription(1)
  <=BE DataRow
  <=BE CommandStatus(SELECT)
  <=BE ReadyForQuery(T)
simple execute,
handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler@1033450,
maxRows=0, fetchSize=0, flags=22
  FE=> Bind(stmt=S_2,portal=null)
  FE=> Execute(portal=null,limit=1)
  FE=> Sync
  <=BE BindComplete [null]
  <=BE CommandStatus(COMMIT)
  <=BE ReadyForQuery(I)

On 24-Oct-06, at 3:37 AM, Adriaan Joubert wrote:

> Oliver Jowett wrote:
>
>> The driver should split this query on the semicolons and send
>> Parse/Bind/Execute for each part, followed by a Sync at the end.
>> If it ends up using named statements due to JDBC statement reuse,
>> it should use a different name for each part. Of course there
>> might be unknown bugs in there, but it has been designed to handle
>> this sort of compound statement..
>> To the OP: Is autocommit on or off? Can you reproduce the problem
>> with a URL parameter of loglevel=2 and see what it looks like?
>> (that'll generate a trace protocol-level messages)
>
> autocommit is off.
>
> I have not been able to reproduce this with logging on - even with
> logging off the problem only occurs intermittently. Looking at the
> output from the trace everything seems to happen as expected - see
> trace below. Yet we are getting a few of these errors in our logs
> every day - obviously only the first time we ask for the value of
> the sequence back. Scary thought is that may be getting an older
> value back in other instances. It feels an awful lot like a timing
> issue where the sequence number is retrieved, but there is a delay
> until currval can use it. I'm not sure how currval works.

currval works like this:

When you execute nextval('sequence_name') the result of that is
stored in your session. A session lives as long as this connection is
alive. If nextval('sequence_name') has not  been called in this
session then currval('sequence_name') is undefined.

Hopefully this helps

Dave
>
> I will continue to try to reproduce this with more logging, but
> would appreciate any ideas.
>
> Thanks!
>
> Adriaan
>
> <=BE CommandStatus(BEGIN)
>  <=BE ParseComplete [null]
>  <=BE BindComplete [null]
>  <=BE RowDescription(1)
>  <=BE DataRow
>  <=BE CommandStatus(SELECT)
>  <=BE ReadyForQuery(T)
> simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement
> $StatementResultHandler@87e9bf, maxRows=0, fetchSize=0, flags=1
>  FE=> Parse(stmt=null,query="UPDATE prm SET ... AND _audit=
> $16",oids={23,23,701,23,701,23,23,0,701,701,701,0,0,23,23,23})
>  FE=> Bind(stmt=null,portal=null,$1=<421>,$2=<1>,
> $3=<0.21927195726630877>,$4=<18>,$5=<0.376345008550404>,$6=<2>,
> $7=<1>,$8=<NULL>,$9=<0.045037791453060014>,
> $10=<0.020180805785169714>,$11=<1.0>,$12=<NULL>,$13=<NULL>,
> $14=<387>,$15=<435>,$16=<3382993>)
>  FE=> Describe(portal=null)
>  FE=> Execute(portal=null,limit=0)
>  FE=> Parse(stmt=null,query=" SELECT currval('ip_audit_seq')",oids={})
>  FE=> Bind(stmt=null,portal=null)
>  FE=> Describe(portal=null)
>  FE=> Execute(portal=null,limit=0)
>  FE=> Sync
>  <=BE ParseComplete [null]
>  <=BE BindComplete [null]
>  <=BE NoData
>  <=BE CommandStatus(UPDATE 1)
>  <=BE ParseComplete [null]
>  <=BE BindComplete [null]
>  <=BE RowDescription(1)
>  <=BE DataRow
>  <=BE CommandStatus(SELECT)
>  <=BE ReadyForQuery(T)
> simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Connection
> $TransactionCommandHandler@1033450, maxRows=0, fetchSize=0, flags=22
>  FE=> Bind(stmt=S_2,portal=null)
>  FE=> Execute(portal=null,limit=1)
>  FE=> Sync
>  <=BE BindComplete [null]
>  <=BE CommandStatus(COMMIT)
>  <=BE ReadyForQuery(I)
>
> ---------------------------(end of
> broadcast)---------------------------
> TIP 6: explain analyze is your friend
>

Adriaan Joubert <a.joubert@albourne.com> writes:
> It feels an awful lot like a timing issue where the sequence
> number is retrieved, but there is a delay until currval can use it. I'm
> not sure how currval works.

There is no "timing issue" in currval --- the server is single-threaded
and it's simply not possible that currval wouldn't be aware of a
previous nextval.

The theory that sounds best to me is the one someone already mentioned
about your trigger having a code path that doesn't execute nextval.
Another straw to grasp at is connection pooling: are you using it,
if so is it conceivable that the SELECT is being issued on a different
connection than the UPDATE?

            regards, tom lane

On 24-Oct-06, at 10:18 AM, Tom Lane wrote:

> Adriaan Joubert <a.joubert@albourne.com> writes:
>> It feels an awful lot like a timing issue where the sequence
>> number is retrieved, but there is a delay until currval can use
>> it. I'm
>> not sure how currval works.

Additionally since there is some confusion about how currval actually
works you need to be aware that currval is not necessarily the
current value of the sequence. It is the last value returned by
nextval for that connection. So what's the difference?

1) sequence = 1

2) con1 ->nextval .. sequence=2 currval = 2 for con1

3)con2 -> nextval .. sequence = 3 currval=3 for con2

4) now unless nextval is called again in connection 1 currval  will
still return  2

Dave
>
> There is no "timing issue" in currval --- the server is single-
> threaded
> and it's simply not possible that currval wouldn't be aware of a
> previous nextval.
>
> The theory that sounds best to me is the one someone already mentioned
> about your trigger having a code path that doesn't execute nextval.
> Another straw to grasp at is connection pooling: are you using it,
> if so is it conceivable that the SELECT is being issued on a different
> connection than the UPDATE?
>
>             regards, tom lane
>
> ---------------------------(end of
> broadcast)---------------------------
> TIP 9: In versions below 8.0, the planner will ignore your desire to
>        choose an index scan if your joining column's datatypes do not
>        match
>