Announcement Announcement Module
Collapse
No announcement yet.
Hibernate second level caching: slow - no, really slow Page Title Module
Move Remove Collapse
X
Conversation Detail Module
Collapse
  • Filter
  • Time
  • Show
Clear All
new posts

  • Hibernate second level caching: slow - no, really slow

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

  • #2
    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.

    Comment


    • #3
      you are putting 100'000 objects in and caching only 10'000.
      At least this is what I see from your ehcache config.

      What I don't get: why are no sql statements logged for the remaining objects?
      Last edited by zeko; Apr 16th, 2008, 03:59 PM.

      Comment


      • #4
        Originally posted by zeko View Post
        you are putting 100'000 objects in and caching only 10'000.
        At least this is what I see from your ehcache config.

        What I don't get: why are no sql statements logged for the remaining objects?
        Yeah, sorry, that's a typo. It's 10,000 objects, fetched 10 times (+ one time to fill the cache).

        Comment


        • #5
          any follow up on this ?

          I'm currently just started configuring EHCache + hibernate too and I'm interested in the follow up of the performance improvement you've described in this thread. Any success of better result ? Thank you.

          Comment

          Working...
          X