Bri*_*ian 7 performance spring hibernate jpa ehcache
I have what I would assume is a pretty standard setup...spring, jpa (hibernate) and I'm trying to add ehcache.
I have it all configured and verified that it's working...I'm logging the hibernate sql statements and cache statements and can see that the cache is getting invoked and that once the object is in the cache, when I try to load it again, the sql statement is not written out (ie, it's not hitting the database).
However, the performance is terrible...it's pretty much the same performance if I get the object from the cache or from the db. I suspect that perhaps the problem is to do with spring automatically flushing the hibernate session, or maybe the overhead is due to transactions (which I have tried to turn off for that method), or maybe my connection pooling using c3p0 isn't working well enough. At any rate, I'm at a bit of a loss..
I'll post all the relevant information that I have and hopefully some genius here can help me out otherwise I'm stuck.
Firstly, my spring config:
<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&useUnicode=true&characterEncoding=UTF-8&jdbcCompliantTruncation=false&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" />
Run Code Online (Sandbox Code Playgroud)
My ehcache file is as follows
<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" />
Run Code Online (Sandbox Code Playgroud)
My cached object which is annotated in order to invoke the cache is as follows:
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;
}
}
Run Code Online (Sandbox Code Playgroud)
and my implementation of my interface used to save and get the SystemProperty object with the spring @Transactional method is as follows:
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);
}
}
Run Code Online (Sandbox Code Playgroud)
请注意,@ Transaction仅适用于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");
}
Run Code Online (Sandbox Code Playgroud)
日志文件有很多信息.我将在"开始时间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
Run Code Online (Sandbox Code Playgroud)
你可以看到它被加载到缓存中,hibernate会话被打开,关闭和刷新.
I'll post my second log file in a comment below as I've hit the max length already of this question. Main point is, it all looks ok, the only real problem is that it's sooo damn slow.
When I load 3000 objects the first time (ie, hitting the db) it takes pretty much exactly the same as teh second time (ie, hitting the cache). Like I said, is it cos the overhead is opening and closing the connection, flushing the session, dealing with transactions? I'm not sure. But it's pretty brutal at any rate. Help me stackoverflow...you're my only hope :)
要点是,一切看起来都不错,唯一真正的问题是它太慢了。
该死的慢是一个主观测量单位:)
当我第一次加载 3000 个对象时(即,访问数据库),它所花费的时间与第二次(即,访问缓存)几乎完全相同。
显示指标,没有所有日志记录开销(也没有 P6Spy),使用System.nanoTime()
long startTime = System.nanoTime();
// ... the code being measured ...
long estimatedTime = System.nanoTime() - startTime;
Run Code Online (Sandbox Code Playgroud)
也许还可以尝试使用单个事务在单个事务中执行测试EntityManager,只是为了看看在这些条件下事情的表现如何。
就像我说的,是因为开销是打开和关闭连接、刷新会话、处理事务吗?我不知道。但无论如何,这都是相当残酷的。
不能说,您应该分析您的代码以查看时间花在哪里(并监视 GC 活动)。
但理论上:
connection中的Session是惰性的(仅在需要时才会获取)connection应该相当快(可以忽略不计)flush应该非常快换句话说,我不认为上述操作会很昂贵(所以我会关注周围的部分)。但正如我所说,分析(并监视 GC 活动)。
| 归档时间: |
|
| 查看次数: |
11327 次 |
| 最近记录: |