Threading issues with Hibernate

Question

I'm experiencing a strange behaviour with Hibernate. I've been banging my head against the wall for a while now, and will award any answer which leads to a solution with a +100 bounty.

I have a JAX-RS (Jersey) REST server, with a filter that associates one Hibernate-session per request.

In one request a client POSTs some data which is stored in the database using one session (and one transaction). In a subsequent call, the client tries to GET this entity, but Hibernate can't find it.

Some observations:

• I can only reproduce this if I run multiple simultaneous clients. I've never managed to reproduce it by running one client at a time.)

• I can see the entity ID in the database, and if I restart the server, the entity is found by Hibernate as it should.

• The error does not occur if I use a thread pool of size 1 (regardless of how many clients I run simultaneously).

Here's the code, with some logging:

chargeables.setId(new SecureRandom().nextLong());

System.out.printf("%s,  session: %s  [%s]%n",
                  Thread.currentThread(),
                  System.identityHashCode(session),
                  "session.beginTransaction()");

session.beginTransaction();


System.out.printf("%s,  session: %s  [%s]%n",
                  Thread.currentThread(),
                  System.identityHashCode(session),
                  "session.save(id = "+chargeables.getId()+")");

session.save(chargeables);


System.out.printf("%s,  session: %s  [%s]%n",
                  Thread.currentThread(),
                  System.identityHashCode(session),
                  "session.getTransaction().commit()");

session.getTransaction().commit();

The code for getting the entity:

System.out.printf("%s,  session: %s  [%s]%n",
                  Thread.currentThread(),
                  System.identityHashCode(session),
                  "session.get("+id+")");

Chargeables entity = (Chargeables) session.get(Chargeables.class, id);

if (entity == null)
    System.out.printf("%s,  session: %s  [%s]%n",
                      Thread.currentThread(),
                      System.identityHashCode(session),
                      "ENTITY NOT FOUND!");

Now here is an excerpt of the resulting log (with some additional open/close session output):

Thread[Grizzly(5),5,main],  session:  2041842357  [factory.openSession()]
Thread[Grizzly(5),5,main],  session:  2041842357  [session.beginTransaction()]
Thread[Grizzly(5),5,main],  session:  2041842357  [session.save(id = 7939229356942262438)]
Thread[Grizzly(5),5,main],  session:  2041842357  [session.getTransaction().commit()]
Thread[Grizzly(5),5,main],  session:  2041842357  [session.close()]
[...]
Thread[Grizzly(7),5,main],  session:  1717445911  [factory.openSession()]
Thread[Grizzly(7),5,main],  session:  1717445911  [session.get(7939229356942262438)]
Thread[Grizzly(7),5,main],  session:  1717445911  [ENTITY NOT FOUND!]
Thread[Grizzly(7),5,main],  session:  1717445911  [session.close()]

Why on earth do I reach ENTITY NOT FOUND!?

---

Hibernate version: 4.1.9.Final
MySQL verison: 14.14 Distrib 5.5.29

---

Mapping file for Chargeables:

<?xml version="1.0"?>
<!DOCTYPE hibernate-mapping PUBLIC
       "-//Hibernate/Hibernate Mapping DTD 3.0//EN"
       "http://www.hibernate.org/dtd/hibernate-mapping-3.0.dtd">

<hibernate-mapping
   default-cascade="all"
   package="se.package.common.chargeables"
   default-lazy="false">


    <class name="Chargeables">

        <id name="id" type="long">
            <generator class="assigned"/>
        </id>

        <property name="startTimeStamp" />
        <property name="endTimeStamp" />

        <list name="chargeables">
            <key column="chargeableId" />
            <list-index column="pos" />
            <many-to-many class="Chargeable"/>
        </list>

    </class>


    <class name="Chargeable">

        <id column="id" type="long">
            <generator class="native"/>
        </id>

        <discriminator />

        <property name="timestamp" />

    </class>


    <subclass name="DataTransfer" extends="Chargeable">
        <property name="bytesSent" />
        <property name="bytesReceived" />
    </subclass>


    <subclass name="TelephonyChargeable" extends="Chargeable">
        <many-to-one name="num" />
    </subclass>

    <subclass name="Call" extends="TelephonyChargeable">
        <property name="duration" />        
    </subclass>

    <subclass name="OutgoingCall" extends="Call" />
    <subclass name="IncomingCall" extends="Call" />

    <subclass name="Message" extends="TelephonyChargeable" />

    <subclass name="Sms" extends="Message" />
    <subclass name="IncomingSms" extends="Sms" />
    <subclass name="OutgoingSms" extends="Sms" />

    <subclass name="Mms" extends="Message" />
    <subclass name="IncomingMms" extends="Mms" />
    <subclass name="OutgoingMms" extends="Mms" />


</hibernate-mapping>

Answer 1

IMHO it's an isolation problem. Your second session start before the transaction of the 1st one is commited. As default hibernate isolation level is read_commited, the 2nd session can't so retrieve the entity.
How are you passing id between the 2 threads ?

Answer 2

If you can see the commit in the database, it cannot be an isolation issue at the MySQL level: console operations are also client operations, you don't get special powers when running them, so they conform to the isolation policy you selected.

Looking out for solution, I discovered that Hibernate provide some facilities to cache DB results: there are actually 2 levels of cache implemented there. Perhaps your hibernate installation comes bundled with a cache mechanism?

The first level works on a per session basis, which is consistent with the behaviour you observe when running the code on one thread, and seemingly happens to be activated by default. I am not Hibernate proficient, I can't say that for sure, but my opinion is that your setup has this first level of cache set in read-only mode, while you would like it to be in read-write mode.