Announcement Announcement Module
Collapse
No announcement yet.
Hibernate commit very slow in multithreaded test Page Title Module
Move Remove Collapse
X
Conversation Detail Module
Collapse
  • Filter
  • Time
  • Show
Clear All
new posts

  • 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                - ---------------------------------------------------------------------------

  • #2
    I wouldn't expect the same results. Multiple inserts lead to contention on the database as an insert needs to be done before other inserts to calculate the correct id (I suspect you use auto inc. fields) and as such threads will wait until the database is free. This might be even worse with a simple db as H2.

    You also might want to try to use the Executor stuff to execute threads...

    Comment

    Working...
    X