Performance problem when switching from pure Hibernate

[obecker]

Hi,

I'm currently in the process of switching my persistence layer from pure Hibernate to Spring+Hibernate. That means instead of constructing the SessionFactory myself I let Spring do the configuration. My DAO implementation uses HibernateDaoSupport.

Now the problem is: a single saveOrUpdate(object) that took about 500 ms now needs more than 9 seconds. The data are the same, the mapping is the same, Hibernate's configuration should be the same (copied and adapted from hibernate.cfg.xml to applicationContext.xml).

I'm clueless what the reason for this performance problem is and where to look for a solution.

Any hints are welcome,
Oliver

[katentim]

Spring shouldn't affect Hibernate's performance. Can you isolate the code and post it.

[robh]

Oliver,

This does sound quite bizarre. However, you might want to check whether you are using the same datasource configuration. You should also investigate the P6Spy tool to see whether both versions of the application are actually executing the same SQL.

Post back with you findings.

Rob

[obecker]

Hmm, having show_sql set to true displays subtle differences. But the overall amount of SQL queries is nearly the same.

The point is: without Spring the SQL log shows up very fast, with Spring I can nearly watch each query one after another.

Regarding the DataSource:
(note: this is currently a non-web standalone test)

In hibernate.cfg.xml:

      <session-factory>
         <property name="hibernate.dialect"
            >net.sf.hibernate.dialect.MySQLDialect</property>
         <property name="hibernate.connection.driver_class"
            >com.mysql.jdbc.Driver</property>
         <property name="hibernate.connection.url"
           >jdbc&#58;mysql&#58;//141.***&#58;3306/myDB?relaxAutoCommit=true</property>
         <property name="hibernate.connection.username">xxx</property>
         <property name="hibernate.connection.password">xxx</property>

        ...

In applicationContext.xml:

   <bean id="myDataSource" 
         class="org.springframework.jdbc.datasource.DriverManagerDataSource">
      <property name="driverClassName">
         <value>com.mysql.jdbc.Driver</value>
      </property>
      <property name="url">
         <value>jdbc&#58;mysql&#58;//141.***&#58;3306/myDB?relaxAutoCommit=true</value>
      </property>
      <property name="username">
         <value>xxx</value>
      </property>
      <property name="password">
         <value>xxx</value>
      </property>
   </bean>
   
   <!-- Hibernate SessionFactory -->
   <bean id="mySessionFactory" 
      class="org.springframework.orm.hibernate.LocalSessionFactoryBean">
      <property name="dataSource">
         <ref local="myDataSource"/>
      </property>
      <property name="hibernateProperties">
         <props>
            <prop key="hibernate.dialect">net.sf.hibernate.dialect.MySQLDialect</prop>
            <prop key="hibernate.connection.pool_size">1</prop>
            <!-- etc other properties -->

             ...

   <bean id="objectDAO" class="MyDAOImpl">
      <property name="sessionFactory">
         <ref bean="mySessionFactory" />
      </property>
   </bean>

...

Well, the Java code isn't any spectacular (both in main(String[] a))
formerly:

        Session s = MyHibernateHelper.currentSession();
        Transaction tx = s.beginTransaction();
        try {
            s.saveOrUpdate(o);
            tx.commit();
        }
        catch (HibernateException e) {
            tx.rollback();
        }
        MyHibernateHelper.closeSession();

Now:

        SessionFactory sessionFactory = 
            (SessionFactory)MyDAOHelper.getBean("mySessionFactory");
        Session s = SessionFactoryUtils.getSession(sessionFactory, true);
        myDAO = (MyDAO)MyDAOHelper.getBean("objectDAO");
        myDAO.save(o);
        s.flush();
        SessionFactoryUtils.closeSessionIfNecessary(s, sessionFactory);

     and in MyDAOImpl.save(o):

        getHibernateTemplate().saveOrUpdate(o);

I think this is all standard code.
(Sorry for the length of this reply)

I'm going to check P6Spy in any case, thanks.
Oliver

[trisberg]

I would start by switching to a different data source - org.springframework.jdbc.datasource.DriverManagerD ataSource is more geared for testing and it does not do any connection pooling. Try using Commons DBCP or C3P0 pooled connection data source. If you want to run a quick test - use org.springframework.jdbc.datasource.SingleConnecti onDataSource - it keeps a connection open for the length of its life or until destroy() is called on it.

[obecker]

Try using Commons DBCP or C3P0 pooled connection data source. If you want to run a quick test - use org.springframework.jdbc.datasource.SingleConnecti onDataSource - it keeps a connection open for the length of its life or until destroy() is called on it.

Hi Thomas,
unfortunately this doesn't change anything.
org.springframework.jdbc.datasource.SingleConnecti onDataSource refused to work for me ("connection was closed"), and org.apache.commons.dbcp.BasicDataSource results in the same performance.

