Thread: Hibernate, JBoss, PostgreSQL, timestamp read doesn't match during update

I have no idea where to point the blame on this one.  I have a
workaround, but here's the scenario.

I have a timestamp column which I want to use in JBoss/Hibernate as a
"version" column so that Hibernate can do opportunistic locking for
updates.  The timestamp is actually generated by a trigger on the
table.  Here's an edited down copy of the DDL for the table and trigger:

  CREATE TABLE security (
    id                        SERIAL,
    primary_identifier        VARCHAR(10) NOT NULL,
    ...
    active_on                 TIMESTAMP(3),
  );

  DROP FUNCTION security_biur_trg() CASCADE;

  CREATE FUNCTION security_biur_trg() RETURNS TRIGGER AS $$
      BEGIN
          NEW.active_on := CURRENT_TIMESTAMP AT TIME ZONE 'UTC';
          RETURN NEW;
      END;
  $$ LANGUAGE plpgsql;

  CREATE TRIGGER security_biur BEFORE INSERT OR UPDATE
      ON security FOR EACH ROW
      EXECUTE PROCEDURE security_biur_trg();

I have a custom UserVersionType for Hibernate to allow it to treat the
column as a version object.  You can see the full post of my code at
http://www.hibernate.org/461.html.  The code does work with one caveat
that I will come to shortly.

The Hibernate mapping file for this table is
  <?xml version="1.0"?>
  <!DOCTYPE hibernate-mapping PUBLIC
          "-//Hibernate/Hibernate Mapping DTD 3.0//EN"
          "http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd">

  <hibernate-mapping>
    <class name="Security">
      <id name="securityId" column="id" type="long" unsaved-value="null">
        <generator class="sequence">
          <param name="sequence">security_id_seq</param>
        </generator>
      </id>
      <natural-id>
        <property name="primaryIdentifier"
                  column="primary_identifier"
                  type="string"/>
      </natural-id>
      <version name="activeOn"
               column="active_on"
               type="HibernateUTC$TimestampType"
               generated="always"
               insert="false"
               unsaved-value="null"/>
      ...
    </class>
  </hibernate-mapping>

What happens when I actually try to update a row is described in more
detail here, http://forum.hibernate.org/viewtopic.php?p=2409286#2409286,
but the short answer is that Hibernate thinks the row has been updated
by another transaction.  After trying all sorts of different mapping
definitions for the active_on column (including letting Hibernate
generate the values, which sort-of works), I finally hit upon a simple
column definition change that works around the problem:

  active_on timestamp(3)

Yes, restrict the timestamp to millisecond precision.  Somewhere the
sub-millisecond parts are getting lost.  I have no idea if it is in the
JDBC layer or somewhere in Hibernate.  Any clues on figuring this out?

Oh, the SQL generated by Hibernate puts both the primary key and the
active_on column in the "where" clause.  This is what it is supposed to
do and how it detects a row as having been updated by another
transaction.  In this case, the precision mismatch fools it.

roland

--
               PGP Key ID: 66 BC 3B CD
Roland B. Roberts, PhD                             RL Enterprises
roland@rlenter.com                            6818 Madeline Court
roland@astrofoto.org                           Brooklyn, NY 11220

You should not use a trigger to generate the version info for hibernate. You should use the application's time.

Dave

Dave Cramer wrote:
> You should not use a trigger to generate the version info for
> hibernate. You should use the application's time.
Then why bother having the generated atribute to version?  That flies in
the face of the design of *Hibernate* in allowing this.  Hibernate
*does* do the right thing in querying the column to get the value back
after the update.  You're telling me to not do what Hibernate explicitly
say I can do.  Why?

roland

--
               PGP Key ID: 66 BC 3B CD
Roland B. Roberts, PhD                             RL Enterprises
roland@rlenter.com                            6818 Madeline Court
roland@astrofoto.org                           Brooklyn, NY 11220

Roland Roberts wrote:

> Yes, restrict the timestamp to millisecond precision.  Somewhere the
> sub-millisecond parts are getting lost.  I have no idea if it is in the
> JDBC layer or somewhere in Hibernate.  Any clues on figuring this out?

