performance - Spring、JPA (Hibernate) 和 Ehcache 性能不佳

Question

我有我认为是一个非常标准的设置...spring，jpa( hibernate )，我正在尝试添加ehcache。

我已全部配置并验证它是否正常工作...我正在记录 hibernate sql 语句和缓存语句，并且可以看到缓存正在被调用，并且一旦对象在缓存中，当我尝试再次加载它时, sql 语句没有写出(即它没有命中数据库)。

但是，性能很糟糕......如果我从缓存或数据库中获取对象，性能几乎相同。我怀疑问题可能与 spring 自动刷新 hibernate session 有关，或者开销可能是由于事务(我试图为该方法关闭)，或者我使用 c3p0 的连接池工作不正常足够。无论如何，我有点茫然..

我将发布我拥有的所有相关信息，希望这里的一些天才可以帮助我，否则我会被卡住。

首先，我的 Spring 配置:

<beans xmlns="http://www.springframework.org/schema/beans"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xmlns:aop="http://www.springframework.org/schema/aop"
xmlns:tx="http://www.springframework.org/schema/tx"
xmlns:hprof="http://www.nhprof.com/schema/hprof"
xsi:schemaLocation="
http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans-2.0.xsd
http://www.springframework.org/schema/tx http://www.springframework.org/schema/tx/spring-tx-2.0.xsd
http://www.springframework.org/schema/aop http://www.springframework.org/schema/aop/spring-aop-2.0.xsd
http://www.nhprof.com/schema/hprof http://www.nhprof.com/schema/hprof/hprof.xsd">


<bean class="org.springframework.orm.jpa.support.PersistenceAnnotationBeanPostProcessor" />

<bean id="systemPropertyManager" class="com.service.impl.SystemPropertyManagerImpl" />
<bean id="entityManagerFactory" class="org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean">
     <property name="dataSource" ref="mysql" /> 
    <property name="jpaVendorAdapter">
        <bean
            class="org.springframework.orm.jpa.vendor.HibernateJpaVendorAdapter">
            <property name="database" value="MYSQL" />
            <property name="showSql" value="true" />
        </bean>
    </property>
    <property name="jpaProperties">
        <props>

           <prop key="hibernate.dialect">org.hibernate.dialect.MySQLDialect</prop>
           <!-- always puts logging out to the console...we want it in the log file -->
           <prop key="hibernate.connection.show_sql">false</prop>
           <prop key="hibernate.hbm2ddl.auto">update</prop>
       <prop key="hibernate.cache.provider_class">net.sf.ehcache.hibernate.SingletonEhCacheProvider</prop>
       <prop key="net.sf.ehcache.configurationResourceName">ehcache.xml</prop>
           <prop key="hibernate.cache.use_second_level_cache">true</prop>
           <prop key="hibernate.cache.use_structured_entries">true</prop>
           <prop key="hibernate.cache.use_query_cache">true</prop>
           <prop key="hibernate.generate_statistics">true</prop>
           <prop key="hibernate.default_batch_fetch_size">500</prop>
           <prop key="hibernate.max_fetch_depth">5</prop>
           <prop key="hibernate.jdbc.batch_size">1000</prop>
           <prop key="hibernate.use_outer_join">true</prop>
        </props>
    </property> 
 <!--   <hprof:profiler /> -->
</bean>


 <bean id="mysql" class="com.mchange.v2.c3p0.ComboPooledDataSource" destroy-method="close">
  <property name="driverClass" value="com.mysql.jdbc.Driver" />
    <property name="jdbcUrl" value="jdbc:mysql://localhost/daily?relaxAutoCommit=true&amp;useUnicode=true&amp;characterEncoding=UTF-8&amp;jdbcCompliantTruncation=false&amp;emulateLocators=true" />
    <property name="user" value="root" />
    <property name="password" value="" />
    <property name="initialPoolSize"><value>5</value></property>
    <property name="minPoolSize"><value>5</value></property>
    <property name="maxPoolSize"><value>50</value></property>
    <property name="idleConnectionTestPeriod"><value>200</value></property>
    <property name="acquireIncrement"><value>3</value></property>
    <property name="numHelperThreads"><value>3</value></property>