Is there anything that happens between the single SQL statements in Spring? Can I trace this by some means?

Oliver

[obecker]

addendum:
I got org.springframework.jdbc.datasource.SingleConnecti onDataSource working by adding
<property name="suppressClose"><value>true</value></property>
but again, no change in the performance.

[Colin Sampaleanu]

What is the lifetime of the appcontext this is all coming out of? You are not by any chance recreating the entire appcontext (including the expensive to create SessionFactory) on each usage of the DAO, are you?

[obecker]

No, the appcontext is created only once.

I guess it must have something to do with the way hibernate will be configured. I've transfered the entries of hibernate.cfg.xml to applicationContext.xml in the following way:

   <bean id="mySessionFactory" 
      class="org.springframework.orm.hibernate.LocalSessionFactoryBean">
      <property name="dataSource">
         <ref local="myDataSource"/>
      </property>
      <property name="mappingResources">
         <list> ... </list>
      </property>
      <property name="hibernateProperties">
         <props>
            <prop key="hibernate.dialect">net.sf.hibernate.dialect.MySQLDialect</prop>
            <prop key="hibernate.connection.pool_size">1</prop>
            <prop key="hibernate.show_sql">true</prop>
            <prop key="hibernate.query.substitutions"
               >true 1, false 0, yes 'Y', no 'N'</prop>
         
            <!-- JDBC -->
            <prop key="hibernate.jdbc.batch_size">0</prop>
            <prop key="hibernate.jdbc.batch_versioned_data">true</prop>
            <prop key="hibernate.jdbc.use_streams_for_binary">true</prop>
         
            <prop key="hibernate.max_fetch_depth">1</prop>
         
            <!-- Second level cache -->
            <prop key="hibernate.cache.region_prefix"
               >hibernate.test</prop>
            <prop key="hibernate.cache.use_query_cache">true</prop>
            <prop key="hibernate.cache.provider_class"
               >net.sf.hibernate.cache.EhCacheProvider</prop>
         </props>
      </property>
   </bean>

However, setting Hibernate's logging to debug, I see these lines in my original configuration (using Hibernate only with hibernate.cfg.xml):

DEBUG  net.sf.hibernate.cfg.Configuration.addProperties(Configuration.java:853) - hibernate.connection.pool_size=1
DEBUG  net.sf.hibernate.cfg.Configuration.addProperties(Configuration.java:853) - hibernate.show_sql=true
DEBUG  net.sf.hibernate.cfg.Configuration.addProperties(Configuration.java:853) - hibernate.query.substitutions=true 1, false 0, yes 'Y', no 'N'
DEBUG  net.sf.hibernate.cfg.Configuration.addProperties(Configuration.java:853) - hibernate.jdbc.batch_size=0
DEBUG  net.sf.hibernate.cfg.Configuration.addProperties(Configuration.java:853) - hibernate.jdbc.batch_versioned_data=true
DEBUG  net.sf.hibernate.cfg.Configuration.addProperties(Configuration.java:853) - hibernate.jdbc.use_streams_for_binary=true
DEBUG  net.sf.hibernate.cfg.Configuration.addProperties(Configuration.java:853) - hibernate.max_fetch_depth=1
DEBUG  net.sf.hibernate.cfg.Configuration.addProperties(Configuration.java:853) - hibernate.cache.region_prefix=hibernate.test
DEBUG  net.sf.hibernate.cfg.Configuration.addProperties(Configuration.java:853) - hibernate.cache.use_query_cache=true
DEBUG  net.sf.hibernate.cfg.Configuration.addProperties(Configuration.java:853) - hibernate.cache.provider_class=net.sf.hibernate.cache.EhCacheProvider

These lines don't appear if I use Hibernate via Spring.

Is this probably a Hibernate issue and should be asked on the Hibernate forum?

Oliver
(obviously a newbie to all this stuff)

[Colin Sampaleanu]

If your code is working fine outside of Spring then this is Spring specific to the extent that I think your actual config or environment is messed up in Spring somehow. Spring is just a wrapper over HIbernate, so the same setup should run with the same speed, but in your case something is different.

W/regards to the logging statements you mention, it's nothing to worry about. In the case of hibernate parsing the hibernate.cfg.xml file, it logs each property it reads from the file. In the case of feeding them in via Spring, Spring just calls Hibernate's Configuration object's addProperties method, which doesn't log all the properties. Even with Spring you could just point it (via the configLocation property) to a hibernate.cfg.xml file if you wanted, and you would see the logging...

I'm sort of stumped here as I haven't seen anything like this before, and as I said, all Spring is doing is wrapping... Are you sure btw than in the Spring case your entire app is not running slowly for some reason (i.e. you have some thread or something consuming most resources)?