Merge pull request #2679 from ebean-orm/feature/2677

#2677 - Fix for trim failing on mutation of lastAccessTime

ebean-core/src/main/java/io/ebeaninternal/server/cache/DefaultServerCache.java

@@ -13,6 +13,8 @@ import java.io.Serializable;
 import java.lang.ref.SoftReference;
 import java.util.*;
 import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicLong;
+import java.util.concurrent.locks.ReentrantLock;
 
 /**
  * The default cache implementation.
@@ -43,10 +45,13 @@ public class DefaultServerCache implements ServerCache {
 
   protected final String name;
   protected final String shortName;
-  private final int maxSize;
-  private final int trimFrequency;
-  private final int maxIdleSecs;
-  private final int maxSecsToLive;
+  protected final int maxSize;
+  protected final int trimFrequency;
+  protected final int maxIdleSecs;
+  protected final int maxSecsToLive;
+  protected final long trimOnPut;
+  protected final ReentrantLock lock = new ReentrantLock();
+  protected final AtomicLong mutationCounter = new AtomicLong();
 
   public DefaultServerCache(DefaultServerCacheConfig config) {
     this.name = config.getName();
@@ -56,6 +61,7 @@ public class DefaultServerCache implements ServerCache {
     this.maxIdleSecs = config.getMaxIdleSecs();
     this.maxSecsToLive = config.getMaxSecsToLive();
     this.trimFrequency = config.determineTrimFrequency();
+    this.trimOnPut = config.determineTrimOnPut();
 
     MetricFactory factory = MetricFactory.get();
     String prefix = "l2n.";
@@ -187,6 +193,9 @@ public class DefaultServerCache implements ServerCache {
   public void put(Object key, Object value) {
     map.put(key, new SoftReference<>(new CacheEntry(key, value)));
     putCount.increment();
+    if (mutationCounter.incrementAndGet() > trimOnPut) {
+      runEviction();
+    }
   }
 
   /**
@@ -222,62 +231,72 @@ public class DefaultServerCache implements ServerCache {
    * Run the eviction based on Idle time, Time to live and LRU last access.
    */
   public void runEviction() {
-    long trimForMaxSize;
-    if (maxSize == 0) {
-      trimForMaxSize = 0;
-    } else {
-      trimForMaxSize = size() - maxSize;
-    }
-    if (maxIdleSecs == 0 && maxSecsToLive == 0 && trimForMaxSize < 0) {
-      // nothing to trim on this cache
-      return;
-    }
-    long startNanos = System.nanoTime();
-    long trimmedByIdle = 0;
-    long trimmedByGC = 0;
-    long trimmedByTTL = 0;
-    long trimmedByLRU = 0;
-
-    List<CacheEntry> activeList = new ArrayList<>(map.size());
-    long idleExpireNano = startNanos - TimeUnit.SECONDS.toNanos(maxIdleSecs);
-    long ttlExpireNano = startNanos - TimeUnit.SECONDS.toNanos(maxSecsToLive);
-    Iterator<SoftReference<CacheEntry>> it = map.values().iterator();
-    while (it.hasNext()) {
-      SoftReference<CacheEntry> ref = it.next();
-      final CacheEntry cacheEntry = ref.get();
-      if (cacheEntry == null) {
-        it.remove();
-        trimmedByGC++;
-      } else if (maxIdleSecs > 0 && idleExpireNano > cacheEntry.getLastAccessTime()) {
-        it.remove();
-        trimmedByIdle++;
-      } else if (maxSecsToLive > 0 && ttlExpireNano > cacheEntry.getCreateTime()) {
-        it.remove();
-        trimmedByTTL++;
-      } else if (trimForMaxSize > 0) {
-        activeList.add(cacheEntry);
+    lock.lock();
+    try {
+      long trimForMaxSize;
+      if (maxSize == 0) {
+        trimForMaxSize = 0;
+      } else {
+        trimForMaxSize = size() - maxSize;
       }
-    }
-    if (trimForMaxSize > 0 && activeList.size() > maxSize) {
-      // sort into last access time ascending
-      activeList.sort(BY_LAST_ACCESS);
-      int trimSize = getTrimSize();
-      for (int i = trimSize; i < activeList.size(); i++) {
-        // remove if still in the cache
-        if (map.remove(activeList.get(i).getKey()) != null) {
-          trimmedByLRU++;
+      if (maxIdleSecs == 0 && maxSecsToLive == 0 && trimForMaxSize < 0) {
+        // nothing to trim on this cache
+        mutationCounter.set(0);
+        return;
+      }
+      long startNanos = System.nanoTime();
+      long trimmedByIdle = 0;
+      long trimmedByGC = 0;
+      long trimmedByTTL = 0;
+      long trimmedByLRU = 0;
+
+      try {
+        List<CacheEntry> activeList = new ArrayList<>(map.size());
+        long idleExpireNano = startNanos - TimeUnit.SECONDS.toNanos(maxIdleSecs);
+        long ttlExpireNano = startNanos - TimeUnit.SECONDS.toNanos(maxSecsToLive);
+        Iterator<SoftReference<CacheEntry>> it = map.values().iterator();
+        while (it.hasNext()) {
+          SoftReference<CacheEntry> ref = it.next();
+          final CacheEntry cacheEntry = ref.get();
+          if (cacheEntry == null) {
+            it.remove();
+            trimmedByGC++;
+          } else if (maxIdleSecs > 0 && idleExpireNano > cacheEntry.getLastAccessTime()) {
+            it.remove();
+            trimmedByIdle++;
+          } else if (maxSecsToLive > 0 && ttlExpireNano > cacheEntry.getCreateTime()) {
+            it.remove();
+            trimmedByTTL++;
+          } else if (trimForMaxSize > 0) {
+            activeList.add(cacheEntry.forSort());
+          }
         }
+        if (trimForMaxSize > 0 && activeList.size() > maxSize) {
+          // sort into last access time ascending
+          activeList.sort(BY_LAST_ACCESS);
+          int trimSize = getTrimSize();
+          for (int i = trimSize; i < activeList.size(); i++) {
+            // remove if still in the cache
+            if (map.remove(activeList.get(i).getKey()) != null) {
+              trimmedByLRU++;
+            }
+          }
+        }
+        mutationCounter.set(0);
+        evictCount.add(trimmedByIdle);
+        evictCount.add(trimmedByGC);
+        evictCount.add(trimmedByTTL);
+        evictCount.add(trimmedByLRU);
+        if (logger.isTraceEnabled()) {
+          long exeMicros = TimeUnit.MICROSECONDS.convert(System.nanoTime() - startNanos, TimeUnit.NANOSECONDS);
+          logger.trace("Executed trim of cache {} in [{}]millis idle[{}] timeToLive[{}] accessTime[{}] gc[{}]",
+            name, exeMicros, trimmedByIdle, trimmedByTTL, trimmedByLRU, trimmedByGC);
+        }
+      } catch (Throwable e) {
+        logger.warn("Error during trim of DefaultServerCache [" + name + "]. Cache might be bigger than desired.", e);
       }
-    }
-
-    evictCount.add(trimmedByIdle);
-    evictCount.add(trimmedByGC);
-    evictCount.add(trimmedByTTL);
-    evictCount.add(trimmedByLRU);
-    if (logger.isTraceEnabled()) {
-      long exeMicros = TimeUnit.MICROSECONDS.convert(System.nanoTime() - startNanos, TimeUnit.NANOSECONDS);
-      logger.trace("Executed trim of cache {} in [{}]millis idle[{}] timeToLive[{}] accessTime[{}] gc[{}]",
-        name, exeMicros, trimmedByIdle, trimmedByTTL, trimmedByLRU, trimmedByGC);
+    } finally {
+      lock.unlock();
     }
   }
 
@@ -293,7 +312,7 @@ public class DefaultServerCache implements ServerCache {
   }
 
   /**
-   * Comparator for sorting by last access time.
+   * Comparator for sorting by last access sort, a copy of last access time that should not mutate during trim processing.
    */
   public static final class CompareByLastAccess implements Comparator<CacheEntry>, Serializable {
 
@@ -301,7 +320,7 @@ public class DefaultServerCache implements ServerCache {
 
     @Override
     public int compare(CacheEntry e1, CacheEntry e2) {
-      return Long.compare(e1.getLastAccessTime(), e2.getLastAccessTime());
+      return Long.compare(e1.lastAccessSort, e2.lastAccessSort);
     }
   }
 
@@ -314,6 +333,7 @@ public class DefaultServerCache implements ServerCache {
     private final Object value;
     private final long createTime;
     private long lastAccessTime;
+    private long lastAccessSort;
 
     public CacheEntry(Object key, Object value) {
       this.key = key;
@@ -322,6 +342,14 @@ public class DefaultServerCache implements ServerCache {
       this.lastAccessTime = createTime;
     }
 
+    /**
+     * Store a copy of lastAccessTime used for sorting. This value should not change during trim processing.
+     */
+    public CacheEntry forSort() {
+      this.lastAccessSort = lastAccessTime;
+      return this;
+    }
+
     /**
      * Return the entry key.
      */

ebean-core/src/main/java/io/ebeaninternal/server/cache/DefaultServerCacheConfig.java

@@ -76,4 +76,14 @@ public final class DefaultServerCacheConfig {
     }
     return 0;
   }
+
+  /**
+   * Determine the number of mutations/puts required to trigger a runEviction() in the foreground.
+   */
+  public long determineTrimOnPut() {
+    if (maxSize > 0) {
+      return maxSize / 10;
+    }
+    return 1000;
+  }
 }

ebean-core/src/test/java/io/ebeaninternal/server/cache/DefaultServerCacheConfigTest.java

@@ -6,8 +6,7 @@ import org.junit.jupiter.api.Test;
 
 import static org.junit.jupiter.api.Assertions.assertEquals;
 
-public class DefaultServerCacheConfigTest {
-
+class DefaultServerCacheConfigTest {
 
   private DefaultServerCacheConfig create(int maxSize, int maxIdleSecs, int maxSecsToLive, int trimFreq) {
     ServerCacheOptions options = new ServerCacheOptions();
@@ -20,33 +19,45 @@ public class DefaultServerCacheConfigTest {
   }
 
   @Test
-  public void trimFreq_halfIdle() {
-
+  void trimFreq_halfIdle() {
     assertEquals(create(10000,10,20, 0).determineTrimFrequency(), 4);
   }
 
-
   @Test
-  public void trimFreq_halfIdle_withRounding() {
-
+  void trimFreq_halfIdle_withRounding() {
     assertEquals(create(10000,11,20, 0).determineTrimFrequency(), 4);
   }
 
   @Test
-  public void trimFreq_halfTTL() {
-
+  void trimFreq_halfTTL() {
     assertEquals(create(10000,0,20, 0).determineTrimFrequency(), 9);
   }
 
   @Test
-  public void trimFreq_halfTTL_withRounding() {
-
+  void trimFreq_halfTTL_withRounding() {
     assertEquals(create(10000,0,21, 0).determineTrimFrequency(), 9);
   }
 
   @Test
-  public void trimFreq_explicit() {
-
+  void trimFreq_explicit() {
     assertEquals(create(10000,10,20, 42).determineTrimFrequency(), 42);
   }
+
+  @Test
+  void trimOnPut_default() {
+    assertEquals(create(0,0,0, 0).determineTrimOnPut(), 1_000);
+  }
+
+  @Test
+  void trimOnPut_tenPercent() {
+    assertEquals(create(10_000,0,0, 0).determineTrimOnPut(), 1_000);
+    assertEquals(create(9_000,0,0, 0).determineTrimOnPut(), 900);
+    assertEquals(create(100,0,0, 0).determineTrimOnPut(), 10);
+  }
+
+  @Test
+  void trimOnPut_roundDown() {
+    assertEquals(create(9010,0,0, 0).determineTrimOnPut(), 901);
+    assertEquals(create(9009,0,0, 0).determineTrimOnPut(), 900);
+  }
 }

ebean-core/src/test/java/io/ebeaninternal/server/cache/DefaultServerCache_RunEvictionTest.java

@@ -10,16 +10,14 @@ import org.junit.jupiter.api.Test;
 import java.util.Random;
 
 
-public class DefaultServerCache_RunEvictionTest {
-
+class DefaultServerCache_RunEvictionTest {
 
   private DefaultServerCache createCache() {
-
     ServerCacheOptions cacheOptions = new ServerCacheOptions();
-    cacheOptions.setMaxSize(10000);
+    cacheOptions.setMaxSize(300);
     cacheOptions.setMaxIdleSecs(1);
     cacheOptions.setMaxSecsToLive(2);
-    cacheOptions.setTrimFrequency(1);
+    cacheOptions.setTrimFrequency(5);
 
     ServerCacheConfig con = new ServerCacheConfig(ServerCacheType.BEAN, "foo", "foo", cacheOptions, null, null);
     return new DefaultServerCache(new DefaultServerCacheConfig(con));
@@ -35,8 +33,7 @@ public class DefaultServerCache_RunEvictionTest {
 
   @Disabled("test takes long time")
   @Test
-  public void runEvict() throws InterruptedException {
-
+  void runEvict() throws InterruptedException {
     for (int i = 0; i < 15; i++) {
       doStuff();
       cache.runEviction();
@@ -47,12 +44,10 @@ public class DefaultServerCache_RunEvictionTest {
   }
 
   private void doStuff() {
-
-    for (int i = 0; i < 500; i++) {
+    for (int i = 0; i < 5000; i++) {
       String key = "" + random.nextInt(20000);
-
       int mode = random.nextInt(10);
-      if (mode < 8) {
+      if (mode < 7) {
         cache.get(key);
       } else {
         cache.put(key, key + "-" + System.currentTimeMillis());