Archief - [PROG][JAVA] Hibernate second level caching: traag!

Het archief is een bevroren moment uit een vorige versie van dit forum, met andere regels en andere bazen. Deze posts weerspiegelen op geen enkele manier onze huidige ideeën, waarden of wereldbeelden en zijn op sommige plaatsen gecensureerd wegens ontoelaatbaar. Veel zijn in een andere tijdsgeest gemaakt, al dan niet ironisch - zoals in het ironische subforum Off-Topic - en zouden op dit moment niet meer gepost (mogen) worden. Toch bieden we dit archief nog graag aan als informatiedatabank en naslagwerk. Lees er hier meer over of start een gesprek met anderen.
f

forloRn_

Legacy Member
Dag mensen,

Het onderstaande heb ik op het forum van Hibernate gepost. Het is nogal dringend, daarom plak ik het ook hier. Het komt er grofweg op neer dat ik EHCache als second level cache probeer te gebruiken in Hibernate, maar dat de resultaten redelijk tegenvallen, en ik niet weet hoe dat komt. :sad:
Kunnen jullie me soms helpen?



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.
B

Bavo aka Joske

Legacy Member
Dit is wel boeiend :) Wel vreemd dat je second_level_cache afzet terwijl je een provider ervoor opgeeft. Maar dat zal gewoon de default uitschekelen zijn dan?

Kan je de url doorgeven van dat fourm, zou het graag volgen. Let wel: Hibernate mensen zijn niet bekend om hun vriendelijkheid ;-)
B

Bavo aka Joske

Legacy Member
Ik vond die 4000 keer sneller wel storend, tot ik besefte dat je gewoon in je DAO zelf cached. Maw, je parsed geen queries, je hebt geen isolation levels, geen transacties, geen cpu cycles voor cache flushing etc.

Dat maakt wel een pak verschil natuurlijk, zeker als je ziet dat EHCACHE een ditributed cache is, die op de hoogte moet zijn van dirty states etc.

Nu, het kan misshcien wle beter, eens zien wat de Hibernate mensen zeggen.
f

forloRn_

Legacy Member
Maakt niet uit, in mijn test maak ik ook geen gebruik van transacties en flushing doet EHCache ook niet omdat de cache juist groot genoeg is. Bovendien is EHCache niet geconfigureerd als distributed cache.

Los daarvan: een cache die maar vijfmaal sneller is dan een query op de DB? Dat vind ik eerlijk gezegd redelijk zwakjes. Maar goed, ik zal ergens wel iets verkeerd geconfigureerd hebben, ik weet gewoon niet wat.
Het archief is een bevroren moment uit een vorige versie van dit forum, met andere regels en andere bazen. Deze posts weerspiegelen op geen enkele manier onze huidige ideeën, waarden of wereldbeelden en zijn op sommige plaatsen gecensureerd wegens ontoelaatbaar. Veel zijn in een andere tijdsgeest gemaakt, al dan niet ironisch - zoals in het ironische subforum Off-Topic - en zouden op dit moment niet meer gepost (mogen) worden. Toch bieden we dit archief nog graag aan als informatiedatabank en naslagwerk. Lees er hier meer over of start een gesprek met anderen.
Terug
Bovenaan