• Bug
  • Status: Closed
  • Resolution: Fixed
  • drb
  • Reporter: sourceforgetracker
  • September 21, 2009
  • 0
  • Watchers: 0
  • September 22, 2009
  • September 22, 2009

Description

While evaluating ehcache, I tried a test using a single thread on a single node that would put, get, and remove an entry in a tight loop. Replicators were configured to update other nodes, though at the time no other nodes were running.

When the test was run, it had erratic behavior. It would seem to halt in some cases and delay the loop. I tried profiling in YourKit and noticed it was spending nearly 100% of the time in LinkedList.get(int). Here is the code it was running, from RMIAsynchronousCacheReplicator.flushReplicationQueue():

replicationQueueCopy = new ArrayList(replicationQueue.size()); for (int i = 0; i < replicationQueue.size(); i++) { CacheEventMessage cacheEventMessage = (CacheEventMessage) replicationQueue.get(i); replicationQueueCopy.add(cacheEventMessage); }

replicationQueue is a LinkedList. Since it’s using LinkedList.get(index) to copy the queue, it’s O(n^2). I tried changing this to just:

replicationQueueCopy = new ArrayList(replicationQueue);

The test turned out to be much faster, and it never halted. The test code is included below:

final CacheManager manager = …; final Cache cache = manager.getCache(“sampleCache”); long start = System.currentTimeMillis(); final String keyBase = Long.toString(start); int count = 0;

while(true) { final String key = keyBase + ‘:’ + Integer.toString((int)(Math.random() * 1000.0)); cache.put(new Element(key, “My Test”)); cache.get(key); cache.remove(key); count++;

final long end = System.currentTimeMillis(); if(end - start >= 1000) { start = end; logger.info(“Items written: “ + count); count = 0; } } Sourceforge Ticket ID: 1816084 - Opened By: sampsonk - 18 Oct 2007 19:12 UTC

Comments

Sourceforge Tracker 2009-09-21

Logged In: YES user_id=693320 Originator: NO

HI

I added your test to RMICacheReplicatorTest. I see what you mean. I got:

/** * Shows result of perf problem and fix in flushReplicationQueue * <p/> * Behaviour before change: * <p/> * INFO: Items written: 10381 * Oct 29, 2007 11:40:04 AM net.sf.ehcache.distribution.RMICacheReplicatorTest testReplicatePerf * INFO: Items written: 29712 * Oct 29, 2007 11:40:57 AM net.sf.ehcache.distribution.RMICacheReplicatorTest testReplicatePerf * INFO: Items written: 1 * Oct 29, 2007 11:40:58 AM net.sf.ehcache.distribution.RMICacheReplicatorTest testReplicatePerf * INFO: Items written: 32354 * Oct 29, 2007 11:42:34 AM net.sf.ehcache.distribution.RMICacheReplicatorTest testReplicatePerf * INFO: Items written: 322 * Oct 29, 2007 11:42:35 AM net.sf.ehcache.distribution.RMICacheReplicatorTest testReplicatePerf * INFO: Items written: 41909 * <p/> * Behaviour after change: * INFO: Items written: 26356 * Oct 29, 2007 11:44:39 AM net.sf.ehcache.distribution.RMICacheReplicatorTest testReplicatePerf * INFO: Items written: 33656 * Oct 29, 2007 11:44:40 AM net.sf.ehcache.distribution.RMICacheReplicatorTest testReplicatePerf * INFO: Items written: 32234 * Oct 29, 2007 11:44:42 AM net.sf.ehcache.distribution.RMICacheReplicatorTest testReplicatePerf * INFO: Items written: 38677 * Oct 29, 2007 11:44:43 AM net.sf.ehcache.distribution.RMICacheReplicatorTest testReplicatePerf * INFO: Items written: 43418 * Oct 29, 2007 11:44:44 AM net.sf.ehcache.distribution.RMICacheReplicatorTest testReplicatePerf * INFO: Items written: 31277 * Oct 29, 2007 11:44:45 AM net.sf.ehcache.distribution.RMICacheReplicatorTest testReplicatePerf * INFO: Items written: 27769 * Oct 29, 2007 11:44:46 AM net.sf.ehcache.distribution.RMICacheReplicatorTest testReplicatePerf * INFO: Items written: 29596 * Oct 29, 2007 11:44:47 AM net.sf.ehcache.distribution.RMICacheReplicatorTest testReplicatePerf * INFO: Items written: 17142 * Oct 29, 2007 11:44:48 AM net.sf.ehcache.distribution.RMICacheReplicatorTest testReplicatePerf * INFO: Items written: 14775 * Oct 29, 2007 11:44:49 AM net.sf.ehcache.distribution.RMICacheReplicatorTest testReplicatePerf * INFO: Items written: 4088 * Oct 29, 2007 11:44:51 AM net.sf.ehcache.distribution.RMICacheReplicatorTest testReplicatePerf * INFO: Items written: 5492 * Oct 29, 2007 11:44:52 AM net.sf.ehcache.distribution.RMICacheReplicatorTest testReplicatePerf * INFO: Items written: 10188 * * Also no pauses noted. */

Thanks for the fix. It is a huge perf improvement.

I hope you end up using ehcache and flick a few more improvements like that its way.

The fix is in trunk and will be in ehcache-1.2beta2.

Greg Comment by: gregluck - 29 Oct 2007 01:56 UTC

Fiona OShea 2009-09-22

Re-opening so that I can properly close out these issues and have correct Resolution status in Jira