Entries evicted too quickly when ttl is greater than zero

[jiri-pejchal]

I'm experiencing an issue when every 60 seconds cache entries are evicted sooner than they should be according their Time to live.

I think it's because every 60 seconds CleanupService runs cleanup in LocalRegionCache and the following removes elements from cache:

https://github.com/hazelcast/hazelcast-hibernate5/blob/92d13a07aa01a850c4d12b7852958735bbb3d4f9/hazelcast-hibernate5/src/main/java/com/hazelcast/hibernate/local/LocalRegionCache.java#L372-L373

Perhaps there are some problems with timestamp generation?

Failing test case

I am able to reproduce the issue on

• hazelcast 3.11.1
• hazelcast-hibernate 1.3.2-SNAPSHOT
• hibernate 5.3.7.Final

by adding the following test case to com.hazelcast.hibernate.RegionFactoryDefaultSlowTest.java in hazelcast-hibernate53 module:

props.setProperty(Environment.CACHE_REGION_FACTORY, HazelcastLocalCacheRegionFactory.class.getName());

@Test
public void testQueryCacheCleanup() {
  final int defaultCleanupPeriod = 60;
  QueryResultsRegionTemplate regionTemplate = (QueryResultsRegionTemplate) (((SessionFactoryImpl) sf)
      .getCache()).getDefaultQueryResultsCache().getRegion();
  RegionCache cache = ((HazelcastStorageAccessImpl) regionTemplate.getStorageAccess()).getDelegate();

  insertDummyEntities(1);
  executeQuery(sf, 0);

  assertEquals(1, cache.getElementCountInMemory());

  sleep(defaultCleanupPeriod + 1);

  assertEquals(1, cache.getElementCountInMemory());
}

Time to live for query cache needs to be greater than zero in hazelcast-custom.xml:

<!-- Config for query cache -->
<map name="default-query-results-region">
  <time-to-live-seconds>3600</time-to-live-seconds>
  <max-size>50</max-size>
</map>

[jiri-pejchal]

It is working in hazelcast-hibernate52 but not in hazelcast-hibernate53.

It basically means that every 60 seconds all entries are removed from the cache.

The difference is that for long now = nextTimestamp() in LocalRegionCache

• HazelcastTimestamper.nextTimestamp(hazelcastInstance) is used in hibernate52
• SimpleTimestamper.next() from hibernate is used in hibernate53

Perhaps @dohertyfjatl would know why nextTimestamp() is implemented differently when computing now?

[dohertyfjatl]

At the time it looked like we could re-use the existing timestamper from Hibernate.

But since you reported this issue and digging into it a bit more, it looks like the timestamper would need to return a timestamp which is in millis - as it adds the timeToLive (which is in millis):
https://github.com/hazelcast/hazelcast-hibernate5/blob/92d13a07aa01a850c4d12b7852958735bbb3d4f9/hazelcast-hibernate5/src/main/java/com/hazelcast/hibernate/local/LocalRegionCache.java#L372-L373
(Apologies for this oversight).

Reverting LocalRegionCache::nextTimestamp to use the HazelcastTimestamper seems to make your test case pass, so that looks like it would resolve the problem.
I think it would be good to add your test case to the test suite as well.

Feel free to proceed with creating a PR for this fix, if you are ok with that (or if not then hopefully over the next day or two I can take a look at creating a PR for this fix plus adding the test case - whatever you prefer).

[dohertyfjatl]

@George-007 here is the pull request that I have created:
#56
which includes a reversion to use the HazelcastTimestamper, as well as some additional test cases which includes the scenario you outlined above.

[jiri-pejchal]

Thanks, I'll test.

[leszko]

Fixed by #56

[leszko]

The fix is released in hazelcast-hibernate:1.3.2