In trying to test out Hibernate performance before using it in an application, I'm running into trouble with one aspect of my testing. I'm trying to create a bunch of threads (10-50), and get them to retreive, modify, and store some objects from the database, a specific number of times.
One of the modifications they make is to increment a value, called "commits". This value is in a map. It's the "data" column/field of the "intdata" map, as shown in my mapping document. (It is NOT the "commits" property, it's a name/value pair in the "intdata" map. The "commits" property was for some other testing.) If the commit fails, for any reason, the transaction is rolled back, the session closed, and the iteration is retried. This keeps happening until the commit succeeds.
At the end of the performance test, I retrieve and print out that same "commits" value, from the "intdata" of each entity, and I expect them all to be equal to the number of threads * iterations in each thread. When using a single thread this is always the case.
However, when using multiple threads, often, the value I get is significantly lower than the one I expect.
As far as I understand, this is something transactions are supposed to help you do, so I'm sure I'm doing something wrong, but I can't for the life of me figure out what.
Any help educating my on my mistakes (Messy Java aside, it's throw-away code) would be much appreciated. :)
Hibernate version: 3.1 rc3
Mapping documents:
Code:
<class name="com.lewisd.test.Entity" table="entity">
<cache usage="read-write" />
<id name="id" column="id">
<generator class="increment"/>
</id>
<version name="version" type="long" />
<property name="commits" />
<map name="intdata" table="intdata" >
<cache usage="read-write" />
<key column="id" />
<map-key column="name" type="string" />
<element column="data" type="int" />
</map>
<map name="stringdata" table="stringdata" >
<cache usage="read-write" />
<key column="id" />
<map-key column="name" type="string" />
<element column="data" type="string" />
</map>
</class>
The Entity class is nothing special, just a POJO, straightforward getter/setter methods.
hibernate.xml (fragment):
Code:
<session-factory>
<property name="connection.driver_class">com.mysql.jdbc.Driver</property>
<property name="connection.url">jdbc:mysql://localhost/hibernate</property>
<property name="connection.username">lewisd</property>
<property name="connection.password">mine123</property>
<!-- JDBC connection pool (use the built-in) -->
<property name="connection.pool_size">20</property>
<!-- SQL dialect -->
<property name="dialect">org.hibernate.dialect.MySQLDialect</property>
<!-- Echo all executed SQL to stdout -->
<property name="show_sql">true</property>
<!-- Drop and re-create the database schema on startup -->
<property name="hbm2ddl.auto">create</property>
<property name="hibernate.cache.provider_class">org.hibernate.cache.EhCacheProvider</property>
<property name="hibernate.cache.use_second_level_cache">false</property>
<property name="hibernate.transaction.factory_class">org.hibernate.transaction.JDBCTransactionFactory</property>
<property name="hibernate.current_session_context_class">thread</property>
<mapping resource="Entity.hbm.xml"/>
</session-factory>
This is my entire test class code:
Code:
/*
* Created on 14-Jan-2006
*/
package com.lewisd.test;
import java.util.ArrayList;
import java.util.Collections;
import java.util.LinkedList;
import java.util.List;
import java.util.Map;
import java.util.concurrent.Callable;
import java.util.concurrent.ExecutionException;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.Future;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.hibernate.Session;
import org.hibernate.StaleStateException;
import org.hibernate.Transaction;
public class TestPerformance<V> implements Callable<V>
{
private static final Log log = LogFactory.getLog( TestPerformance.class );
private static final int ITERATIONS = 50;
private static final int THREADS = 2;
private static final int ENTITIES = 1;
private static int errors = 0;
private static int stale = 0;
public static void main( String args[] ) throws InterruptedException
{
ExecutorService executor = Executors.newFixedThreadPool( THREADS );
List<Callable<Object>> tasks = new ArrayList<Callable<Object>>( THREADS );
for ( int i = 0; i < THREADS; ++i )
{
tasks.add( new TestPerformance<Object>() );
}
setup();
long t0 = System.currentTimeMillis();
List<Future<Object>> results = executor.invokeAll( tasks );
executor.shutdown();
long t1 = System.currentTimeMillis();
log.info( "Total time: " + ( t1 - t0 ) / 1000.0 + " sec" );
log.info( "Errors: " + errors );
log.info( "Stale: " + stale );
for ( Future<Object> result : results )
{
try
{
log.info( result.get() );
}
catch ( InterruptedException e )
{
e.printStackTrace();
}
catch ( ExecutionException e )
{
e.printStackTrace();
}
}
executor.shutdown();
checkCorrectness();
}
private static void setup()
{
Session s = HibernateUtil.currentSession();
Transaction tx = s.beginTransaction();
for ( int i = 0; i < ENTITIES; ++i )
{
Entity e = new Entity();
s.save( e );
e.getIntdata().put( "commits", 0 );
}
tx.commit();
HibernateUtil.closeSession();
}
private static void checkCorrectness()
{
Session s = HibernateUtil.currentSession();
List<Entity> entities = s.createQuery( "from Entity" ).list();
for ( Entity e : entities )
{
long commits = e.getIntdata().get( "commits" );
log.info( "commits = " + commits + " (Should be " + (THREADS*ITERATIONS) + ")" );
}
HibernateUtil.closeSession();
}
protected void incrementCommits()
{
Session s = HibernateUtil.currentSession();
Transaction tx = s.beginTransaction();
List<Entity> entities = s.createQuery( "from Entity" ).list();
Collections.shuffle( entities );
for ( Entity e : entities )
{
Map<String, Integer> intdata = e.getIntdata();
intdata.put( "commits", intdata.get( "commits" ) + 1 );
}
s.flush();
tx.commit();
HibernateUtil.closeSession();
}
public V call()
{
log.info( "Invoking " + Thread.currentThread() );
for ( int x = 0; x < ITERATIONS; ++x )
{
boolean success = false;
while ( !success )
{
try
{
incrementCommits();
success = true;
}
catch ( StaleStateException e )
{
log.error( e );
stale++;
}
catch ( Exception e )
{
log.error( e );
errors++;
}
if ( ! success )
{
HibernateUtil.currentSession().getTransaction().rollback();
HibernateUtil.closeSession();
}
}
}
log.info( "Exiting " + Thread.currentThread() );
return null;
}
}
The HibernateUtil used here is straight from the example here:
http://www.hibernate.org/hib_docs/refer ... ngwithcatsName and version of the database you are using:I've tried this with both MySQL 4.1.14 and HSQL (whatever version shipped with Hibernate 3.1 rc3)
I'm reluctant to post the SQL/debug logs, because I can only duplicate this when doing something like 100 transactions, so it's a lot of log.
The full log is available here:
http://www.lewisd.com/files/hibernate-3.logOn a side note, something in the logging has been really frustrating.
In this sample:
Code:
Hibernate: update entity set version=?, commits=? where id=? and version=?
14:33:03,886 Thread-1 DEBUG LongType:79 - binding '24' to parameter: 1
14:33:03,886 Thread-1 DEBUG LongType:79 - binding '0' to parameter: 2
14:33:03,887 Thread-1 DEBUG LongType:79 - binding '1' to parameter: 3
14:33:03,887 Thread-1 DEBUG LongType:79 - binding '23' to parameter: 4
Hibernate: update intdata set data=? where id=? and name=?
14:33:03,889 Thread-1 DEBUG IntegerType:79 - binding '23' to parameter: 1
14:33:03,687 Thread-0 DEBUG IntegerType:123 - returning '3' as column: data0_
14:33:03,889 Thread-0 DEBUG StringType:123 - returning 'commits' as column: name0_
Hibernate: update entity set version=?, commits=? where id=? and version=?
14:33:03,891 Thread-0 DEBUG LongType:79 - binding '5' to parameter: 1
14:33:03,892 Thread-0 DEBUG LongType:79 - binding '0' to parameter: 2
14:33:03,894 Thread-0 DEBUG LongType:79 - binding '1' to parameter: 3
14:33:03,894 Thread-0 DEBUG LongType:79 - binding '4' to parameter: 4
You can see one log entry, timestamped 14:33:03,687 that is logged out of order from the test, at least as far as the timestamp goes. I'm not sure when this is actually happening, so it's been making my attempt to debug my problem somewhat awkward.
Here's the code for Entity, just for completeness, in case anyone would like to try to run this to help me out:
Code:
/*
* Created on 14-Jan-2006
*/
package com.lewisd.test;
import java.util.HashMap;
import java.util.Map;
public class Entity
{
private long id;
private long version;
private Map<String, Integer> intdata = new HashMap<String, Integer>();
private Map<String, String> stringdata = new HashMap<String, String>();
private long commits = 0;
public Entity()
{
super();
}
public long getId()
{
return this.id;
}
public void setId( long id )
{
this.id = id;
}
public Map<String, Integer> getIntdata()
{
return this.intdata;
}
public void setIntdata( Map<String, Integer> intdata )
{
this.intdata = intdata;
}
public Map<String, String> getStringdata()
{
return this.stringdata;
}
public void setStringdata( Map<String, String> stringdata )
{
this.stringdata = stringdata;
}
public long getVersion()
{
return this.version;
}
public void setVersion( long version )
{
this.version = version;
}
public long getCommits()
{
return this.commits;
}
public void setCommits( long commits )
{
this.commits = commits;
}
}
Login
FAQ
Search
