Hibernate Transaction Manager Performance Issue

Question

I am currently encountering Performance Issue in Hibernate

For executing SQL statement(e.g. select * from table), it takes around 90ms to fetch only 10 records with 12 columns

However, for hibernate to run following java code in DAO class

List<T> afterGetAll = getSessionFactory().getCurrentSession().createCriteria(type).list();

It takes around 260~300 ms to complete in executing above statement ONLY ,not to mention additional execution time in service class calling that DAO. Totally around 600~1000 ms would be spent. I doubt that most of the time was spent in transaction management.

I am not sure where my code/configuration goes wrong and I have also tried the following approach but doesn't help too much...

1. Add connection pool in dataSource setting
2. Using hibernate native SQL method instead of createCriteria in DAO class
3. Enable lazy load
4. Increase heap size of tomcat server
5. Use second-level cache provider
6. @Transactional(readOnly = true) for read-only query

Some workarounds for speeding up operation:

1. Enable hibernate cache by configuring EhCacheRegionFactory and enable second-level cache together. Then at the start of the server, my web application initialize the cache by manually trigger the service call. This could successfully reduce the data-binding process to Java class after fetching the sql query by Hibernate from 300~400ms to 1~3ms. However, the bottleneck is at the point of committing transaction...(See Update#2 below)

Here is my configuration and code

Hibernate Configuration

<bean id="jdbcTemplate" class="com.mchange.v2.c3p0.ComboPooledDataSource">
    <property name="driverClass" value="com.mysql.jdbc.Driver" />
    <property name="jdbcUrl" value="jdbc:mysql://test />
    <property name="user" value="test" />
    <property name="password" value="test" />
    <property name="maxPoolSize" value="20" />
    <property name="minPoolSize" value="5" />
    <property name="maxStatements" value="5" />
</bean>

<bean id="sessionFactory" class="org.springframework.orm.hibernate4.LocalSessionFactoryBean">
    <property name="dataSource" ref="jdbcTemplate"></property>
    <property name="mappingResources">
        <list>
            <value>orm/UserModel.hbm.xml</value>
            <value>orm/UserToken.hbm.xml</value>
            <value>orm/RoleModel.hbm.xml</value>
        </list>
    </property>
    <property name="hibernateProperties">
      <props>
        <prop key="hibernate.dialect">org.hibernate.dialect.MySQL5Dialect</prop>
        <prop key="hibernate.show_sql">true</prop>
        <prop key="hibernate.format_sql">true</prop>
        <prop key="hibernate.use_sql_comments">true</prop>
        <prop key="hibernate.enable_lazy_load_no_trans">true</prop>
        <prop key="hibernate.cache.provider_class">org.hibernate.cache.EhCacheProvider</prop>  
        <prop key="hibernate.cache.use_second_level_cache">true</prop>   
        <prop key="hibernate.c3p0.minPoolSize">5</prop>
        <prop key="hibernate.c3p0.maxPoolSize">20</prop>
      </props>
    </property>
</bean>

<bean id="baseDao" abstract="true" class="com.test.app.project.dao.BaseDAOImpl">
    <property name="sessionFactory" ref="sessionFactory" />
</bean>

<bean id="userDao" parent="baseDao" class="com.test.app.project.dao.UserDAOImpl">
</bean>

<bean id="userService" class="com.test.app.project.services.UserServiceImpl">
    <property name="userDao" ref="userDao" />
</bean>

<bean id="transactionManager" class="org.springframework.orm.hibernate4.HibernateTransactionManager">
    <property name="sessionFactory" ref="sessionFactory" />
</bean>

getAll method in DAO class

public <T> List<T> getAll(final Class<T> type) {
        long startTime = System.nanoTime();
        List<T> afterGetAll = getSessionFactory().getCurrentSession().createSQLQuery("SELECT user_id,username,email,is_active FROM app_users")
                .addScalar("user_id", LongType.INSTANCE)
                .addScalar("username", StringType.INSTANCE)
                .addScalar("email", StringType.INSTANCE)
                .addScalar("is_active", IntegerType.INSTANCE)
                .setResultTransformer(Transformers.aliasToBean(UserModel.class)).list();
        //List<T> afterGetAll = getSessionFactory().getCurrentSession().createCriteria(type).list();
        long endTime = System.nanoTime();
        long duration = (endTime - startTime); 
        logger.info("============getAll=============== Execution Timestamp: " + duration/1000000 + "milliseconds");
        return afterGetAll;
    }

Service Class calling the above dao

@Transactional(propagation=Propagation.REQUIRES_NEW,isolation = Isolation.READ_COMMITTED)
@Service
public class UserServiceImpl implements UserService{
...
    @Override
    public <T> List<T> getAll(Class<T> type) {
        List<T> userList = userDao.getAll(type);
        return userList;
    }
...
}

Any suggestion in configuration/code can improve the performance is also welcomed. Thanks first

Update#1: After enable hibernate statistics, I can deduce that most of the time spent not on the executing statement due to following statistics.

2015-10-14 10:45:46 INFO  StatisticalLoggingSessionEventListener:275 - Session M
etrics {
    298847 nanoseconds spent acquiring 1 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    914957 nanoseconds spent preparing 1 JDBC statements;
    335661830 nanoseconds spent executing 1 JDBC statements;
    0 nanoseconds spent executing 0 JDBC batches;
    0 nanoseconds spent performing 0 L2C puts;
    0 nanoseconds spent performing 0 L2C hits;
    0 nanoseconds spent performing 0 L2C misses;
    0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and
0 collections);
    5735 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 en
tities and 0 collections)
}