Is the server built with integer_datetimes? Maybe you are just hitting a
rounding problem.

-O

Oliver Jowett wrote:
> Roland Roberts wrote:
>
>> Yes, restrict the timestamp to millisecond precision.  Somewhere the
>> sub-millisecond parts are getting lost.  I have no idea if it is in the
>> JDBC layer or somewhere in Hibernate.  Any clues on figuring this out?
>>
> Is the server built with integer_datetimes? Maybe you are just hitting a
> rounding problem.
>
Which server; do you mean PostgreSQL or JBoss?  I think you mean JBoss,
but I'm not sure how to check on that.  If you know, please share.  I'll
see what I can find out.

roland

--
               PGP Key ID: 66 BC 3B CD
Roland B. Roberts, PhD                             RL Enterprises
roland@rlenter.com                            6818 Madeline Court
roland@astrofoto.org                           Brooklyn, NY 11220

Roland Roberts wrote:
> Oliver Jowett wrote:
>> Roland Roberts wrote:
>>
>>> Yes, restrict the timestamp to millisecond precision.  Somewhere the
>>> sub-millisecond parts are getting lost.  I have no idea if it is in the
>>> JDBC layer or somewhere in Hibernate.  Any clues on figuring this out?
>>>
>> Is the server built with integer_datetimes? Maybe you are just hitting a
>> rounding problem.
>>
> Which server; do you mean PostgreSQL or JBoss?  I think you mean JBoss,
> but I'm not sure how to check on that.  If you know, please share.  I'll
> see what I can find out.

No, I mean the PostgreSQL server.

See http://www.postgresql.org/docs/8.3/static/datatype-datetime.html,
specifically this bit:

    Note:  When timestamp values are stored as double precision
floating-point numbers (currently the default), the effective limit of
precision might be less than 6. timestamp values are stored as seconds
before or after midnight 2000-01-01. Microsecond precision is achieved
for dates within a few years of 2000-01-01, but the precision degrades
for dates further away. When timestamp values are stored as eight-byte
integers (a compile-time option), microsecond precision is available
over the full range of values. However eight-byte integer timestamps
have a more limited range of dates than shown above: from 4713 BC up to
294276 AD. The same compile-time option also determines whether time and
interval values are stored as floating-point or eight-byte integers. In
the floating-point case, large interval values degrade in precision as
the size of the interval increases.

Try "SHOW integer_datetimes;" via psql to see how your server is configured.

-O

Oliver Jowett wrote:
> Roland Roberts wrote:
>
>> Oliver Jowett wrote:
>>
>>> Roland Roberts wrote:
>>>
>>>
>>>> Yes, restrict the timestamp to millisecond precision.  Somewhere the
>>>> sub-millisecond parts are getting lost.  I have no idea if it is in the
>>>> JDBC layer or somewhere in Hibernate.  Any clues on figuring this out?
>>>>
>>> Is the server built with integer_datetimes? Maybe you are just hitting a
>>> rounding problem.
>>>
>> Which server; do you mean PostgreSQL or JBoss?  I think you mean JBoss,
>> but I'm not sure how to check on that.  If you know, please share.  I'll
>> see what I can find out.
>>
> No, I mean the PostgreSQL server.
>
roland=# show integer_datetimes;
 integer_datetimes
-------------------
 off
(1 row)

When I use a trigger to set the timestamps, they show up with
microsecond precision.  The problem is that the extra precision is
definitely getting lost before Hibernate tries to put the value back.
The update looks more-or-less like

update mytable set col1=val1 where primary_key = pkval and
some_timestamp = timestamp_value

timestamp_value doesn't match what is in the database even though it was
retrieved by an earlier query.

I've got some more poking I can do.  Java doesn't seem to have a way of
printing microseconds for timestamps with, for example,
SimpleDateFormat, but I should be able to see if it can at least
retrieve them.

roland

--
               PGP Key ID: 66 BC 3B CD
Roland B. Roberts, PhD                             RL Enterprises
roland@rlenter.com                            6818 Madeline Court
roland@astrofoto.org                           Brooklyn, NY 11220

