-->
These old forums are deprecated now and set to read-only. We are waiting for you on our new forums!
More modern, Discourse-based and with GitHub/Google/Twitter authentication built-in.

All times are UTC - 5 hours [ DST ]



Forum locked This topic is locked, you cannot edit posts or make further replies.  [ 4 posts ] 
Author Message
 Post subject: Second level cache is slow- no, really slow
PostPosted: Wed Apr 16, 2008 10:54 am 
Newbie

Joined: Wed Apr 16, 2008 10:13 am
Posts: 4
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.


Top
 Profile  
 
 Post subject: Re: Second level cache is slow- no, really slow
PostPosted: Wed Apr 16, 2008 12:10 pm 
Expert
Expert

Joined: Wed Apr 11, 2007 11:39 am
Posts: 735
Location: Montreal, QC
Hmm, in your ehcache configuration only 10,000 objects are held in memory which means the rest are being flush to hard disk. What if you increase that? I am assuming your loading around 100,000 objects.



Farzad-


Top
 Profile  
 
 Post subject: Re: Second level cache is slow- no, really slow
PostPosted: Wed Apr 16, 2008 12:29 pm 
Newbie

Joined: Wed Apr 16, 2008 10:13 am
Posts: 4
farzad wrote:
Hmm, in your ehcache configuration only 10,000 objects are held in memory which means the rest are being flush to hard disk. What if you increase that? I am assuming your loading around 100,000 objects.



Farzad-


Whoops, that's a typo. It's 10,000 objects being fetched 10 times each. Disk caching is disabled, by the way.

Oh, and before someone complains: hibernate.cache.use_second_level_cache was set to true when I ran the test against EHCache.


Top
 Profile  
 
 Post subject: Re: Second level cache is slow- no, really slow
PostPosted: Tue Jun 03, 2008 2:50 pm 
Newbie

Joined: Tue Jun 03, 2008 2:35 pm
Posts: 1
I don't know if you already solved your problem, but I noticed that your cache hit is 10,000 where I would expect 10 x 10,000 hits.

If your cache size is only 1 short of what is necessary (e.g. when you have 10,001 items), you will only get a cache hit for the first 10,000 items in your specific test scenario, the remainder is not found in cache.

Can you increase the cache size, just to rule this option out and see what it does with the cache hits?


Top
 Profile  
 
Display posts from previous:  Sort by  
Forum locked This topic is locked, you cannot edit posts or make further replies.  [ 4 posts ] 

All times are UTC - 5 hours [ DST ]


You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum

Search for:
cron
© Copyright 2014, Red Hat Inc. All rights reserved. JBoss and Hibernate are registered trademarks and servicemarks of Red Hat, Inc.