Cache eviction problem on Hibernate 4.3
wolf31o2 opened this issue · 6 comments
This appears similar to #9 but I have no easy way to verify the "eviction" is occurring.
Hibernate: 4.3.9.Final (and 4.3.11.Final, same results)
Hibernate-l2-memcached: 4.3.11.0
I am attempting to switch from ehcache to memcached and am running into issues which appear to be eviction-related. I can verify that the problem occurs only when using memcached as the second-level cache.
In my code, I have a flushAndClear function which I am calling in my integration tests.
protected void flushAndClear() {
sessionFactory.getCurrentSession().flush();
sessionFactory.getCurrentSession().clear();
sessionFactory.getCache().evictAllRegions();
}
Configuration
hibernate.cache.use_second_level_cache: true
hibernate.cache.use_query_cache: true
hibernate.cache.use_structured_entries: true
# hibernate.cache.region.factory_class: org.hibernate.cache.ehcache.SingletonEhCacheRegionFactory
hibernate.cache.region.factory_class: com.mc.hibernate.memcached.MemcachedRegionFactory
hibernate.memcached.cacheTimeSeconds: 60
hibernate.memcached.clearSupported: true
I am running the above flushAndClear between making an update and querying it from the cache. The test is returning the pre-cache value.
going trough the implementation in debug mode when calling sessionFactory.getCache().evictAllRegions(); with hibernate.memcached.clearSupported set to true, I can see that MemcachedCache.clear() gets called as expected for each region.
And subsequent calls that would get stuff from session, have to go all the way to the DB.
Maybe I am missing something, maybe it's an issue that is not related to eviction but to something else? If possible, can you add a code snippet that shows how you are making an update and how you are querying it from the cache. Thanks.
OK. I'm definitely having a different issue than originally reported. It appears that my configuration isn't being read correctly.
We're using Spring Boot 1.4.7 with Hibernate 4.3.9 and are configuring with an application.yaml file. It appears that none of my hibernate.memcached.* settings are being honored. With hibernate.memcached.cacheTimeSeconds: 60 set, I am seeing objects in the cache living longer. It appears that they're expiring after 300 seconds. To verify, I added a Thread.sleep(301000) to my flushAndClear method to sleep longer than the default TTL.
I am running this through our normal integration test suite. I can verify that the update is indeed updating in the database.
Here's a more complete configuration snippet.
hibernate.cache.use_second_level_cache: true
hibernate.cache.use_query_cache: true
hibernate.cache.use_structured_entries: true
# hibernate.cache.region.factory_class: org.hibernate.cache.ehcache.SingletonEhCacheRegionFactory
hibernate.cache.region.factory_class: com.mc.hibernate.memcached.MemcachedRegionFactory
# above here definitely works, as I am 100% caching into memcache and returning cached results
hibernate.memcached.servers:
# overriding this in a different profile, local, and using HIBERNATE_MEMCACHED_SERVERS in env
hibernate.memcached.cacheTimeSeconds: 1
hibernate.memcached.clearSupported: true
hibernate.memcached.cacheLockTimeout: 500
hibernate.memcached.connectionFactory: BinaryConnectionFactory
hibernate.memcached.dogpilePrevention: true
# snip unrelated
---
spring.profiles: local
hibernate.memcached.servers: localhost:11211
Items do not expire after 1s. I am updating the logging configuration and running the tests, again.
What is the best way to retrieve useful output. I've tried the following logging configuration, and see that I am still missing something.
<!-- Hibernate Memcached second-level cache -->
<logger name="com.mc.hibernate.memcached" level="DEBUG" />
<logger name="net.spy.spymemcached" level="DEBUG" />
<logger name="org.hibernate.cache" level="DEBUG" />
Looking at my cache (echo lru_crawler metadump all | nc 127.0.0.1 11211) I see lots of keys that are hashes which have an expiration time 300s from the last accessed time... most of these keys are accessed exactly once during unit tests, so I would guess those la times are also creation time.
I checked, and at no point do I see this log in debug
Dogpile prevention enabled, setting token and adjusting object cache time
Do I need to do something specific to configure this in Spring 4.x w/ Spring Boot 1.4.7? There's a pile of configuration for ehcache that I'm replacing and I feel like I'm just missing something to wire up my configuration.
So it's a configuration issue the way I see it... but I can't figure it out from the snippets you provided.
I made a small test project (admittedly using the latest versions of spring boot and hibernate - but maybe you can retrofit it to your use case) that works fine: https://github.com/mihaicostin/boot-memcached
If you run the test in this project, you will see in the logs stuff like:
2020-05-15 08:31:51 - MemcachedClient.get(default-update-timestamps-region:index_key)
2020-05-15 08:31:51 - Final cache key: [d7e680fa5168cf243988168c476c3e5ff00101e5]
2020-05-15 08:31:51 - Dogpile prevention enabled, setting token and adjusting object cache time. Key: [d7e680fa5168cf243988168c476c3e5ff00101e5.dogpileTokenKey]
2020-05-15 08:31:51 - MemcachedClient.set(d7e680fa5168cf243988168c476c3e5ff00101e5.dogpileTokenKey)
2020-05-15 08:31:51 - Memcache.set(d7e680fa5168cf243988168c476c3e5ff00101e5)
2020-05-15 08:31:51 - MemcachedClient.set(d7e680fa5168cf243988168c476c3e5ff00101e5)
2020-05-15 08:31:51 - MemcachedClient.get(default-update-timestamps-region:index_key)
2020-05-15 08:31:51 - Final cache key: [d7e680fa5168cf243988168c476c3e5ff00101e5]
2020-05-15 08:31:51 - Dogpile prevention enabled, setting token and adjusting object cache time. Key: [d7e680fa5168cf243988168c476c3e5ff00101e5.dogpileTokenKey]
2020-05-15 08:31:51 - MemcachedClient.set(d7e680fa5168cf243988168c476c3e5ff00101e5.dogpileTokenKey)
2020-05-15 08:31:51 - Memcache.set(d7e680fa5168cf243988168c476c3e5ff00101e5)
2020-05-15 08:31:51 - MemcachedClient.set(d7e680fa5168cf243988168c476c3e5ff00101e5)
Maybe this can be of help, at least as a starting point in debugging what is missing from your config files ?
BTW, I find it weird that it picks up the hibernate.cache.region.factory_class property (since it is using memcached as L2 cache) but it ignores the other properties :|
Well, hibernate.cache.region.factory_class was already used in my application to configure ehcache. I found that any properties that I change will change, but ones that I add do not. This definitely leads to an issue with configuration loading, which I have now confirmed.
Last night, I ran
tests-integration.sh -Dhibernate.memcached.dogpilePrevention=true -Dhibernate.memcached.clearSupported=true -Dhibernate.memcached.cacheTimeSeconds=60
to kick off my integration suite and it worked just fine. I see the Dogpile log, and I see keys that are named appropriately. I'm going to close this issue. Your code is functioning perfectly. Thank you.