que tienen lo que supongo que es una configuración bastante estándar ... Spring, JPA (hibernación) y estoy tratando de añadir ehcache.Spring, JPA (Hibernate) y Ehcache degradación de las prestaciones
Lo tengo todo configurado y verificado que está funcionando ... Estoy registrando las sentencias sql de hibernación y las instrucciones de caché y puedo ver que la caché está siendo invocada y que una vez que el objeto está en la caché, cuando intento para volver a cargarlo, la instrucción SQL no está escrita (es decir, no está llegando a la base de datos).
Sin embargo, el rendimiento es terrible ... es más o menos el mismo rendimiento si consigo el objeto de la caché o desde el PP. Sospecho que tal vez el problema es que la primavera se vacíe automáticamente en la sesión de hibernación, o tal vez la sobrecarga se deba a transacciones (que he intentado desactivar para ese método), o quizás mi agrupación de conexiones usando c3p0 no esté funcionando bien suficiente. En cualquier caso, estoy en un poco de una pérdida ..
Voy a publicar toda la información relevante que tengo y es de esperar que algún genio aquí me puede ayudar a cabo por lo demás estoy atascado.
En primer lugar, mi primavera 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" />
Mi archivo ehcache es el siguiente
<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" />
Mi objeto en caché que está anotado con el fin de invocar la memoria caché es el siguiente:
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;
}
}
y mi aplicación de mi interfaz que se utiliza para guardar y sacar el objeto SystemProperty con el método @Transactional primavera es el siguiente:
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);
}
}
Tenga en cuenta que @Transactional es sólo en el método save. Finalmente, he llenado la base de datos mysql con 3000 objetos de propiedades del sistema y luego he escrito un pequeño archivo de prueba, que los carga dos veces.
La primera vez que los carga, puedo ver el SQL que se genera y que el caché no está siendo golpeado. La segunda vez, la memoria caché recibe un golpe y el sql no se genera.
Test Unit:
@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");
}
El archivo de registro tiene un montón de información. Publicaré la sección del archivo de registro en el área de "inicio de temporización 1". Esto corresponde a lo que ocurre solamente para el primer objeto que se carga cuando no está en la memoria caché:
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 [email protected] [managed: 5, unused: 4, excluded: 0] (e.g. [email protected])
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 [[email protected]] 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 [[email protected]] for key [org[email protected]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 [[email protected]] for key [org[email protected]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 [email protected] [managed: 5, unused: 4, excluded: 0] (e.g. [email protected])
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 [[email protected]] for key [org[email protected]11b99c4] from thread [main]
DEBUG 2010-10-22 11:57:49,612 [main][] org.springframework.transaction.support.TransactionSynchronizationManager - Removed value [[email protected]] 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
Se puede ver que se está haciendo cargado en la memoria caché, se abrió la sesión de hibernación y se cierra y enrojecida.
voy a publicar mi segundo archivo de registro en un comentario más abajo como he golpeado la longitud máxima ya de esta cuestión. El punto principal es que todo parece estar bien, el único problema real es que es muy lento.
Cuando cargo 3000 objetos por primera vez (es decir, golpeando el db) que tarda casi exactamente el mismo que teh segunda vez (es decir, golpeando el caché).Como dije, ¿es porque la sobrecarga está abriendo y cerrando la conexión, enjuagando la sesión, tratando transacciones? No estoy seguro. Pero es bastante brutal en cualquier caso. Ayúdame stackoverflow ... eres mi única esperanza :)
Parece que no puedo agregar otro comentario que muestra suficientes detalles de mi segundo archivo de registro. Basta con decir que es exactamente igual a la primera vez, excepto que golpea la caché. Por ejemplo, snippit: – Brian
Si necesita adjuntar más registros/código, http://pastebin.com/ es muy útil – skaffman
org.hibernate.engine.StatefulPersistenceContext - inicialización de colecciones no perezosas org.hibernate.event.def.DefaultLoadEventListener - Objeto resuelto en caché de segundo nivel: [com.model.SystemProperty # name_0] org.springframework.transaction.interceptor.TransactionInterceptor - Realización de transacción para [com.service.SystemPropertyManager.find] org.hibernate.transaction.JDBCTransaction - commit org.hibernate.impl.SessionImpl - sesión de vaciado automático – Brian