Hibernate事务管理器性能问题 [英] Hibernate Transaction Manager Performance Issue

查看：373
本文介绍了Hibernate事务管理器性能问题的处理方法，对大家解决问题具有一定的参考价值，需要的朋友们下面随着小编来一起学习吧！

问题描述

我目前在Hibernate中遇到性能问题

I am currently encountering Performance Issue in Hibernate

为了执行SQL语句（例如select * from table），只需要90ms来获取12列的10条记录

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

然而，让hibernate在DAO类中运行以下java代码

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

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

执行上述声明需要大约260~300 ms 仅 ，更不用说调用DAO的服务类中的额外执行时间。将花费大约600~1000毫秒。我怀疑大部分时间都花在了事务管理上。

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.

我不确定我的代码/配置出错的地方我也尝试了以下方法但是没有t太多了...

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. 在dataSource设置中添加连接池

  2. 使用hibernate本机SQL方法而不是DAO类中的createCriteria

  3. 启用延迟加载

  4. 增加tomcat服务器的堆大小

  5. 使用二级缓存提供程序

  6. @Transactional（readOnly = true）表示只读查询

  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. 通过配置EhCacheRegionFactory并一起启用二级缓存来启用hibernate缓存。然后在服务器启动时，我的Web应用程序通过手动触发服务调用来初始化缓存。在Hibernate从300~400ms获取sql查询到1~3ms之后，这可以成功地减少到Java类的数据绑定过程。但是，瓶颈就是交易......（见下面的更新＃2 ）

  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)

这是我的配置和代码

休眠配置 

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

DAO类中的getAll方法 

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;
    }

调用上述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

更新＃1：
启用hibernate统计信息后，我可以推断出大部分时间都花在了执行上声明由于以下统计数据。

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

事实证明，执行控制器类之间的执行时间几乎是10倍，调用只调用DAO的服务和通过hibernate执行语句

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

更新＃2

我尝试添加一些毫秒时间戳来追踪大部分时间花在哪个进程上。后来我发现大部分时间花在将hibernate事务暴露为jdbc事务并在每次服务操作后提交事务。统计查找日志列在下面

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初始化缓存

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?

推荐答案

最后解决问题。
除了配置解决方案（参见我编辑的帖子，我使用缓存初始化），我重构我的代码，以便在一个事务服务方法中尽可能多地进行适当的DAO操作（在此之前我的事务服务只有非常简化的方法，即我可能需要为一个工作流调用几种交易服务方法（例如注册新用户）。这样做成本非常高。

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.

正如我们在我的帖子Update＃2中看到的那样，瓶颈在于事务提交。可能是数据库服务器问题。现在我将db更改为localhost。速度从400~500ms进一步提升至20ms

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

这篇关于Hibernate事务管理器性能问题的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！

查看全文
相关文章
Java开发最新文章
热门教程
热门工具
登录 关闭
扫码关注1秒登录
发送“验证码”获取 | 15天全站免登陆