</bean>

<bean id="transactionManager" class="org.springframework.orm.jpa.JpaTransactionManager">
    <property name="entityManagerFactory" ref="entityManagerFactory" />
</bean>

<tx:annotation-driven transaction-manager="transactionManager" />

我的ehcache文件如下

<ehcache>
<diskStore path="c:/cache"/>

    <defaultCache eternal="false" 
            overflowToDisk="false"
            maxElementsInMemory="50000" 
            timeToIdleSeconds="30" 
            timeToLiveSeconds="6000"
            memoryStoreEvictionPolicy="LRU"
            />
    <cache name="com.model.SystemProperty"
            maxElementsInMemory="5000"
            eternal="true"
            overflowToDisk="false"
            memoryStoreEvictionPolicy="LFU" />              

为了调用缓存而注释的我的缓存对象如下:

package com.model;

import javax.persistence.*;

import org.hibernate.annotations.Cache;
import org.hibernate.annotations.CacheConcurrencyStrategy;

@Entity
@Cache(usage = CacheConcurrencyStrategy.READ_ONLY, region="com.model.SystemProperty", include="non-lazy")
@EntityListeners(com.util.GenericEntityLogger.class)
public class SystemProperty extends BaseObject{

    private String name;
    private String value;

    // default constructor
    public SystemProperty(){

    }
    public SystemProperty(String name, String value){
        this.name = name;
        this.value = value;
    }

    @Id
    public String getName() {
        return name;
    }
    public void setName(String name) {
        this.name = name;
    }

    public String getValue() {
        return value;
    }
    public void setValue(String value) {
        this.value = value;
    }

    @Override
    public boolean equals(Object o) {
        // TODO Auto-generated method stub
        return false;
    }
    @Override
    public int hashCode() {
        // TODO Auto-generated method stub
        return 0;
    }
    @Override
    public String toString() {
        // TODO Auto-generated method stub
        return null;
    }


}

我使用spring @Transactional 方法保存和获取SystemProperty对象的接口(interface)实现如下:

package com.service.impl;

import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.springframework.transaction.annotation.Transactional;

import com.model.SystemProperty;
import com.service.SystemPropertyManager;


public class SystemPropertyManagerImpl extends BaseManagerImpl implements SystemPropertyManager {

    // logging
    protected final Log log = LogFactory.getLog(getClass());

    public SystemProperty find(String name){
        return (SystemProperty) super.entityManager.find(SystemProperty.class, name);
    }

    @Transactional
    public SystemProperty save(SystemProperty prop){
        return (SystemProperty) super.save(prop);
    }

}

请注意，@Transactional 仅在 save 方法上。
最后，我用 3000 个系统属性对象填充了 mysql 数据库，然后编写了一个小测试文件，将它们加载了两次。

第一次加载它们时，我可以看到正在生成的 sql 并且缓存没有被命中。第二次，缓存确实被命中并且没有生成 sql。

单元测试:

    @Test
public void testGetCachedUser1(){
    log.debug("starting testGetCachedUser");
    SystemPropertyManager mgr = ManagerFactory.getSystemPropertyManager();
    EntityManager em = mgr.getEntityManager();

    log.debug("start timing 1");
    for(int i = 0; i<3000; i ++){
        mgr.find("name_"+i);
    }
    log.debug("end timing 1");
    log.debug("start timing 2");
    for(int i = 0; i<3000; i ++){
        mgr.find("name_"+i);
    }
    log.debug("end timing 2");
}   

日志文件有很多信息。我将在“开始计时 1”区域中发布日志文件中的部分。这对应于仅在加载的第一个对象不在缓存中时发生的情况:

