Issue:
I have a criteria query where Hibernate's 2nd level cache is used in using cache(true):
User user = User.createCriteria().get {
eq("id", 1l)
cache(true)
}
When this code is hit two times, 1st time it makes the database query which is expected but when the next time the same code is executed, it should not hit the database for the query instead it should get it from the cache. But that is not happening.
Logs:
2019-08-29 23:25:06.023 DEBUG --- [nio-8080-exec-1] o.h.cache.internal.StandardQueryCache : Checking cached query results in region: org.hibernate.cache.internal.StandardQueryCache
2019-08-29 23:25:06.023 DEBUG --- [nio-8080-exec-1] o.h.c.e.i.r.EhcacheGeneralDataRegion : key: sql: select this_.id as id1_0_0_, this_.version as version2_0_0_, this_.first_name as first_na3_0_0_, this_.last_name as last_nam4_0_0_, this_.email as email5_0_0_ from user this_ where this_.id=?; parameters: 1, ; transformer: org.hibernate.transform.CacheableResultTransformer@110f2
2019-08-29 23:25:06.027 DEBUG --- [nio-8080-exec-1] o.h.c.e.i.r.EhcacheGeneralDataRegion : Element for key sql: select this_.id as id1_0_0_, this_.version as version2_0_0_, this_.first_name as first_na3_0_0_, this_.last_name as last_nam4_0_0_, this_.email as email5_0_0_ from user this_ where this_.id=?; parameters: 1, ; transformer: org.hibernate.transform.CacheableResultTransformer@110f2 is null
2019-08-29 23:25:06.028 DEBUG --- [nio-8080-exec-1] o.h.cache.internal.StandardQueryCache : Query results were not found in cache
2019-08-29 23:25:06.030 DEBUG --- [nio-8080-exec-1] org.hibernate.SQL : select this_.id as id1_0_0_, this_.version as version2_0_0_, this_.first_name as first_na3_0_0_, this_.last_name as last_nam4_0_0_, this_.email as email5_0_0_ from user this_ where this_.id=?
2019-08-29 23:25:06.046 DEBUG --- [nio-8080-exec-1] o.h.s.internal.ConcurrentStatisticsImpl : HHH000117: HQL: [CRITERIA] select this_.id as id1_0_0_, this_.version as version2_0_0_, this_.first_name as first_na3_0_0_, this_.last_name as last_nam4_0_0_, this_.email as email5_0_0_ from user this_ where this_.id=?, time: 17ms, rows: 1
2019-08-29 23:25:06.047 DEBUG --- [nio-8080-exec-1] o.h.cache.internal.StandardQueryCache : Caching query results in region: org.hibernate.cache.internal.StandardQueryCache; timestamp=6418846948913152
2019-08-29 23:25:06.049 DEBUG --- [nio-8080-exec-1] o.h.c.e.i.r.EhcacheGeneralDataRegion : key: sql: select this_.id as id1_0_0_, this_.version as version2_0_0_, this_.first_name as first_na3_0_0_, this_.last_name as last_nam4_0_0_, this_.email as email5_0_0_ from user this_ where this_.id=?; parameters: 1, ; transformer: org.hibernate.transform.CacheableResultTransformer@110f2 value: [6418846948913152, 1]
Found com.wizpanda.test.User : 1
2019-08-29 23:25:06.099 INFO --- [nio-8080-exec-1] i.StatisticalLoggingSessionEventListener : Session Metrics {
45071 nanoseconds spent acquiring 1 JDBC connections;
0 nanoseconds spent releasing 0 JDBC connections;
3767346 nanoseconds spent preparing 1 JDBC statements;
4620558 nanoseconds spent executing 1 JDBC statements;
0 nanoseconds spent executing 0 JDBC batches;
7925151 nanoseconds spent performing 1 L2C puts;
0 nanoseconds spent performing 0 L2C hits;
4562453 nanoseconds spent performing 1 L2C misses;
0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Environment:
- Operating System: MacOS, CentOS7
- GORM Version: 6.1.11
- Grails Version (if using Grails): 3.3.9
- JDK Version: 1.8.0_91
Steps to reproduce:
- Clone this repo
git clone [email protected]:wizpanda/test-l2-cache.git - Login to MySQL database and create a new database
create database test_l2_cache - Change the MySQL username & password in
grails-app/conf/application.yml - Run the app
grails run-appor./gradlew bootRun - Browse to
http://localhost:8080/and check the logs
Raised issue: https://github.com/grails/grails-data-mapping/issues/1266