Roland Roberts wrote:
> I've got some more poking I can do.  Java doesn't seem to have a way
> of printing microseconds for timestamps with, for example,
> SimpleDateFormat, but I should be able to see if it can at least
> retrieve them.
I modified HibernateUTC$Timestamp, my UserVersionType class, to have it
use log4j to tell me exactly what the timestamp is immediates after the
rs.getTimestamp() call.  The extra precision is there.

20:01:21,756 INFO  [STDOUT] Hibernate: select security0_.id as id1_,
security0_.active_on as active2_1_, security0_.primary_identifier as
primary3_1_, security0_.identifier_type_code as identifier4_1_,
security0_.security_type_code as security5_1_, security0_.issue_name as
issue6_1_, security0_.issuer_name as issuer7_1_,
security0_.industry_name as industry8_1_, security0_.exchange_code as
exchange9_1_, security0_.mic_code as mic10_1_,
security0_.def_sector_code as def11_1_, security0_.icb4_code as
icb12_1_, security0_.def_gdr_security_id as def13_1_, security0_.is_live
as is14_1_, security0_.shares_outstanding as shares15_1_,
security0_.last_price_modified_time as last16_1_,
security0_.last_price_time as last17_1_,
security0_.last_price_validated_time as last18_1_,
security0_.active_until as active19_1_ from drpg.Security security0_
where primary_identifier=? limit ?
20:01:21,767 INFO  [HibernateUTC] got timestamp 2009-03-20
20:00:59.526338 nanos=526338000
20:01:21,768 INFO  [HibernateUTC] got timestamp 2009-03-20 20:00:59.6
nanos=600000000

I'm not through poking, but at least I know where the problem isn't.

roland

--
               PGP Key ID: 66 BC 3B CD
Roland B. Roberts, PhD                             RL Enterprises
roland@rlenter.com                            6818 Madeline Court
roland@astrofoto.org                           Brooklyn, NY 11220

Roland Roberts wrote:
> Roland Roberts wrote:
>> I've got some more poking I can do.  Java doesn't seem to have a way
>> of printing microseconds for timestamps with, for example,
>> SimpleDateFormat, but I should be able to see if it can at least
>> retrieve them.
> I modified HibernateUTC$Timestamp, my UserVersionType class, to have
> it use log4j to tell me exactly what the timestamp is immediates after
> the rs.getTimestamp() call.  The extra precision is there.
>
> 20:01:21,756 INFO  [STDOUT] Hibernate: select security0_.id as id1_,
> security0_.active_on as active2_1_, security0_.primary_identifier as
> primary3_1_, security0_.identifier_type_code as identifier4_1_,
> security0_.security_type_code as security5_1_, security0_.issue_name
> as issue6_1_, security0_.issuer_name as issuer7_1_,
> security0_.industry_name as industry8_1_, security0_.exchange_code as
> exchange9_1_, security0_.mic_code as mic10_1_,
> security0_.def_sector_code as def11_1_, security0_.icb4_code as
> icb12_1_, security0_.def_gdr_security_id as def13_1_,
> security0_.is_live as is14_1_, security0_.shares_outstanding as
> shares15_1_, security0_.last_price_modified_time as last16_1_,
> security0_.last_price_time as last17_1_,
> security0_.last_price_validated_time as last18_1_,
> security0_.active_until as active19_1_ from drpg.Security security0_
> where primary_identifier=? limit ?
> 20:01:21,767 INFO  [HibernateUTC] got timestamp 2009-03-20
> 20:00:59.526338 nanos=526338000
> 20:01:21,768 INFO  [HibernateUTC] got timestamp 2009-03-20 20:00:59.6
> nanos=600000000
>
> I'm not through poking, but at least I know where the problem isn't.
Aarrgh!  User error.  The application copies the timestamps inside the
setter by creating a new one:

myval = new Timestamp(old_timestamp.getTime());

which only copies down to the milliseconds.


roland

--
               PGP Key ID: 66 BC 3B CD
Roland B. Roberts, PhD                             RL Enterprises
roland@rlenter.com                            6818 Madeline Court
roland@astrofoto.org                           Brooklyn, NY 11220