DEBUG 2010-10-22 11:57:49,533 [main][] org.springframework.transaction.annotation.AnnotationTransactionAttributeSource - Adding transactional method [find] with attribute [PROPAGATION_REQUIRED,ISOLATION_DEFAULT]
DEBUG 2010-10-22 11:57:49,533 [main][] org.hibernate.impl.SessionImpl - opened session at timestamp: 5274603804807168
DEBUG 2010-10-22 11:57:49,533 [main][] org.hibernate.transaction.JDBCTransaction - begin
DEBUG 2010-10-22 11:57:49,533 [main][] org.hibernate.jdbc.ConnectionManager - opening JDBC connection
DEBUG 2010-10-22 11:57:49,533 [main][] com.mchange.v2.resourcepool.BasicResourcePool - trace com.mchange.v2.resourcepool.BasicResourcePool@4e2f0a [managed: 5, unused: 4, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@1631573)
DEBUG 2010-10-22 11:57:49,533 [main][] org.hibernate.transaction.JDBCTransaction - current autocommit status: true
DEBUG 2010-10-22 11:57:49,533 [main][] org.hibernate.transaction.JDBCTransaction - disabling autocommit
DEBUG 2010-10-22 11:57:49,533 [main][] org.hibernate.jdbc.JDBCContext - after transaction begin
DEBUG 2010-10-22 11:57:49,549 [main][] org.springframework.transaction.support.TransactionSynchronizationManager - Bound value [org.springframework.jdbc.datasource.ConnectionHolder@5fbbf3] for key [com.mchange.v2.c3p0.ComboPooledDataSource [ acquireIncrement -> 3, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, dataSourceName -> 31ghzi8b1mphf1c19l14qo|149105b, debugUnreturnedConnectionStackTraces -> false, description -> null, driverClass -> com.p6spy.engine.spy.P6SpyDriver, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> 31ghzi8b1mphf1c19l14qo|149105b, idleConnectionTestPeriod -> 200, initialPoolSize -> 5, jdbcUrl -> jdbc:mysql://localhost/daily?relaxAutoCommit=true&useUnicode=true&characterEncoding=UTF-8&jdbcCompliantTruncation=false&emulateLocators=true, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 0, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 50, maxStatements -> 0, maxStatementsPerConnection -> 0, minPoolSize -> 5, numHelperThreads -> 3, numThreadsAwaitingCheckoutDefaultUser -> 0, preferredTestQuery -> null, properties -> {user=******, password=******}, propertyCycle -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, usesTraditionalReflectiveProxies -> false ]] to thread [main]
DEBUG 2010-10-22 11:57:49,549 [main][] org.springframework.transaction.support.TransactionSynchronizationManager - Bound value [org.springframework.orm.jpa.EntityManagerHolder@1bb03ee] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@11b99c4] to thread [main]
DEBUG 2010-10-22 11:57:49,549 [main][] org.springframework.transaction.support.TransactionSynchronizationManager - Initializing transaction synchronization
DEBUG 2010-10-22 11:57:49,549 [main][] org.springframework.transaction.interceptor.TransactionInterceptor - Getting transaction for [com.service.SystemPropertyManager.find]
DEBUG 2010-10-22 11:57:49,549 [main][] org.springframework.transaction.support.TransactionSynchronizationManager - Retrieved value [org.springframework.orm.jpa.EntityManagerHolder@1bb03ee] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@11b99c4] bound to thread [main]
DEBUG 2010-10-22 11:57:49,549 [main][] org.hibernate.event.def.DefaultLoadEventListener - loading entity: [com.model.SystemProperty#name_0]
DEBUG 2010-10-22 11:57:49,549 [main][] org.hibernate.event.def.DefaultLoadEventListener - attempting to resolve: [com.model.SystemProperty#name_0]
DEBUG 2010-10-22 11:57:49,549 [main][] org.hibernate.event.def.DefaultLoadEventListener - object not resolved in any cache: [com.model.SystemProperty#name_0]
DEBUG 2010-10-22 11:57:49,549 [main][] org.hibernate.persister.entity.AbstractEntityPersister - Fetching entity: [com.model.SystemProperty#name_0]
DEBUG 2010-10-22 11:57:49,549 [main][] org.hibernate.loader.Loader - loading entity: [com.model.SystemProperty#name_0]
DEBUG 2010-10-22 11:57:49,549 [main][] org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
DEBUG 2010-10-22 11:57:49,549 [main][] org.hibernate.SQL - select systemprop0_.name as name11_0_, systemprop0_.value as value11_0_ from SystemProperty systemprop0_ where systemprop0_.name=?
DEBUG 2010-10-22 11:57:49,549 [main][] org.hibernate.jdbc.AbstractBatcher - preparing statement
DEBUG 2010-10-22 11:57:49,580 [main][] org.hibernate.type.StringType - binding 'name_0' to parameter: 1
DEBUG 2010-10-22 11:57:49,580 [main][] org.hibernate.jdbc.AbstractBatcher - about to open ResultSet (open ResultSets: 0, globally: 0)
DEBUG 2010-10-22 11:57:49,580 [main][] org.hibernate.loader.Loader - processing result set
DEBUG 2010-10-22 11:57:49,580 [main][] org.hibernate.loader.Loader - result set row: 0
DEBUG 2010-10-22 11:57:49,580 [main][] org.hibernate.loader.Loader - result row: EntityKey[com.model.SystemProperty#name_0]
DEBUG 2010-10-22 11:57:49,580 [main][] org.hibernate.loader.Loader - Initializing object from ResultSet: [com.model.SystemProperty#name_0]
DEBUG 2010-10-22 11:57:49,580 [main][] org.hibernate.persister.entity.AbstractEntityPersister - Hydrating entity: [com.model.SystemProperty#name_0]
DEBUG 2010-10-22 11:57:49,580 [main][] org.hibernate.type.StringType - returning 'value_0' as column: value11_0_
DEBUG 2010-10-22 11:57:49,580 [main][] org.hibernate.loader.Loader - done processing result set (1 rows)
DEBUG 2010-10-22 11:57:49,580 [main][] org.hibernate.jdbc.AbstractBatcher - about to close ResultSet (open ResultSets: 1, globally: 1)
DEBUG 2010-10-22 11:57:49,580 [main][] org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
DEBUG 2010-10-22 11:57:49,580 [main][] org.hibernate.jdbc.AbstractBatcher - closing statement
DEBUG 2010-10-22 11:57:49,580 [main][] org.hibernate.loader.Loader - total objects hydrated: 1
DEBUG 2010-10-22 11:57:49,580 [main][] org.hibernate.engine.TwoPhaseLoad - resolving associations for [com.model.SystemProperty#name_0]
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.engine.TwoPhaseLoad - adding entity to second-level cache: [com.model.SystemProperty#name_0]
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.cache.ReadOnlyCache - Caching: com.model.SystemProperty#name_0
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.engine.TwoPhaseLoad - done materializing entity [com.model.SystemProperty#name_0]
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.engine.StatefulPersistenceContext - initializing non-lazy collections
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.loader.Loader - done entity load
DEBUG 2010-10-22 11:57:49,596 [main][] org.springframework.transaction.interceptor.TransactionInterceptor - Completing transaction for [com.service.SystemPropertyManager.find]
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.transaction.JDBCTransaction - commit
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.impl.SessionImpl - automatically flushing session
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.event.def.AbstractFlushingEventListener - flushing session
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.event.def.AbstractFlushingEventListener - processing flush-time cascades
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.engine.Cascade - processing cascade ACTION_PERSIST_ON_FLUSH for: com.model.SystemProperty
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.engine.Cascade - done processing cascade ACTION_PERSIST_ON_FLUSH for: com.model.SystemProperty
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.event.def.AbstractFlushingEventListener - dirty checking collections
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.event.def.AbstractFlushingEventListener - Flushing entities and processing referenced collections
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.event.def.AbstractFlushingEventListener - Processing unreferenced collections
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.event.def.AbstractFlushingEventListener - Scheduling collection removes/(re)creates/updates
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.event.def.AbstractFlushingEventListener - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.event.def.AbstractFlushingEventListener - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.pretty.Printer - listing entities:
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.pretty.Printer - com.model.SystemProperty{name=name_0, value=value_0}
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.event.def.AbstractFlushingEventListener - executing flush
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.jdbc.ConnectionManager - registering flush begin
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.jdbc.ConnectionManager - registering flush end
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.event.def.AbstractFlushingEventListener - post flush
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.jdbc.JDBCContext - before transaction completion
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.impl.SessionImpl - before transaction completion
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.transaction.JDBCTransaction - re-enabling autocommit
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.transaction.JDBCTransaction - committed JDBC Connection
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.jdbc.JDBCContext - after transaction completion
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
DEBUG 2010-10-22 11:57:49,596 [main][] com.mchange.v2.resourcepool.BasicResourcePool - trace com.mchange.v2.resourcepool.BasicResourcePool@4e2f0a [managed: 5, unused: 4, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@1631573)
DEBUG 2010-10-22 11:57:49,596 [main][] org.hibernate.impl.SessionImpl - after transaction completion
DEBUG 2010-10-22 11:57:49,596 [main][] org.springframework.transaction.support.TransactionSynchronizationManager - Clearing transaction synchronization
DEBUG 2010-10-22 11:57:49,596 [main][] org.springframework.transaction.support.TransactionSynchronizationManager - Removed value [org.springframework.orm.jpa.EntityManagerHolder@1bb03ee] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@11b99c4] from thread [main]
DEBUG 2010-10-22 11:57:49,612 [main][] org.springframework.transaction.support.TransactionSynchronizationManager - Removed value [org.springframework.jdbc.datasource.ConnectionHolder@5fbbf3] for key [com.mchange.v2.c3p0.ComboPooledDataSource [ acquireIncrement -> 3, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, dataSourceName -> 31ghzi8b1mphf1c19l14qo|149105b, debugUnreturnedConnectionStackTraces -> false, description -> null, driverClass -> com.p6spy.engine.spy.P6SpyDriver, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> 31ghzi8b1mphf1c19l14qo|149105b, idleConnectionTestPeriod -> 200, initialPoolSize -> 5, jdbcUrl -> jdbc:mysql://localhost/daily?relaxAutoCommit=true&useUnicode=true&characterEncoding=UTF-8&jdbcCompliantTruncation=false&emulateLocators=true, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 0, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 50, maxStatements -> 0, maxStatementsPerConnection -> 0, minPoolSize -> 5, numHelperThreads -> 3, numThreadsAwaitingCheckoutDefaultUser -> 0, preferredTestQuery -> null, properties -> {user=******, password=******}, propertyCycle -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, usesTraditionalReflectiveProxies -> false ]] from thread [main]
DEBUG 2010-10-22 11:57:49,612 [main][] org.hibernate.impl.SessionImpl - closing session
DEBUG 2010-10-22 11:57:49,612 [main][] org.hibernate.jdbc.ConnectionManager - connection already null in cleanup : no action

您可以看到它被加载到缓存中， hibernate session 被打开和关闭并刷新。

我将在下面的评论中发布我的第二个日志文件，因为我已经达到了这个问题的最大长度。重点是，一切看起来都不错，唯一真正的问题是它太慢了。

当我第一次加载 3000 个对象(即命中数据库)时，它与第二次加载几乎完全相同(即命中缓存)。就像我说的那样，开销是打开和关闭连接、刷新 session 、处理事务吗？我不知道。但无论如何，这都是相当残酷的。帮我stackoverflow...你是我唯一的希望:)

Answer 1

我建议尝试用普通的应用缓存替换二级缓存的使用。当我过去测试 Hibernate 的二级缓存性能时，我发现它不是很有效。这是由于缓存数据的结构方式——类似于结果集——即存储的是表格数据，而不是对象。这意味着许多缓存请求，结果证明是昂贵的。

为了将缓存代码与持久化逻辑分离，我使用了 AOP。由于您使用 Spring，这应该很容易。