2015-10-14 10:45:46 INFO  AdminOperationController:51 - =======/admin/operation/
UserManagement Execution Timestamp:====== 3051milliseconds

It turns out that the execution time is almost 10 times different between executing controller class calling that service only which calls the DAO and executing statement by hibernate

Update#2

I try to add some millisecond timestamp to track down which process spent most of the time. Later I found out most of the time spent on exposing hibernate transaction as jdbc transaction and commiting transaction after each service operation. The statistical finding log is listed below

2015-10-15 18:00:13,768 DEBUG HibernateTransactionManager:448 - Preparing JDBC Connection of Hibernate Session [SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=org.hibernate.engine.spi.ExecutableList@2b237512 updates=org.hibernate.engine.spi.ExecutableList@24db06de deletions=org.hibernate.engine.spi.ExecutableList@279febb9 orphanRemovals=org.hibernate.engine.spi.ExecutableList@742cd301 collectionCreations=org.hibernate.engine.spi.ExecutableList@2ad1223d collectionRemovals=org.hibernate.engine.spi.ExecutableList@81ee8c1 collectionUpdates=org.hibernate.engine.spi.ExecutableList@2542db11 collectionQueuedOps=org.hibernate.engine.spi.ExecutableList@483c4c33 unresolvedInsertDependencies=UnresolvedEntityInsertActions[]])]
2015-10-15 18:00:13,847 DEBUG HibernateTransactionManager:516 - Exposing Hibernate transaction as JDBC transaction [ConnectionHandle{url=jdbc:mysql://test, user=test, debugHandle=null, lastResetAgoInSec=18, lastUsedAgoInSec=18, creationTimeAgoInSec=18}]
2015-10-15 18:00:13,924 DEBUG SQL:109 - 
    /* dynamic native SQL query */ SELECT
        user_id,
        username,
        email,
        is_active 
    FROM
        app_users
2015-10-15 18:00:14,018 TRACE BasicExtractor:78 - extracted value ([user_id] : [BIGINT]) - [43]
...
...
2015-10-15 18:00:14,177 TRACE BasicExtractor:78 - extracted value ([username] : [VARCHAR]) - [username33]
2015-10-15 18:00:14,178 TRACE BasicExtractor:78 - extracted value ([email] : [VARCHAR]) - [ss@ss.com]
2015-10-15 18:00:14,178 TRACE BasicExtractor:78 - extracted value ([is_active] : [INTEGER]) - [0]
2015-10-15 18:00:14,178 TRACE BasicExtractor:78 - extracted value ([user_id] : [BIGINT]) - [136]
2015-10-15 18:00:14,179 TRACE BasicExtractor:78 - extracted value ([username] : [VARCHAR]) - [username34]
2015-10-15 18:00:14,179 TRACE BasicExtractor:78 - extracted value ([email] : [VARCHAR]) - [ss2@ss.com]
2015-10-15 18:00:14,180 TRACE BasicExtractor:78 - extracted value ([is_active] : [INTEGER]) - [0]
2015-10-15 18:00:14,283 INFO  BaseDAOImpl:117 - ============getAll=============== Execution Timestamp: 433milliseconds
2015-10-15 18:00:14,284 DEBUG HibernateTransactionManager:759 - Initiating transaction commit
2015-10-15 18:00:14,286 DEBUG HibernateTransactionManager:580 - Committing Hibernate transaction on Session [SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=org.hibernate.engine.spi.ExecutableList@2b237512 updates=org.hibernate.engine.spi.ExecutableList@24db06de deletions=org.hibernate.engine.spi.ExecutableList@279febb9 orphanRemovals=org.hibernate.engine.spi.ExecutableList@742cd301 collectionCreations=org.hibernate.engine.spi.ExecutableList@2ad1223d collectionRemovals=org.hibernate.engine.spi.ExecutableList@81ee8c1 collectionUpdates=org.hibernate.engine.spi.ExecutableList@2542db11 collectionQueuedOps=org.hibernate.engine.spi.ExecutableList@483c4c33 unresolvedInsertDependencies=UnresolvedEntityInsertActions[]])]
2015-10-15 18:00:14,496 DEBUG HibernateTransactionManager:669 - Closing Hibernate Session [SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=org.hibernate.engine.spi.ExecutableList@2b237512 updates=org.hibernate.engine.spi.ExecutableList@24db06de deletions=org.hibernate.engine.spi.ExecutableList@279febb9 orphanRemovals=org.hibernate.engine.spi.ExecutableList@742cd301 collectionCreations=org.hibernate.engine.spi.ExecutableList@2ad1223d collectionRemovals=org.hibernate.engine.spi.ExecutableList@81ee8c1 collectionUpdates=org.hibernate.engine.spi.ExecutableList@2542db11 collectionQueuedOps=org.hibernate.engine.spi.ExecutableList@483c4c33 unresolvedInsertDependencies=UnresolvedEntityInsertActions[]])] after transaction
2015-10-15 18:00:14,499 INFO  StatisticalLoggingSessionEventListener:275 - Session Metrics {
    21735 nanoseconds spent acquiring 1 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    10155810 nanoseconds spent preparing 1 JDBC statements;
    69653167 nanoseconds spent executing 1 JDBC statements;
    0 nanoseconds spent executing 0 JDBC batches;
    11795265 nanoseconds spent performing 1 L2C puts;
    0 nanoseconds spent performing 0 L2C hits;
    69732 nanoseconds spent performing 1 L2C misses;
    0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
    31394 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
2015-10-15 18:00:14,639 INFO  AdminOperationController:49 - =======/admin/operation/UserManagement Execution Timestamp:====== 924milliseconds

With initializing caching

2015-10-15 18:00:22,410 DEBUG HibernateTransactionManager:516 - Exposing Hibernate transaction as JDBC transaction [ConnectionHandle{url=jdbc:mysql://test, user=test, debugHandle=null, lastResetAgoInSec=22, lastUsedAgoInSec=22, creationTimeAgoInSec=22}]
2015-10-15 18:00:22,417 INFO  BaseDAOImpl:117 - ============getAll=============== Execution Timestamp: 4milliseconds
2015-10-15 18:00:22,418 DEBUG HibernateTransactionManager:759 - Initiating transaction commit
2015-10-15 18:00:22,419 DEBUG HibernateTransactionManager:580 - Committing Hibernate transaction on Session [SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=org.hibernate.engine.spi.ExecutableList@19acc826 updates=org.hibernate.engine.spi.ExecutableList@1e8843f5 deletions=org.hibernate.engine.spi.ExecutableList@425997c orphanRemovals=org.hibernate.engine.spi.ExecutableList@407f9e04 collectionCreations=org.hibernate.engine.spi.ExecutableList@7a5f39b0 collectionRemovals=org.hibernate.engine.spi.ExecutableList@1c49094 collectionUpdates=org.hibernate.engine.spi.ExecutableList@fefe574 collectionQueuedOps=org.hibernate.engine.spi.ExecutableList@4ec12ad8 unresolvedInsertDependencies=UnresolvedEntityInsertActions[]])]
2015-10-15 18:00:22,625 DEBUG HibernateTransactionManager:669 - Closing Hibernate Session [SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=org.hibernate.engine.spi.ExecutableList@19acc826 updates=org.hibernate.engine.spi.ExecutableList@1e8843f5 deletions=org.hibernate.engine.spi.ExecutableList@425997c orphanRemovals=org.hibernate.engine.spi.ExecutableList@407f9e04 collectionCreations=org.hibernate.engine.spi.ExecutableList@7a5f39b0 collectionRemovals=org.hibernate.engine.spi.ExecutableList@1c49094 collectionUpdates=org.hibernate.engine.spi.ExecutableList@fefe574 collectionQueuedOps=org.hibernate.engine.spi.ExecutableList@4ec12ad8 unresolvedInsertDependencies=UnresolvedEntityInsertActions[]])] after transaction
2015-10-15 18:00:22,627 INFO  StatisticalLoggingSessionEventListener:275 - Session Metrics {
    19621 nanoseconds spent acquiring 1 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    0 nanoseconds spent preparing 0 JDBC statements;
    0 nanoseconds spent executing 0 JDBC statements;
    0 nanoseconds spent executing 0 JDBC batches;
    0 nanoseconds spent performing 0 L2C puts;
    2170444 nanoseconds spent performing 1 L2C hits;
    0 nanoseconds spent performing 0 L2C misses;
    0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
    19018 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
2015-10-15 18:00:22,766 INFO  AdminOperationController:49 - =======/admin/operation/UserManagement Execution Timestamp:====== 425milliseconds

Does anyone could suggest how should I improve this situation?

Answer 1

Finally solve the problem. Besides configuration solution(See my edited post, I use caching initialization), and I refactor my code to proceed appropriate DAO operations as much as possible in one transaction service method (Before that my transaction service only has very simplified method, i.e. I may need to call several transaction services methods for one workflow(e.g. registration a new user). It is very costly to do so.

It boosts my performance further.

As we see that in my post Update#2, the bottleneck is at the transaction commit. It is likely database server problem. Now I change the db to localhost. The speed has been further boosted to 20ms from 400~500ms

Answer 2

Please find some suggestions :

1. Set hibernate.show_sql to "false" and ensure that Hibernate logging is running at the lowest possible loglevel.
2. Define lazy loading as the preferred association loading strategy.
3. Set @Transactional(readOnly = true) on Queries and Criteria, when objects returned will never be modified.
4. Most queries do not benefit from caching, so by default, queries are not cached. To enable caching, call Query.setCacheable(true).
5. You can activate Hibernate Statistics to analyze performance issues (property hibernate.generate_statistics set to true).
6. Verify you have index on tables.