1. 首页
  2. 问题列表
  3. Hibernate事务管理器性能问题
提问者：小点点

Hibernate事务管理器性能问题


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

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

但是，要使hibernate在DAO类中运行以下java代码

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

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

我不确定我的代码/配置哪里出错了，我也尝试了以下方法，但没有太大帮助……

  1. 在dataSource设置中添加连接池
  2. 在DAO类中使用hibernate原生SQL方法而不是createCriteria
  3. 启用懒加载
  4. 增加tomcat服务器的堆大小
  5. 使用二级缓存提供程序
  6. @Transactional（只读=true）用于只读查询

加速操作的一些变通方法：

  1. 通过配置EhCacheRegion onFactory启用hibernate缓存，并一起启用二级缓存。然后在服务器启动时，我的Web应用程序通过手动触发服务调用来初始化缓存。这可以成功地将Hibernate获取sql查询后的数据绑定过程从300~400ms减少到1~3ms。然而，瓶颈在于提交事务的点…（参见下面的更新#2）

这是我的配置和代码

Hibernate配置

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

呼叫上述道的服务类

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

也欢迎在配置/代码中提出任何可以提高性能的建议。首先感谢

更新#1：启用Hibernate统计信息后，我可以推断出由于以下统计信息，大部分时间没有花在执行语句上。

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

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

更新#2

我尝试添加一些毫秒级的时间戳来追踪哪个进程花费了最多的时间。后来我发现了每次服务操作后暴露hibernate事务为jdbc事务和提交事务花费的大部分时间。下面列出了统计发现日志

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

通过初始化缓存

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

有人能建议我应该如何改善这种情况吗？


共2个答案

匿名用户

请找到一些建议：

  1. 设置hibernate。show_sql为false并确保Hibernate日志记录以尽可能低的loglevel运行。
  2. 将延迟加载定义为首选的关联加载策略。
  3. 在查询和条件上设置@Transactional（只读=true），当返回的对象永远不会被修改时。
  4. 大多数查询都不会从缓存中受益，因此默认情况下，查询不会被缓存。要启用缓存，请调用Query. setCacheable（true）。
  5. 您可以激活Hibernate统计来分析性能问题（属性hibernate.generate_statistics设置为true）。
  6. 验证您有表索引。

匿名用户

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

这进一步提高了我的表现。

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

相关问题



热门标签
Java JavaScript Python PHP C# Android Html jQuery C++ Css IOS MySQL NodeJS