Hi,
I'm trying to get my second level cache configured in Hibernate. I'm thinking of using EHCache, because eventually I'll be needing a distributed cache.
I've come to the point where the second level cache is working. I've drawn that conclusion because there is no more SQL output after I've filled the cache, cache statistics seem ok, and performance is better but...
not
that much better, only about a factor 5 or 6.
To obtain some kind of theoretical maximum, I disable second level cache, and add my own "cache" to my DAO: a ConcurrentHashMap. In this case, fetching performs better by a factor of, well, about 4000.
My unit tests pass too, so I'm assuming the ConcurrentHashMap is actually doing what it's supposed to do.
Any idea why Hibernate+EHCache is so slow?
This is my hibernate.properties:
Code:
hibernate.show_sql=false
hibernate.dialect=org.hibernate.dialect.Oracle9Dialect
#hibernate.dialect=org.hibernate.dialect.HSQLDialect
hibernate.jdbc.batch_size=30
hibernate.cache.use_query_cache=false
hibernate.cache.use_second_level_cache=false
#hibernate.cache.provider_class=net.sf.ehcache.hibernate.EhCacheProvider
#net.sf.ehcache.configurationResourceName=/ehcache.xml
hibernate.cache.provider_class=org.hibernate.cache.EhCacheProvider
hibernate.cache.provider_configuration_file_resource_path=ehcache.xml
hibernate.generate_statistics=true
These are Hibernate's startup logs:
Code:
16:17:19,796-INFO -org.hibernate.cfg.Environment|[]| Hibernate 3.1.3 |main
16:17:19,807-INFO -org.hibernate.cfg.Environment|[]| loaded properties from resource hibernate.properties: {hibernate.cglib.use_reflection_optimizer=true, hibernate.cache.provider_class=org.hibernate.cache.EhCacheProvider, hibernate.cache.use_query_cache=false, hibernate.dialect=org.hibernate.dialect.Oracle9Dialect, hibernate.cache.use_second_level_cache=true, hibernate.cache.provider_configuration_file_resource_path=ehcache.xml, hibernate.jdbc.batch_size=30, hibernate.generate_statistics=true, hibernate.show_sql=false} |main
16:17:19,808-INFO -org.hibernate.cfg.Environment|[]| using CGLIB reflection optimizer |main
16:17:19,808-INFO -org.hibernate.cfg.Environment|[]| using JDK 1.4 java.sql.Timestamp handling |main
16:17:20,219-INFO -org.hibernate.cfg.HbmBinder|[]| Mapping class: com.nsn.idtv.ibilling.domain.Transaction -> TRANSACTIONS |main
16:17:20,410-INFO -org.hibernate.cfg.HbmBinder|[]| Mapping class: com.nsn.idtv.ibilling.trax.dto.ProviderDto -> PROVIDERS |main
16:17:20,466-INFO -org.hibernate.cfg.HbmBinder|[]| Mapping class: com.nsn.idtv.ibilling.trax.dto.EventDto -> EVENTS |main
16:17:20,582-INFO -org.hibernate.cfg.HbmBinder|[]| Mapping class: com.nsn.idtv.ibilling.trax.dto.StbDto -> STBS |main
16:17:20,604-INFO -org.hibernate.cfg.HbmBinder|[]| Mapping class: com.nsn.idtv.ibilling.trax.dto.TmDto -> TMS |main
16:17:20,623-INFO -org.hibernate.cfg.HbmBinder|[]| Mapping class: com.nsn.idtv.ibilling.trax.dto.SubscriberDto -> SUBSCRIBERS |main
16:17:20,914-INFO -org.hibernate.connection.ConnectionProviderFactory|[]| Initializing connection provider: org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider |main
16:17:21,246-INFO -org.hibernate.cfg.SettingsFactory|[]| RDBMS: Oracle, version: Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - 64bit Production
With the Partitioning, OLAP and Data Mining options |main
16:17:21,246-INFO -org.hibernate.cfg.SettingsFactory|[]| JDBC driver: Oracle JDBC driver, version: 10.2.0.4.0 |main
16:17:21,281-INFO -org.hibernate.dialect.Dialect|[]| Using dialect: org.hibernate.dialect.Oracle9Dialect |main
16:17:21,291-INFO -org.hibernate.transaction.TransactionFactoryFactory|[]| Using default transaction strategy (direct JDBC transactions) |main
16:17:21,294-INFO -org.hibernate.transaction.TransactionManagerLookupFactory|[]| No TransactionManagerLookup configured (in JTA environment, use of read-write or transactional second-level cache is not recommended) |main
16:17:21,295-INFO -org.hibernate.cfg.SettingsFactory|[]| Automatic flush during beforeCompletion(): disabled |main
16:17:21,296-INFO -org.hibernate.cfg.SettingsFactory|[]| Automatic session close at end of transaction: disabled |main
16:17:21,296-INFO -org.hibernate.cfg.SettingsFactory|[]| JDBC batch size: 30 |main
16:17:21,296-INFO -org.hibernate.cfg.SettingsFactory|[]| JDBC batch updates for versioned data: disabled |main
16:17:21,297-INFO -org.hibernate.cfg.SettingsFactory|[]| Scrollable result sets: enabled |main
16:17:21,297-INFO -org.hibernate.cfg.SettingsFactory|[]| JDBC3 getGeneratedKeys(): enabled |main
16:17:21,297-INFO -org.hibernate.cfg.SettingsFactory|[]| Connection release mode: on_close |main
16:17:21,297-INFO -org.hibernate.cfg.SettingsFactory|[]| Default batch fetch size: 1 |main
16:17:21,297-INFO -org.hibernate.cfg.SettingsFactory|[]| Generate SQL with comments: disabled |main
16:17:21,298-INFO -org.hibernate.cfg.SettingsFactory|[]| Order SQL updates by primary key: disabled |main
16:17:21,298-INFO -org.hibernate.cfg.SettingsFactory|[]| Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory |main
16:17:21,301-INFO -org.hibernate.hql.ast.ASTQueryTranslatorFactory|[]| Using ASTQueryTranslatorFactory |main
16:17:21,301-INFO -org.hibernate.cfg.SettingsFactory|[]| Query language substitutions: {} |main
16:17:21,301-INFO -org.hibernate.cfg.SettingsFactory|[]| Second-level cache: enabled |main
16:17:21,301-INFO -org.hibernate.cfg.SettingsFactory|[]| Query cache: disabled |main
16:17:21,302-INFO -org.hibernate.cfg.SettingsFactory|[]| Cache provider: org.hibernate.cache.EhCacheProvider |main
16:17:21,308-INFO -org.hibernate.cfg.SettingsFactory|[]| Optimize cache for minimal puts: disabled |main
16:17:21,308-INFO -org.hibernate.cfg.SettingsFactory|[]| Structured second-level cache entries: disabled |main
16:17:21,315-INFO -org.hibernate.cfg.SettingsFactory|[]| Statistics: enabled |main
16:17:21,315-INFO -org.hibernate.cfg.SettingsFactory|[]| Deleted entity synthetic identifier rollback: disabled |main
16:17:21,315-INFO -org.hibernate.cfg.SettingsFactory|[]| Default entity-mode: pojo |main
16:17:21,357-INFO -org.hibernate.impl.SessionFactoryImpl|[]| building session factory |main
16:17:21,820-INFO -org.hibernate.impl.SessionFactoryObjectFactory|[]| Not binding factory to JNDI, no JNDI name configured |main
This is my EHCache configuration:
Code:
<ehcache xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:noNamespaceSchemaLocation="ehcache.xsd">
<defaultCache
maxElementsInMemory="10000"
eternal="true"
overflowToDisk="false"
memoryStoreEvictionPolicy="LRU" />
<cache name="com.nsn.idtv.ibilling.trax.dto.EventDto"
maxElementsInMemory="10000"
eternal="true"
overflowToDisk="false"
memoryStoreEvictionPolicy="LRU" />
<cache name="org.hibernate.cache.StandardQueryCache"
maxElementsInMemory="5"
eternal="false"
timeToLiveSeconds="120"
overflowToDisk="false"/>
<cache name="org.hibernate.cache.UpdateTimestampsCache"
maxElementsInMemory="1000"
eternal="true"
overflowToDisk="false"/>
<!-- <cacheEventListenerFactory
class="net.sf.ehcache.distribution.RMICacheReplicatorFactory"/> -->
<!-- <cacheManagerPeerProviderFactory
class="net.sf.ehcache.distribution.RMICacheManagerPeerProviderFactory"
properties="peerDiscovery=automatic,
multicastGroupAddress=230.0.0.1,
multicastGroupPort=4446"/>
<cacheManagerPeerListenerFactory
class="net.sf.ehcache.distribution.RMICacheManagerPeerListenerFactory"/> -->
</ehcache>
These are the test results:
Code:
org.hibernate.cache.HashtableCacheProvider
16:13:38,329-INFO -com.nsn.idtv.ibilling.service.event.EventManagerPerformanceComparator|[]| regular hibernateEventDao filled the cache in 55.485 seconds |main
16:15:14,027-INFO -com.nsn.idtv.ibilling.service.event.EventManagerPerformanceComparator|[]| regular hibernateEventDao duration: 95.697 seconds |main
16:15:14,027-INFO -com.nsn.idtv.ibilling.service.event.EventManagerPerformanceComparator|[]| second level cache: size == 10000, hit count == 10000 |main
Code:
org.hibernate.cache.EhCacheProvider
16:18:54,894-INFO -com.nsn.idtv.ibilling.service.event.EventManagerPerformanceComparator|[]| regular hibernateEventDao filled the cache in 55.803 seconds |main
16:20:31,613-INFO -com.nsn.idtv.ibilling.service.event.EventManagerPerformanceComparator|[]| regular hibernateEventDao duration: 96.718 seconds |main
16:20:31,618-INFO -com.nsn.idtv.ibilling.service.event.EventManagerPerformanceComparator|[]| second level cache: size == 10000, hit count == 10000 |main
Code:
java.util.concurrent.ConcurrentHashMap:
16:31:15,633-INFO -com.nsn.idtv.ibilling.service.event.EventManagerPerformanceComparator|[]| regular hibernateEventDao filled the cache in 76.119 seconds |main
16:31:15,816-INFO -com.nsn.idtv.ibilling.service.event.EventManagerPerformanceComparator|[]| regular hibernateEventDao duration: 0.183 seconds |main
This is the DAO method I'm calling in my test (this method has the ConcurrentHashMap in it - that code is only used when second level cache is disabled):
Code:
public EventDto getEvent(String providerId, String eventId) throws TraxDBException {
/*List<EventDto> results = hibernateTemplate.find(GET_EVENT_BY_PROVIDER_ID_AND_EVENT_ID_QUERY, new Object[] { providerId, eventId });
return results.size() > 0 ? results.get(0): null;*/
String key = new StringBuffer().append(providerId).append(".").append(eventId).toString();
EventDto result = cache.get(key);
if (result != null)
return result;
result = (EventDto)hibernateTemplate.get(EventDto.class, new EventPK(providerId, eventId));
cache.put(key, result);
return result;
}
Finally, my test method:
Code:
public void start() throws Exception {
long startTime, duration;
for (NamedEventDao namedEventDao: namedEventDaos){
Session session = SessionFactoryUtils.getSession(sessionFactory, true);
TransactionSynchronizationManager.bindResource(sessionFactory, new SessionHolder(session));
initializeDatabase();
SessionFactoryUtils.getSession(sessionFactory, false).clear();
// fill cache
startTime = System.currentTimeMillis();
for (int i = 0; i < NUMBER_OF_PROVIDERS; i++) {
for (int j = 0; j < NUMBER_OF_EVENTS; j++) {
namedEventDao.getEventDao().getEvent(PROVIDER_PREFIX + i, EVENT_PREFIX + j);
}
}
duration = System.currentTimeMillis() - startTime;
logger.info(namedEventDao.getName() + " filled the cache in " + (double)duration/1000 + " seconds");
SessionFactoryUtils.getSession(sessionFactory, false).clear();
// actual run
startTime = System.currentTimeMillis();
for (int n = 0; n < NUMBER_OF_CYCLES; n++) {
for (int i = 0; i < NUMBER_OF_PROVIDERS; i++) {
for (int j = 0; j < NUMBER_OF_EVENTS; j++) {
namedEventDao.getEventDao().getEvent(PROVIDER_PREFIX + i, EVENT_PREFIX + j);
}
}
}
duration = System.currentTimeMillis() - startTime;
logger.info(namedEventDao.getName() + " duration: " + (double)duration/1000 + " seconds");
SecondLevelCacheStatistics stats = sessionFactory.getStatistics().getSecondLevelCacheStatistics("com.nsn.idtv.ibilling.trax.dto.EventDto");
if (stats != null)
logger.info("second level cache: size == " + stats.getElementCountInMemory() + ", hit count == " + stats.getHitCount());
TransactionSynchronizationManager.unbindResource(sessionFactory);
SessionFactoryUtils.releaseSession(session, sessionFactory);
}
}
In short, I'm opening a session, put 100,000 objects in my database, fetch them once (to fill the cache) and fetch them 10 more times to measure performance. I regularly clear my Session cache so it doesn't influence the tests.
I'm not saying EHCache should be as fast as my ConcurrentHashMap, but 5 times faster is a bit disappointing.
Please help.
Thanks.
Login
FAQ
Search
