I am trying to setup Hibernate query cache for queries derived by method name in Spring Data, but the query cache is never used, or doesn't even seem to be active.
I am using Spring Boot 2.2.1, Kotlin 1.3.50, and Caffeine with the JCache extension as my underlying Hibernate cache.
My repository is as follows:
@Repository
interface LibraryRepository : JpaRepository<Library, Long> {
@QueryHints(QueryHint(name = CACHEABLE, value = "true"))
override fun findAll(sort: Sort): List<Library>
}
Second level cache is active and working, and properly set on the Library entity:
@Entity
@Cacheable
@Cache(usage = CacheConcurrencyStrategy.READ_WRITE, region = "cache.library")
class Library ( ... )
Excerpt from my configuration:
spring:
jpa.properties:
javax.persistence.sharedCache.mode: ENABLE_SELECTIVE
hibernate:
generate_statistics: true
session.events.log: true
hibernate:
cache:
use_second_level_cache: true
use_query_cache: true
region.factory_class: org.hibernate.cache.jcache.JCacheRegionFactory
javax.cache.provider: com.github.benmanes.caffeine.jcache.spi.CaffeineCachingProvider
However when querying libraryRepository.findAll(Sort.by("name")), the database is always queried.
Nothing is mentioned in the logs about query cache.
First call (which should put in the cache):
2019-12-16 18:14:09.955 DEBUG 20400 --- [nio-8080-exec-1] org.hibernate.SQL :
select
library0_.id as id1_3_,
library0_.created_date as created_2_3_,
library0_.last_modified_date as last_mod3_3_,
library0_.name as name4_3_,
library0_.root as root5_3_
from
library library0_
order by
library0_.name asc
2019-12-16 18:14:09.956 DEBUG 20400 --- [nio-8080-exec-1] o.h.c.s.support.AbstractReadWriteAccess : Caching data from load [region=`cache.library` (AccessType[read-write])] : key[org.gotson.komga.domain.model.Library#73] -> value[CacheEntry(org.gotson.komga.domain.model.Library)]
2019-12-16 18:14:09.957 DEBUG 20400 --- [nio-8080-exec-1] o.h.c.s.support.AbstractReadWriteAccess : Checking writeability of read-write cache item [timestamp=`6457308078116864`, version=`null`] : txTimestamp=`6457308159795200`, newVersion=`null`
2019-12-16 18:14:09.957 DEBUG 20400 --- [nio-8080-exec-1] o.h.c.s.support.AbstractReadWriteAccess : Cache put-from-load [region=`AccessType[read-write]` (cache.library), key=`org.gotson.komga.domain.model.Library#73`, value=`CacheEntry(org.gotson.komga.domain.model.Library)`] failed due to being non-writable
2019-12-16 18:14:09.957 DEBUG 20400 --- [nio-8080-exec-1] o.h.c.s.support.AbstractReadWriteAccess : Caching data from load [region=`cache.library` (AccessType[read-write])] : key[org.gotson.komga.domain.model.Library#3] -> value[CacheEntry(org.gotson.komga.domain.model.Library)]
2019-12-16 18:14:09.957 DEBUG 20400 --- [nio-8080-exec-1] o.h.c.s.support.AbstractReadWriteAccess : Checking writeability of read-write cache item [timestamp=`6457308078116864`, version=`null`] : txTimestamp=`6457308159795200`, newVersion=`null`
2019-12-16 18:14:09.957 DEBUG 20400 --- [nio-8080-exec-1] o.h.c.s.support.AbstractReadWriteAccess : Cache put-from-load [region=`AccessType[read-write]` (cache.library), key=`org.gotson.komga.domain.model.Library#3`, value=`CacheEntry(org.gotson.komga.domain.model.Library)`] failed due to being non-writable
2019-12-16 18:14:09.957 DEBUG 20400 --- [nio-8080-exec-1] o.h.c.s.support.AbstractReadWriteAccess : Caching data from load [region=`cache.library` (AccessType[read-write])] : key[org.gotson.komga.domain.model.Library#33] -> value[CacheEntry(org.gotson.komga.domain.model.Library)]
2019-12-16 18:14:09.957 DEBUG 20400 --- [nio-8080-exec-1] o.h.c.s.support.AbstractReadWriteAccess : Checking writeability of read-write cache item [timestamp=`6457308078116864`, version=`null`] : txTimestamp=`6457308159795200`, newVersion=`null`
2019-12-16 18:14:09.958 DEBUG 20400 --- [nio-8080-exec-1] o.h.c.s.support.AbstractReadWriteAccess : Cache put-from-load [region=`AccessType[read-write]` (cache.library), key=`org.gotson.komga.domain.model.Library#33`, value=`CacheEntry(org.gotson.komga.domain.model.Library)`] failed due to being non-writable
2019-12-16 18:14:09.958 DEBUG 20400 --- [nio-8080-exec-1] o.h.stat.internal.StatisticsImpl : HHH000117: HQL: select generatedAlias0 from Library as generatedAlias0 order by generatedAlias0.name asc, time: 3ms, rows: 3
2019-12-16 18:14:09.989 DEBUG 20400 --- [nio-8080-exec-1] m.m.a.RequestResponseBodyMethodProcessor : Using 'application/json', given [*/*] and supported [application/json]
2019-12-16 18:14:10.025 DEBUG 20400 --- [nio-8080-exec-1] m.m.a.RequestResponseBodyMethodProcessor : Writing [[LibraryDto(id=73, name=All, root=file:/C:/Users/groebroe101209/files/all/), LibraryDto(id=3, name=C (truncated)...]
2019-12-16 18:14:10.123 INFO 20400 --- [nio-8080-exec-1] i.StatisticalLoggingSessionEventListener : Session Metrics {
35800 nanoseconds spent acquiring 1 JDBC connections;
0 nanoseconds spent releasing 0 JDBC connections;
279300 nanoseconds spent preparing 1 JDBC statements;
154000 nanoseconds spent executing 1 JDBC statements;
0 nanoseconds spent executing 0 JDBC batches;
1256401 nanoseconds spent performing 3 L2C puts;
0 nanoseconds spent performing 0 L2C hits;
0 nanoseconds spent performing 0 L2C misses;
0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
3500 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Second call (which should hit the cache):
2019-12-16 18:14:35.180 DEBUG 20400 --- [nio-8080-exec-3] org.hibernate.SQL :
select
library0_.id as id1_3_,
library0_.created_date as created_2_3_,
library0_.last_modified_date as last_mod3_3_,
library0_.name as name4_3_,
library0_.root as root5_3_
from
library library0_
order by
library0_.name asc
2019-12-16 18:14:35.181 DEBUG 20400 --- [nio-8080-exec-3] o.h.c.s.support.AbstractReadWriteAccess : Caching data from load [region=`cache.library` (AccessType[read-write])] : key[org.gotson.komga.domain.model.Library#73] -> value[CacheEntry(org.gotson.komga.domain.model.Library)]
2019-12-16 18:14:35.181 DEBUG 20400 --- [nio-8080-exec-3] o.h.c.s.support.AbstractReadWriteAccess : Checking writeability of read-write cache item [timestamp=`6457308078116864`, version=`null`] : txTimestamp=`6457308263133184`, newVersion=`null`
2019-12-16 18:14:35.181 DEBUG 20400 --- [nio-8080-exec-3] o.h.c.s.support.AbstractReadWriteAccess : Cache put-from-load [region=`AccessType[read-write]` (cache.library), key=`org.gotson.komga.domain.model.Library#73`, value=`CacheEntry(org.gotson.komga.domain.model.Library)`] failed due to being non-writable
2019-12-16 18:14:35.181 DEBUG 20400 --- [nio-8080-exec-3] o.h.c.s.support.AbstractReadWriteAccess : Caching data from load [region=`cache.library` (AccessType[read-write])] : key[org.gotson.komga.domain.model.Library#3] -> value[CacheEntry(org.gotson.komga.domain.model.Library)]
2019-12-16 18:14:35.181 DEBUG 20400 --- [nio-8080-exec-3] o.h.c.s.support.AbstractReadWriteAccess : Checking writeability of read-write cache item [timestamp=`6457308078116864`, version=`null`] : txTimestamp=`6457308263133184`, newVersion=`null`
2019-12-16 18:14:35.181 DEBUG 20400 --- [nio-8080-exec-3] o.h.c.s.support.AbstractReadWriteAccess : Cache put-from-load [region=`AccessType[read-write]` (cache.library), key=`org.gotson.komga.domain.model.Library#3`, value=`CacheEntry(org.gotson.komga.domain.model.Library)`] failed due to being non-writable
2019-12-16 18:14:35.182 DEBUG 20400 --- [nio-8080-exec-3] o.h.c.s.support.AbstractReadWriteAccess : Caching data from load [region=`cache.library` (AccessType[read-write])] : key[org.gotson.komga.domain.model.Library#33] -> value[CacheEntry(org.gotson.komga.domain.model.Library)]
2019-12-16 18:14:35.182 DEBUG 20400 --- [nio-8080-exec-3] o.h.c.s.support.AbstractReadWriteAccess : Checking writeability of read-write cache item [timestamp=`6457308078116864`, version=`null`] : txTimestamp=`6457308263133184`, newVersion=`null`
2019-12-16 18:14:35.182 DEBUG 20400 --- [nio-8080-exec-3] o.h.c.s.support.AbstractReadWriteAccess : Cache put-from-load [region=`AccessType[read-write]` (cache.library), key=`org.gotson.komga.domain.model.Library#33`, value=`CacheEntry(org.gotson.komga.domain.model.Library)`] failed due to being non-writable
2019-12-16 18:14:35.182 DEBUG 20400 --- [nio-8080-exec-3] o.h.stat.internal.StatisticsImpl : HHH000117: HQL: select generatedAlias0 from Library as generatedAlias0 order by generatedAlias0.name asc, time: 2ms, rows: 3
2019-12-16 18:14:35.183 DEBUG 20400 --- [nio-8080-exec-3] m.m.a.RequestResponseBodyMethodProcessor : Using 'application/json', given [*/*] and supported [application/json]
2019-12-16 18:14:35.183 DEBUG 20400 --- [nio-8080-exec-3] m.m.a.RequestResponseBodyMethodProcessor : Writing [[LibraryDto(id=73, name=All, root=file:/C:/Users/groebroe101209/files/all/), LibraryDto(id=3, name=C (truncated)...]
2019-12-16 18:14:35.186 INFO 20400 --- [nio-8080-exec-3] i.StatisticalLoggingSessionEventListener : Session Metrics {
73400 nanoseconds spent acquiring 1 JDBC connections;
0 nanoseconds spent releasing 0 JDBC connections;
41301 nanoseconds spent preparing 1 JDBC statements;
180701 nanoseconds spent executing 1 JDBC statements;
0 nanoseconds spent executing 0 JDBC batches;
1124001 nanoseconds spent performing 3 L2C puts;
0 nanoseconds spent performing 0 L2C hits;
0 nanoseconds spent performing 0 L2C misses;
0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
4000 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
