SQL is run once for every row when .list() is called, despite having no associations

Question

I am using grails 2.5.3

I have a config like:

grails {
    hibernate {
        cache.queries = true
        cache.use_second_level_cache = true
        cache.use_query_cache = true
        cache.provider_class =  'net.sf.ehcache.hibernate.SingletonEhCacheProvider'

I have domain class like:

class AuthorizedDevice implements JSONFormat {
    int id
    String authKey = generateAuthKey()
    String owner
    String name
    String permittedUsers
    String userAgent
    Date   lastVisit
    Date   lastInitialized
    String lastUser
    String lastIpAddress
    Date   dateCreated
    boolean enabled = true
    String notes

    static constraints = {
        authKey(blank: false, unique: true, maxSize: 8)
        owner(blank: false, validator: GormValidators.isCorpUserName)
        name(blank: false, unique: 'owner')
        permittedUsers(nullable: true, validator: permittedUsersValidator)
        userAgent(nullable: true, maxSize: 500)
        lastVisit(nullable: true)
        lastInitialized(nullable: true)
        lastUser(nullable: true, maxSize: 50)
        lastIpAddress(nullable: true, maxSize: 50)
        notes(nullable: true, maxSize: 500)
    }

    def auditService
    def afterInsert() {auditService.noteDeviceChange('Created Device', id)}
    def afterUpdate() {auditService.noteDeviceChange('Updated Device', id)}
    def afterDelete() {auditService.noteDeviceChange('Deleted Device', null)} // Not allowed by GUI, but just in case.


    public Object formatForJSON() {
        return [
                id: id,
                authKey: authKey,
                owner: owner,
                name: name,
                permittedUsers: permittedUsers,
                userAgent: userAgent,
                lastVisit: lastVisit,
                lastInitialized: lastInitialized,
                lastUser: lastUser,
                lastIpAddress: lastIpAddress,
                enabled: enabled,
                notes: notes
        ]
    }

    //------------------
    // Implementation
    //------------------
    private String generateAuthKey() {
         ....
    }

    static permittedUsersValidator = {String val, Object obj, Errors errors ->
        if (!val || val.trim().equals('*')) return
        val.split(',').each {
            if (!getCorprUser(it.trim())) {
                errors.rejectValue('permittedUsers', '',
                        "Unknown User ${it}.  Use a comma-delimited list of usernames or  * to indicate all users."
                )
            }
        }
    }

}

I build a device list like:

def devices = AuthorizedDevice.list()

I notice that GORM/hibernate is doing one SQL query for every row in the table every time AuthorizedDevice.list() is called.

We do not have any associations in the model fields that would generate N+1 queries.

Does someone know what prompts this N+1 like behaviour even though there are no associations?

The first time the .list() is called, the following SQL is run just once:

select
    this_.id as id4_0_,
    this_.version as version4_0_,
    this_.auth_key as auth3_4_0_,
    this_.date_created as date4_4_0_,
    this_.enabled as enabled4_0_,
    this_.last_initialized as last6_4_0_,
    this_.last_ip_address as last7_4_0_,
    this_.last_user as last8_4_0_,
    this_.last_visit as last9_4_0_,
    this_.name as name4_0_,
    this_.notes as notes4_0_,
    this_.owner as owner4_0_,
    this_.permitted_users as permitted13_4_0_,
    this_.user_agent as user14_4_0_ 
from
    authorized_device this_

Everytime the .list() is called thereafter, this SQL gets run for every row in the table:

select
    authorized0_.id as id4_0_,
    authorized0_.version as version4_0_,
    authorized0_.auth_key as auth3_4_0_,
    authorized0_.date_created as date4_4_0_,
    authorized0_.enabled as enabled4_0_,
    authorized0_.last_initialized as last6_4_0_,
    authorized0_.last_ip_address as last7_4_0_,
    authorized0_.last_user as last8_4_0_,
    authorized0_.last_visit as last9_4_0_,
    authorized0_.name as name4_0_,
    authorized0_.notes as notes4_0_,
    authorized0_.owner as owner4_0_,
    authorized0_.permitted_users as permitted13_4_0_,
    authorized0_.user_agent as user14_4_0_
from
    authorized_device authorized0_
where
    authorized0_.id=?

Answer 1

https://dzone.com/articles/pitfalls-hibernate-second-0

If a query has cached results, it returns a list of entity Id's, that is then resolved against the second level cache. If the entities with those Ids where not configured as cacheable or if they have expired, then a select will hit the database per entity Id.

For example if a cached query returned 1000 entity Ids, and non of those entities where cached in the second level cache, then 1000 selects by Id will be issued against the database.

The solution to this problem is to configure query results expiration to be aligned with the expiration of the entities returned by the query.

in your case maybe the solution is just adding to AuthorizedDevice :

static mapping = { cache true } 

in order to enable the second level cache on the domain class AuthorizedDevice (hibernate doesn't enable it by default).

Because it seems like the result of the first sql log you give :

select
    this_.
...
from

is in the cache (query cache). So it is not executed twice. In the link I give, it is explained that the result is cached as a list of entity ids. But not all the data of each entities are in the cache, only the ids. Then during the other call to .list() hibernate will have theses ids in the cache, and will try to retrieve the corresponding entities in the second level cache, but it fails and then hibernate make query to DB for each of these ids.