From d036edf7fd80118813f1b0b4dbce4423911a9299 Mon Sep 17 00:00:00 2001 From: Rob Bygrave Date: Mon, 2 May 2022 20:31:10 +1200 Subject: [PATCH 1/4] #2677 - Fix for trim failing on mutation of lastAccessTime Currently, lastAccessTime can mutate during cache trim processing. This fixes this issue by taking a copy of the lastAccessTime storing as lastAccessSort and using that for sorting for cache trim. --- .../server/cache/DefaultServerCache.java | 15 ++++++++++++--- .../cache/DefaultServerCache_RunEvictionTest.java | 11 +++-------- 2 files changed, 15 insertions(+), 11 deletions(-) diff --git a/ebean-core/src/main/java/io/ebeaninternal/server/cache/DefaultServerCache.java b/ebean-core/src/main/java/io/ebeaninternal/server/cache/DefaultServerCache.java index ae3a297b3..fb3e2fc22 100644 --- a/ebean-core/src/main/java/io/ebeaninternal/server/cache/DefaultServerCache.java +++ b/ebean-core/src/main/java/io/ebeaninternal/server/cache/DefaultServerCache.java @@ -255,7 +255,7 @@ public class DefaultServerCache implements ServerCache { it.remove(); trimmedByTTL++; } else if (trimForMaxSize > 0) { - activeList.add(cacheEntry); + activeList.add(cacheEntry.forSort()); } } if (trimForMaxSize > 0 && activeList.size() > maxSize) { @@ -293,7 +293,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, Serializable { @@ -301,7 +301,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 +314,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 +323,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. */ diff --git a/ebean-core/src/test/java/io/ebeaninternal/server/cache/DefaultServerCache_RunEvictionTest.java b/ebean-core/src/test/java/io/ebeaninternal/server/cache/DefaultServerCache_RunEvictionTest.java index c6596e6d8..236984ef8 100644 --- a/ebean-core/src/test/java/io/ebeaninternal/server/cache/DefaultServerCache_RunEvictionTest.java +++ b/ebean-core/src/test/java/io/ebeaninternal/server/cache/DefaultServerCache_RunEvictionTest.java @@ -10,13 +10,11 @@ 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); @@ -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,10 +44,8 @@ public class DefaultServerCache_RunEvictionTest { } private void doStuff() { - for (int i = 0; i < 500; i++) { String key = "" + random.nextInt(20000); - int mode = random.nextInt(10); if (mode < 8) { cache.get(key); From 1cd319c4957d439acc59412ad5941228d8173a31 Mon Sep 17 00:00:00 2001 From: Rob Bygrave Date: Mon, 2 May 2022 20:51:33 +1200 Subject: [PATCH 2/4] #2677 - Add try catch around DefaultServerCache.runEviction() If there is an unexpected error we expect it to be temporary and want runEviction() to keep executing. --- .../server/cache/DefaultServerCache.java | 76 ++++++++++--------- 1 file changed, 40 insertions(+), 36 deletions(-) diff --git a/ebean-core/src/main/java/io/ebeaninternal/server/cache/DefaultServerCache.java b/ebean-core/src/main/java/io/ebeaninternal/server/cache/DefaultServerCache.java index fb3e2fc22..96eecfb6a 100644 --- a/ebean-core/src/main/java/io/ebeaninternal/server/cache/DefaultServerCache.java +++ b/ebean-core/src/main/java/io/ebeaninternal/server/cache/DefaultServerCache.java @@ -238,46 +238,50 @@ public class DefaultServerCache implements ServerCache { long trimmedByTTL = 0; long trimmedByLRU = 0; - List activeList = new ArrayList<>(map.size()); - long idleExpireNano = startNanos - TimeUnit.SECONDS.toNanos(maxIdleSecs); - long ttlExpireNano = startNanos - TimeUnit.SECONDS.toNanos(maxSecsToLive); - Iterator> it = map.values().iterator(); - while (it.hasNext()) { - SoftReference 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()); + try { + List activeList = new ArrayList<>(map.size()); + long idleExpireNano = startNanos - TimeUnit.SECONDS.toNanos(maxIdleSecs); + long ttlExpireNano = startNanos - TimeUnit.SECONDS.toNanos(maxSecsToLive); + Iterator> it = map.values().iterator(); + while (it.hasNext()) { + SoftReference 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++; + 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++; + } } } - } - 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); + 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); } } From 5c332286b6f5d9e7511d5abbb556fb3bae5309b4 Mon Sep 17 00:00:00 2001 From: Rob Bygrave Date: Mon, 2 May 2022 21:48:58 +1200 Subject: [PATCH 3/4] #2677 - Add ReentrantLock for DefaultServerCache.runEviction() and trigger runEviction() via mutationCounter If we get a lot of cache mutation (puts) between background trims then also trigger runEviction() in foreground using mutationCounter. --- .../server/cache/DefaultServerCache.java | 131 ++++++++++-------- .../DefaultServerCache_RunEvictionTest.java | 6 +- 2 files changed, 75 insertions(+), 62 deletions(-) diff --git a/ebean-core/src/main/java/io/ebeaninternal/server/cache/DefaultServerCache.java b/ebean-core/src/main/java/io/ebeaninternal/server/cache/DefaultServerCache.java index 96eecfb6a..c479cdbfa 100644 --- a/ebean-core/src/main/java/io/ebeaninternal/server/cache/DefaultServerCache.java +++ b/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,12 @@ 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 ReentrantLock lock = new ReentrantLock(); + protected final AtomicLong mutationCounter = new AtomicLong(); public DefaultServerCache(DefaultServerCacheConfig config) { this.name = config.getName(); @@ -187,6 +191,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() > 1000) { + runEviction(); + } } /** @@ -222,66 +229,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; - + lock.lock(); try { - List activeList = new ArrayList<>(map.size()); - long idleExpireNano = startNanos - TimeUnit.SECONDS.toNanos(maxIdleSecs); - long ttlExpireNano = startNanos - TimeUnit.SECONDS.toNanos(maxSecsToLive); - Iterator> it = map.values().iterator(); - while (it.hasNext()) { - SoftReference 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()); - } + 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 activeList = new ArrayList<>(map.size()); + long idleExpireNano = startNanos - TimeUnit.SECONDS.toNanos(maxIdleSecs); + long ttlExpireNano = startNanos - TimeUnit.SECONDS.toNanos(maxSecsToLive); + Iterator> it = map.values().iterator(); + while (it.hasNext()) { + SoftReference 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); - } - } catch (Throwable e) { - logger.warn("Error during trim of DefaultServerCache [" + name + "]. Cache might be bigger than desired.", e); + } finally { + lock.unlock(); } } diff --git a/ebean-core/src/test/java/io/ebeaninternal/server/cache/DefaultServerCache_RunEvictionTest.java b/ebean-core/src/test/java/io/ebeaninternal/server/cache/DefaultServerCache_RunEvictionTest.java index 236984ef8..d98c48707 100644 --- a/ebean-core/src/test/java/io/ebeaninternal/server/cache/DefaultServerCache_RunEvictionTest.java +++ b/ebean-core/src/test/java/io/ebeaninternal/server/cache/DefaultServerCache_RunEvictionTest.java @@ -17,7 +17,7 @@ class DefaultServerCache_RunEvictionTest { 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)); @@ -44,10 +44,10 @@ 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()); From 2cf83278ea082559160e6e5bcc55a913ea3f03e5 Mon Sep 17 00:00:00 2001 From: Rob Bygrave Date: Mon, 2 May 2022 22:19:37 +1200 Subject: [PATCH 4/4] #2677 - Change trimOnPut to be 10% of max or 1_000. Can look to provide an explicit option via `@CacheBeanTuning` later. --- .../server/cache/DefaultServerCache.java | 4 +- .../cache/DefaultServerCacheConfig.java | 10 +++++ .../cache/DefaultServerCacheConfigTest.java | 37 ++++++++++++------- 3 files changed, 37 insertions(+), 14 deletions(-) diff --git a/ebean-core/src/main/java/io/ebeaninternal/server/cache/DefaultServerCache.java b/ebean-core/src/main/java/io/ebeaninternal/server/cache/DefaultServerCache.java index c479cdbfa..f3b49fd2e 100644 --- a/ebean-core/src/main/java/io/ebeaninternal/server/cache/DefaultServerCache.java +++ b/ebean-core/src/main/java/io/ebeaninternal/server/cache/DefaultServerCache.java @@ -49,6 +49,7 @@ public class DefaultServerCache implements ServerCache { 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(); @@ -60,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."; @@ -191,7 +193,7 @@ 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() > 1000) { + if (mutationCounter.incrementAndGet() > trimOnPut) { runEviction(); } } diff --git a/ebean-core/src/main/java/io/ebeaninternal/server/cache/DefaultServerCacheConfig.java b/ebean-core/src/main/java/io/ebeaninternal/server/cache/DefaultServerCacheConfig.java index 2e5c5dbcd..3f3a5c0f0 100644 --- a/ebean-core/src/main/java/io/ebeaninternal/server/cache/DefaultServerCacheConfig.java +++ b/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; + } } diff --git a/ebean-core/src/test/java/io/ebeaninternal/server/cache/DefaultServerCacheConfigTest.java b/ebean-core/src/test/java/io/ebeaninternal/server/cache/DefaultServerCacheConfigTest.java index 512f663fd..19047e9c7 100644 --- a/ebean-core/src/test/java/io/ebeaninternal/server/cache/DefaultServerCacheConfigTest.java +++ b/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); + } }