Hibernate 2nd level cache not working with GORM 6.1.11

[sagrawal31]

Apologies if I'm creating a duplicate issue or I'm not following the doc but I did deep debugging till I'm capable of and went through various posts but couldn't get this working.

Task List

• Steps to reproduce provided
• Stacktrace (if present) provided
• Example that reproduces the problem uploaded to Github
• Full description of the issue provided (see below)

Steps to Reproduce

1. Clone this repo git clone [email protected]:wizpanda/test-l2-cache.git
2. Login to MySQL database and create a new database create database test_l2_cache
3. Change the MySQL username & password in grails-app/conf/application.yml
4. Run the app grails run-app or ./gradlew bootRun
5. Browse to http:https://localhost:8080/ and check the logs

Expected Behaviour

Hibernate 2nd level cache is used in hibernate criteria 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.

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)
}

Actual Behaviour

Criteria should not hit the database after 1st time unless the cache is evicted.

Environment Information

• Operating System: MacOS, CentOS7
• GORM Version: 6.1.11
• Grails Version (if using Grails): 3.3.9
• JDK Version: 1.8.0_91

Example Application

https://github.com/wizpanda/test-l2-cache

[sagrawal31]

Any clues, workaround or information on this?

[demon101]

@sagrawal31 For my projects, I'm using https://github.com/purpleraven/grails-cows-cache-plugin . Hibernate 2nd level cache for me works well. And I didn't check it without the plugin

But, as I know, Hibernate 2nd level cache works if you are requesting entity by primary key.
User.get(id)

[sagrawal31]

@demon101 As per my understanding, Hibernate 2nd level cache works with any kind of query, not just primary key http:https://gorm.grails.org/6.1.x/hibernate/manual/#_caching_queries

[demon101]

@sagrawal31 you are talking about query cache.
My project use GORM 6.1.12.RELEASE. It works with dynamic finders

[sagrawal31]

@demon101 I'm not sure if I got your question.

[sagrawal31]

I spent another 6-7 hours, did all sorts of debugging by going through GORM -> Hibernate using debug points but couldn't make it work.

Later on, I realized that I had to put cache true in the mapping block which I always assumed that it will enable caching for all queries irrespective of passing cache: true in dynamic finders.

Stupid me 😞

Sorry for the mess!