Hibernate commit very slow in multithreaded test
Hi
I have a unit test that tries to persist hibernate entities in a single thread and one that does it multithreaded. I've would expect that the execution time should be more or less the same, but the multithreaded unit test uses twice the amount of time. I'm using H2 DB, Hibernate 3.6.8.Final, Spring 3.1.0.Release with following config. Do you guys have any idea, why it takes almost twice as much time in the multithreaded test?
ApplicationContext.xml
Code:
.
.
<bean id="dataSource" class="com.mchange.v2.c3p0.ComboPooledDataSource" destroy-method="close">
<property name="driverClass" value="${jdbc.driverClassName}" />
<property name="jdbcUrl" value="${jdbc.url}"/>
<property name="user" value="${jdbc.username}"/>
<property name="password" value="${jdbc.password}"/>
<property name="initialPoolSize"><value>10</value></property>
<property name="minPoolSize"><value>10</value></property>
<property name="maxPoolSize"><value>50</value></property>
<property name="idleConnectionTestPeriod"><value>200</value></property>
<property name="acquireIncrement"><value>1</value></property>
<property name="maxStatements"><value>100</value></property>
<property name="numHelperThreads"><value>10</value></property>
</bean>
.
.
Unit Test
Code:
public void testSaveSchedulePerformanceMultiThreaded() {
long t0 = System.currentTimeMillis();
for(int i = 0 ; i < noOfSchedules; i++) {
Runnable runnable = new Runnable() {
public void run() {
try {
Schedule s = TestUtilityMethods.createSchedule();
long t2 = System.currentTimeMillis();
try {
s = epgService.saveSchedule(s);
} catch (EpgException e) {
fail(e.getMessage());
}
long t3 = System.currentTimeMillis();
log.debug("Schedule saved in " + (t3 - t2) + " ms");
} catch (Exception e) {
fail(e.getMessage());
}
}
};
Thread thread = new Thread(runnable);
threads.add(thread);
thread.start();
}
// threads join here
long t1 = System.currentTimeMillis();
log.info("testSaveSchedulePerformanceMultiThreaded completed in " + (t1-t0) + " ms");
}
public void testSaveSchedulePerformanceOneThread() {
long t0 = System.currentTimeMillis();
for(int i = 0; i < noOfSchedules; i++) {
Schedule s = TestUtilityMethods.createSchedule();
long t2 = System.currentTimeMillis();
try {
s = epgService.saveSchedule(s);
} catch (EpgException e) {
fail(e.getMessage());
}
long t3 = System.currentTimeMillis();
log.debug("Schedule saved in " + (t3 - t2) + " ms");
}
long t1 = System.currentTimeMillis();
log.info("testSaveSchedulePerformanceOneThread completed in " + (t1-t0) + " ms");
}
singlethreaded.log
Code:
27/06 09:36:11,207 DEBUG - main - HibernateTransactionManager - Creating new transaction with name [com.barrowa.core.epg.service.impl.EpgServiceImpl.saveSchedule]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT,-EpgException
27/06 09:36:11,207 DEBUG - main - HibernateTransactionManager - Opened new Session [org.hibernate.impl.SessionImpl@412bb519] for Hibernate transaction
27/06 09:36:11,207 DEBUG - main - HibernateTransactionManager - Not preparing JDBC Connection of Hibernate Session [org.hibernate.impl.SessionImpl@412bb519]
27/06 09:36:11,208 DEBUG - main - HibernateTransactionManager - Exposing Hibernate transaction as JDBC transaction [com.mchange.v2.c3p0.impl.NewProxyConnection@3ca5b041]
27/06 09:36:11,208 DEBUG - main - HibernateTransactionManager - Found thread-bound Session [org.hibernate.impl.SessionImpl@412bb519] for Hibernate transaction
27/06 09:36:11,208 DEBUG - main - HibernateTransactionManager - Participating in existing transaction
27/06 09:36:11,211 DEBUG - main - HibernateTransactionManager - Found thread-bound Session [org.hibernate.impl.SessionImpl@412bb519] for Hibernate transaction
27/06 09:36:11,211 DEBUG - main - HibernateTransactionManager - Participating in existing transaction
27/06 09:36:11,264 DEBUG - main - HibernateTransactionManager - Initiating transaction commit
27/06 09:36:11,264 DEBUG - main - HibernateTransactionManager - Committing Hibernate transaction on Session [org.hibernate.impl.SessionImpl@412bb519]
27/06 09:36:13,918 DEBUG - main - HibernateTransactionManager - Closing Hibernate Session [org.hibernate.impl.SessionImpl@412bb519] after transaction
27/06 09:36:13,918 INFO - main - EpgNotificationInterceptor - saveSchedule used 2711 ms
27/06 09:36:13,918 INFO - main - EpgNotificationInterceptor - Schedule (d3c6246a-7b38-4d83-9ea8-39e9407cc1a6) containing 500 events, covering period 27/06 09:36:11 - 04/07 08:16:11 successfully persisted
27/06 09:36:13,918 DEBUG - main - EpgServicePerformanceTest - Schedule saved in 2711 ms
.
.
.
27/06 09:36:26,216 INFO - main - EpgServicePerformanceTest - ---------------------------------------------------------------------------
27/06 09:36:26,216 INFO - main - EpgServicePerformanceTest - testSaveSchedulePerformanceOneThread completed in 15034 ms
27/06 09:36:26,216 INFO - main - EpgServicePerformanceTest - 10 schedules with 500 events created with an average time of 1495ms
27/06 09:36:26,216 INFO - main - EpgServicePerformanceTest - ---------------------------------------------------------------------------
multithreaded.log
Code:
27/06 09:35:46,179 DEBUG - hread-20 - HibernateTransactionManager - Creating new transaction with name [com.barrowa.core.epg.service.impl.EpgServiceImpl.saveSchedule]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT,-EpgException
27/06 09:35:46,180 DEBUG - hread-20 - HibernateTransactionManager - Opened new Session [org.hibernate.impl.SessionImpl@6fe88c7f] for Hibernate transaction
27/06 09:35:46,180 DEBUG - hread-20 - HibernateTransactionManager - Not preparing JDBC Connection of Hibernate Session [org.hibernate.impl.SessionImpl@6fe88c7f]
27/06 09:35:46,182 DEBUG - hread-20 - HibernateTransactionManager - Exposing Hibernate transaction as JDBC transaction [com.mchange.v2.c3p0.impl.NewProxyConnection@593f5a2f]
27/06 09:35:46,184 DEBUG - hread-20 - HibernateTransactionManager - Found thread-bound Session [org.hibernate.impl.SessionImpl@6fe88c7f] for Hibernate transaction
.
.
.
27/06 09:35:47,200 DEBUG - hread-24 - HibernateTransactionManager - Initiating transaction commit
27/06 09:35:47,200 DEBUG - hread-24 - HibernateTransactionManager - Committing Hibernate transaction on Session [org.hibernate.impl.SessionImpl@556b277f]
27/06 09:35:47,272 DEBUG - hread-23 - HibernateTransactionManager - Initiating transaction commit
27/06 09:35:47,272 DEBUG - hread-23 - HibernateTransactionManager - Committing Hibernate transaction on Session [org.hibernate.impl.SessionImpl@476e46f5]
.
.
.
27/06 09:36:07,235 DEBUG - hread-17 - HibernateTransactionManager - Closing Hibernate Session [org.hibernate.impl.SessionImpl@5712bd54] after transaction
27/06 09:36:07,236 INFO - hread-17 - EpgNotificationInterceptor - saveSchedule used 21024 ms
27/06 09:36:07,237 INFO - hread-17 - EpgNotificationInterceptor - Schedule (2c8f3623-17a6-424a-82df-3e05b65b2ea4) containing 500 events, covering period 27/06 09:35:46 - 04/07 08:15:46 successfully persisted
27/06 09:36:07,238 DEBUG - hread-17 - EpgServicePerformanceTest - Schedule saved in 21026 ms
27/06 09:36:08,127 DEBUG - hread-16 - HibernateTransactionManager - Closing Hibernate Session [org.hibernate.impl.SessionImpl@46fdb413] after transaction
.
.
.
27/06 09:36:11,181 INFO - main - EpgServicePerformanceTest - ---------------------------------------------------------------------------
27/06 09:36:11,181 INFO - main - EpgServicePerformanceTest - testSaveSchedulePerformanceMultiThreaded completed in 25151 ms
27/06 09:36:11,181 INFO - main - EpgServicePerformanceTest - ---------------------------------------------------------------------------
