Spring, JPA (Hibernate) and Ehcache Poor Performance

Question

Spring, JPA (Hibernate) and Ehcache Poor Performance

I have what I would suggest is a pretty standard setup ... spring, jpa (hibernate), and I'm trying to add ehcache.

I configured everything and checked that it works ... I register hibernate sql statements and cache statements and see that the cache is being called and that when the object is in the cache, when I try to load it again, the sql instruction is not written out (i.e. . it does not get into the database).

However, the performance is terrible ... it is almost the same performance if I get an object from the cache or from db. I suspect that maybe the problem is with spring automatically clearing the hibernation session, or maybe the overhead is related to transactions (which I tried to disable for this method), or maybe my connection pool using c3p0 is not working good enough. In any case, I am losing a little.

I will send all the relevant information that I have, and I hope some genius here can help me, 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&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" />

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

My cached object, which is annotated to call the cache, looks like this:

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

and my implementation of my interface used to save and retrieve a SystemProperty object using the spring @Transactional method looks like this:

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

Please note that @Transactional is used only for the save method. Finally, I populated a mysql database with 3000 system property objects, and then wrote a small test file that loads them twice.

The first time it loads them, I see how sql is generated and that the cache does not hit. The second time the cache hits, but sql is not generated.

Unit Test:

  @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"); }

There is a lot of information in the log file. I will send a section from the log file in the "start time 1" area. This corresponds to what happens only for the very first object that loads when it is not in the cache:

 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] (eg 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] (eg 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 , debugUnreturnedConnectionStackTraces -> false, description -> null, driverClass -> com.p6spy.engine.spy.P6SpyDriver, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> 31ghzi8b1mphf1c19l14qo | 149105b, idleConnectionTestPeriod 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] (eg 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] (eg 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 , debugUnreturnedConnectionStackTraces -> false, description -> null, driverClass -> com.p6spy.engine.spy.P6SpyDriver, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> 31ghzi8b1mphf1c19l14qo | 149105b, idleConnectionTestPeriod 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] (eg 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] (eg 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

You can see that it is loading into the cache, the sleep mode session opens and closes and is reset.

I will write my second log file in the comment below, since I have already reached the maximum length of this question. The main thing is that everything looks fine, the only real problem is that he is sooooo cursed slowly.

When I load 3000 objects the first time (i.e. getting into db), it takes almost the same thing as the second time (i.e. getting into the cache). As I said, is this because the overhead opens and closes the connection, clearing the session, dealing with transactions? I'm not sure. But it's pretty cruel, anyway. Help me stackoverflow ... you are my only hope :)

+6

performance spring hibernate jpa ehcache

Brian Oct 22 '10 at 13:06

source share

4 answers

I would suggest trying to replace this use of the 2nd level cache with a simple additive cache. When I tested the performance of Hibernate L2 cache in the past, I noticed that it is not very efficient. This is due to how the cached data is structured - similar to a result set - this is tabular data that is stored, not objects. This means that many cache requests are expensive.

To separate the cache code from the save logic, I use AOP. Since you are using Spring, this should be easy.

+4

Eran harel Oct 23 '10 at 11:27

source share

Are you sure you are not using the database in your cache? enable hibernate sql debug logger to make sure it is doing the right thing. I have never used an entity manager before. I always use a hibernation session. If you turn on the query cache, you still have to do setCache (true) in the sleep request. Otherwise, it will still fall in dB. The @Cache annotation essentially only caches its id in ehcache. When you set the cache cache, the cache key is your request, and the result is the identifier of the object, then it will try to resolve the entity in ehcache by id.

+2

michael cheung Apr 14 '11 at 1:19

source share

Your test directly uses EntityManager without transaction. EntityManager is bound to one unit of work, as a rule, to one transaction. You are probably forcing a new transaction, incl. Search in the database connection pool for each search call.

Here is what I would suggest:

use read-only transactions for non-persistent methods instead of TX demarcation
wrap your DataSource bean in a LazyConnectionDataSourceProxy to avoid getting a connection if you really don't need to talk to your database (i.e. if you hit the cache)
update your test to talk to your bean service instead of using EntityManager directly.

+2

Joris kuipers May 21 '12 at 9:24

source share

Pascal thivent · Accepted Answer · 2010-10-22T14:54:10+0000

The main thing is that everything looks normal, the only real problem is that it is clouded slowly.

Damn slow is a subjective unit :)

When I load 3000 objects the first time (i.e. getting into db), it takes almost the same thing as the second time (i.e. getting into the cache).

Show metrics without all logging costs (and also without P6Spy) using System.nanoTime()

 long startTime = System.nanoTime(); // ... the code being measured ... long estimatedTime = System.nanoTime() - startTime;

You might also try running your test inside a single transaction using a single EntityManager to see how things behave in these conditions.

As I said, is this because overhead is opening and closing a connection, clearing a session, working with transactions? I'm not sure. But it's pretty cruel, anyway.

This is not to say that you should comment on your code to find out where the time has been spent (as well as to monitor the activities of the GC).

But in theory:

connection in Session is lazy (acquired only if necessary)
Acquiring a connection from C3P0 should be fairly quick (negligible)
Since your objects are cached as read-only, flush should be pretty fast

In other words, I would not expect the above operations to be expensive (so I would focus on the surrounding parts). But, as I said, profile (and track GC activity).

Spring, JPA (Hibernate) and Ehcache Poor Performance

More articles: