From 63cfd55344ba7e656130b767125903e5c621a759 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Galder=20Zamarren=CC=83o?= Date: Thu, 31 Jan 2019 18:11:14 +0100 Subject: [PATCH 1/2] Fix Hibernate cache random failures #694 * Caffeine offers no strict guarantees on which entity is evicted. Once the max is reached, there's no strict guarantees on which entity will be evicted, so we can't really to try to deterministically choose an entity to query after it's been evicted. * Caffeine is not strict in its max size, it can run over for a little. * Fix incorrect conversion from seconds to nanoseconds. --- .../hibernate/cache/PutFromLoadValidator.java | 2 +- ...spanCacheJPAFunctionalityTestEndpoint.java | 73 +++++++++++++------ 2 files changed, 50 insertions(+), 25 deletions(-) diff --git a/independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/PutFromLoadValidator.java b/independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/PutFromLoadValidator.java index f98a93c483cb9..0c136e958bef9 100644 --- a/independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/PutFromLoadValidator.java +++ b/independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/PutFromLoadValidator.java @@ -80,7 +80,7 @@ public final class PutFromLoadValidator { /** * Period (in nanoseconds) after which ongoing invalidation is removed. */ - public static final long EXPIRATION_PERIOD = 60_000_000; + public static final long EXPIRATION_PERIOD = Duration.ofSeconds(60).toNanos(); /** * Registry of expected, future, isPutValid calls. If a key+owner is registered in this map, it diff --git a/integration-tests/infinispan-cache-jpa/src/main/java/org/jboss/shamrock/example/infinispancachejpa/InfinispanCacheJPAFunctionalityTestEndpoint.java b/integration-tests/infinispan-cache-jpa/src/main/java/org/jboss/shamrock/example/infinispancachejpa/InfinispanCacheJPAFunctionalityTestEndpoint.java index 2415d04c2fa3c..364a0cf865ca1 100644 --- a/integration-tests/infinispan-cache-jpa/src/main/java/org/jboss/shamrock/example/infinispancachejpa/InfinispanCacheJPAFunctionalityTestEndpoint.java +++ b/integration-tests/infinispan-cache-jpa/src/main/java/org/jboss/shamrock/example/infinispancachejpa/InfinispanCacheJPAFunctionalityTestEndpoint.java @@ -12,8 +12,11 @@ import java.io.IOException; import java.io.PrintWriter; +import java.time.Duration; import java.util.*; import java.util.concurrent.TimeUnit; +import java.util.function.BiFunction; +import java.util.function.Supplier; import javax.persistence.EntityManager; import javax.persistence.EntityManagerFactory; @@ -392,24 +395,6 @@ private static void findByIdItems(EntityManager em, String[] expectedDesc) { private static void testMaxSize(EntityManagerFactory emf) { addItemBeyondMaxSize(emf); - queryItemEvicted(emf); - } - - private static void queryItemEvicted(EntityManagerFactory emf) { - Statistics stats = getStatistics(emf); - - EntityManager em = emf.createEntityManager(); - EntityTransaction transaction = em.getTransaction(); - transaction.begin(); - final Item i1 = em.find(Item.class, 1L); - final String expectedDesc = "Infinispan T-shirt"; - if (!i1.getDescription().equals(expectedDesc)) - throw new RuntimeException("Incorrect description: " + i1.getDescription() + ", expected: " + expectedDesc); - - transaction.commit(); - em.close(); - - assertRegionStats(new Counts(1, 0, 1, 3), Item.class.getName(), stats); } private static void addItemBeyondMaxSize(EntityManagerFactory emf) { @@ -423,7 +408,7 @@ private static void addItemBeyondMaxSize(EntityManagerFactory emf) { transaction.commit(); em.close(); - assertRegionStats(new Counts(1, 0, 0, 3), Item.class.getName(), stats); + assertRegionStatsEventually(new Counts(1, 0, 0, 3), Item.class.getName(), stats); } private static void testQuery(EntityManagerFactory entityManagerFactory) { @@ -746,13 +731,53 @@ private static void assertRegionStats(Counts expected, String region, Statistics } private static void assertCountEquals(Counts expected, Counts actual, String msg) { - //FIXME this is currently failing often on CI, needs to be investigated. - //Seems to fail more often in native mode. - // - https://github.com/jbossas/protean-shamrock/issues/694 - /*if (!expected.equals(actual)) + if (!expected.equals(actual)) throw new RuntimeException( "[" + msg + "] expected " + expected + " second level cache count, instead got: " + actual - );*/ + ); + } + + private static void assertRegionStatsEventually(Counts expected, String region, Statistics stats) { + eventually(() -> { + final CacheRegionStatistics cacheStats = stats.getDomainDataRegionStatistics(region); + final Counts actual = new Counts( + cacheStats.getPutCount() + , cacheStats.getHitCount() + , cacheStats.getMissCount() + , cacheStats.getElementCountInMemory() + ); + if (!expected.equals(actual)) { + return new RuntimeException( + "[" + region + "] expected " + expected + " second level cache count, instead got: " + actual + ); + } + + return null; + }); + } + + static void eventually(Supplier condition) { + eventually(Duration.ofSeconds(10).toMillis(), Duration.ofMillis(500).toMillis(), TimeUnit.MILLISECONDS, condition); + } + + static void eventually(long timeout, long pollInterval, TimeUnit unit, Supplier condition) { + if (pollInterval <= 0) { + throw new IllegalArgumentException("Check interval must be positive"); + } + try { + long expectedEndTime = System.nanoTime() + TimeUnit.NANOSECONDS.convert(timeout, unit); + long sleepMillis = TimeUnit.MILLISECONDS.convert(pollInterval, unit); + while (expectedEndTime - System.nanoTime() > 0) { + if (condition.get() == null) return; + Thread.sleep(sleepMillis); + } + + final RuntimeException exception = condition.get(); + if (exception != null) + throw exception; + } catch (Exception e) { + throw new RuntimeException("Unexpected!", e); + } } static final class Counts { From 5d27a98b0594abd39925a98ba6f77b1008ebdcff Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Galder=20Zamarren=CC=83o?= Date: Fri, 1 Feb 2019 12:50:14 +0100 Subject: [PATCH 2/2] Align Hibernate cache timeout units * PutFromLoadValidator compares expiration timeouts with region timestamps, which are provided in milliseconds. * Caffeine works with nanoseconds, so max idle timeouts should be converted into nanoseconds. * Empty VersionedEntry instances are tombstones, whose tomsbtone lifespan should be defined in nanoseconds so that Caffeine can evict it appropiately. --- .../hibernate/cache/CaffeineCache.java | 28 +++++++++++-------- .../hibernate/cache/DomainDataRegionImpl.java | 2 +- .../cache/InfinispanRegionFactory.java | 4 +-- .../hibernate/cache/InternalCacheConfig.java | 6 ++-- .../hibernate/cache/PutFromLoadValidator.java | 8 ++++-- .../hibernate/cache/VersionedEntry.java | 17 ++++++----- 6 files changed, 38 insertions(+), 27 deletions(-) diff --git a/independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/CaffeineCache.java b/independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/CaffeineCache.java index 62980c8c1d7df..bfc1e1926c3f2 100644 --- a/independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/CaffeineCache.java +++ b/independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/CaffeineCache.java @@ -5,6 +5,7 @@ import com.github.benmanes.caffeine.cache.Expiry; import org.jboss.logging.Logger; +import java.time.Duration; import java.util.Map; import java.util.function.BiFunction; import java.util.function.Consumer; @@ -19,7 +20,7 @@ final class CaffeineCache implements InternalCache { private final String cacheName; public CaffeineCache(String cacheName, InternalCacheConfig config, TimeService timeService) { - long maxIdle = config != null ? config.maxIdle : -1; + Duration maxIdle = config != null ? config.maxIdle : null; long maxSize = config != null ? config.maxSize : -1; this.cacheName = cacheName; @@ -129,10 +130,13 @@ public void invalidateAll() { // e.g. regions would then need to aggregate counts for all data accesses for that region. private static final class CacheExpiryPolicy implements Expiry { - private final long maxIdle; + private final long maxIdleNanos; - public CacheExpiryPolicy(long maxIdle) { - this.maxIdle = maxIdle; + public CacheExpiryPolicy(Duration maxIdle) { + if (maxIdle == null) + this.maxIdleNanos = -1; + else + this.maxIdleNanos = maxIdle.toNanos(); } @Override @@ -144,18 +148,18 @@ private long calculateExpiration(Object value, long currentTime) { if (value instanceof VersionedEntry) { // Deal with versioned entry expirations final VersionedEntry versioned = (VersionedEntry) value; - if (maxIdle > 0) { - final long idleDeadline = currentTime + maxIdle; - final long versionedLifespan = versioned.getLifespan(); + if (maxIdleNanos > 0) { + final long idleDeadline = currentTime + maxIdleNanos; + final long versionedLifespan = versioned.getLifespanNanos(); log.tracef("Expire after create, either idle deadline %d (ns) or versioned entry lifespan %d (ns)", idleDeadline, versionedLifespan); return Math.min(idleDeadline, versionedLifespan); } - return versioned.getLifespan(); + return versioned.getLifespanNanos(); } - if (maxIdle > 0) - return maxIdle; + if (maxIdleNanos > 0) + return maxIdleNanos; return Long.MAX_VALUE; } @@ -167,8 +171,8 @@ public long expireAfterUpdate(Object key, Object value, long currentTime, long c @Override public long expireAfterRead(Object key, Object value, long currentTime, long currentDuration) { - if (maxIdle > 0) { - return maxIdle; + if (maxIdleNanos > 0) { + return maxIdleNanos; } return Long.MAX_VALUE; diff --git a/independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/DomainDataRegionImpl.java b/independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/DomainDataRegionImpl.java index e1649b11ff98d..65e01b38cb9e8 100644 --- a/independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/DomainDataRegionImpl.java +++ b/independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/DomainDataRegionImpl.java @@ -190,7 +190,7 @@ private void runInvalidation() { break; case VERSIONED_ENTRIES: // no need to use this as a function - simply override all - VersionedEntry evict = new VersionedEntry(regionFactory.nextTimestamp(), PutFromLoadValidator.EXPIRATION_PERIOD); + VersionedEntry evict = new VersionedEntry(regionFactory.nextTimestamp(), VersionedEntry.TOMBSTONE_LIFESPAN); removeEntries(entry -> cache.put(entry.getKey(), evict)); break; } diff --git a/independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/InfinispanRegionFactory.java b/independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/InfinispanRegionFactory.java index d80d5d99cee97..5a5bd30abd0a7 100644 --- a/independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/InfinispanRegionFactory.java +++ b/independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/InfinispanRegionFactory.java @@ -14,6 +14,7 @@ import org.hibernate.internal.util.config.ConfigurationHelper; import org.jboss.logging.Logger; +import java.time.Duration; import java.util.*; import java.util.concurrent.TimeUnit; @@ -70,8 +71,7 @@ public void start(SessionFactoryOptions settings, Map configValues) { if (key.contains(SIZE_SUFFIX)) { cacheConfig.setMaxSize(Long.parseLong(value)); } else if (key.contains(MAX_IDLE_SUFFIX)) { - final long nanosIdle = TimeUnit.SECONDS.toNanos(Long.parseLong(value)); - cacheConfig.setMaxIdle(nanosIdle); + cacheConfig.setMaxIdle(Duration.ofSeconds(Long.parseLong(value))); } return cacheConfig; diff --git a/independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/InternalCacheConfig.java b/independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/InternalCacheConfig.java index 16607f7b838f7..62b11ee140d12 100644 --- a/independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/InternalCacheConfig.java +++ b/independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/InternalCacheConfig.java @@ -1,15 +1,17 @@ package org.infinispan.protean.hibernate.cache; +import java.time.Duration; + final class InternalCacheConfig { long maxSize = -1; - long maxIdle = -1; + Duration maxIdle; // in seconds void setMaxSize(long maxSize) { this.maxSize = maxSize; } - void setMaxIdle(long maxIdle) { + void setMaxIdle(Duration maxIdle) { this.maxIdle = maxIdle; } diff --git a/independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/PutFromLoadValidator.java b/independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/PutFromLoadValidator.java index 0c136e958bef9..62908d972f514 100644 --- a/independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/PutFromLoadValidator.java +++ b/independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/PutFromLoadValidator.java @@ -78,9 +78,11 @@ public final class PutFromLoadValidator { private static final boolean trace = log.isTraceEnabled(); /** - * Period (in nanoseconds) after which ongoing invalidation is removed. + * Period (in milliseconds) after which ongoing invalidation is removed. + * Needs to be milliseconds because it will be compared with {@link RegionFactory#nextTimestamp()}, + * and that method is expected to return milliseconds. */ - public static final long EXPIRATION_PERIOD = Duration.ofSeconds(60).toNanos(); + private static final long EXPIRATION_PERIOD = Duration.ofSeconds(60).toMillis(); /** * Registry of expected, future, isPutValid calls. If a key+owner is registered in this map, it @@ -120,7 +122,7 @@ public PutFromLoadValidator(InternalCache cache, String regionName, RegionFactor this.nextTimestamp = regionFactory::nextTimestamp; this.pendingPuts = Caffeine.newBuilder() - .expireAfterAccess(Duration.ofNanos(EXPIRATION_PERIOD)) + .expireAfterAccess(Duration.ofMillis(EXPIRATION_PERIOD)) .build(); } diff --git a/independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/VersionedEntry.java b/independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/VersionedEntry.java index 027f5786d260d..9e592e654d122 100644 --- a/independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/VersionedEntry.java +++ b/independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/VersionedEntry.java @@ -4,6 +4,7 @@ import org.hibernate.cache.spi.entry.StructuredCacheEntry; import org.jboss.logging.Logger; +import java.time.Duration; import java.util.Comparator; import java.util.Map; import java.util.function.BiFunction; @@ -14,12 +15,14 @@ final class VersionedEntry { private static final Logger log = Logger.getLogger(VersionedEntry.class); private static final boolean trace = log.isTraceEnabled(); + public static final Duration TOMBSTONE_LIFESPAN = Duration.ofSeconds(60); + static final ExcludeEmptyFilter EXCLUDE_EMPTY_VERSIONED_ENTRY = new ExcludeEmptyFilter(); private final Object value; private final Object version; private final long timestamp; - private long lifespan = Long.MAX_VALUE; // nanoseconds + private Duration lifespan = Duration.ofSeconds(Long.MAX_VALUE); VersionedEntry(Object value, Object version, long timestamp) { this.value = value; @@ -31,7 +34,7 @@ final class VersionedEntry { this(null, null, timestamp); } - VersionedEntry(long timestamp, long lifespan) { + VersionedEntry(long timestamp, Duration lifespan) { this(null, null, timestamp); this.lifespan = lifespan; } @@ -44,8 +47,8 @@ long getTimestamp() { return timestamp; } - long getLifespan() { - return lifespan; + long getLifespanNanos() { + return lifespan.toNanos(); } Object getValue() { @@ -69,7 +72,7 @@ public Object apply(Object key, Object oldValue) { } if (entry.version == null) { // eviction or post-commit removal: we'll store it with given timestamp - entry.lifespan = PutFromLoadValidator.EXPIRATION_PERIOD; + entry.lifespan = TOMBSTONE_LIFESPAN; return entry; } @@ -105,7 +108,7 @@ public Object apply(Object key, Object oldValue) { } } if (versionComparator == null) { - entry.lifespan = PutFromLoadValidator.EXPIRATION_PERIOD; + entry.lifespan = TOMBSTONE_LIFESPAN; return new VersionedEntry(null, null, entry.timestamp); } else { int compareResult = versionComparator.compare(entry.version, oldVersion); @@ -113,7 +116,7 @@ public Object apply(Object key, Object oldValue) { log.tracef("Comparing %s and %s -> %d (using %s)", entry.version, oldVersion, compareResult, versionComparator); } if (entry.value == null && compareResult >= 0) { - entry.lifespan = PutFromLoadValidator.EXPIRATION_PERIOD; + entry.lifespan = TOMBSTONE_LIFESPAN; return entry; } else if (compareResult > 0) { return entry.value instanceof CacheEntry ? entry.value : entry;