Domain class mapping with fetch: 'join' on OneToOne association results in n+1 queries

[amcclain]

We have been troubleshooting n+1 query behavior resulting from a simple association between two domain objects. We believe this should be prevented by specifying a fetch: 'join' mapping on the parent object, but our tests show this mapping having no effect.

We are left wondering if we have some ongoing misunderstanding about the documented features in GORM to control fetching of associated objects, or if something has regressed in GORM itself and this essential feature is broken.

We have created a sample application to reproduce: https://github.com/xh/gorm-list-nplus1-bug/tree/nPlusOneWithSingleAssociation - please see the nPlusOneWithSingleAssociation branch for the clearest expression of the issue that we could create.

Grails 6.0.0
GORM 8.0.0. (via Grails)
Hibernate 5.6.15.Final (via GORM)
Database: H2 (via Grails, although same behavior replicates on MySQL, MSSQL)

Parent class:

class Flight {

    String number
    Location destination

    static mapping = {
       destination fetch: 'join'
    }
}

Child class:

class Location {
    String city
}

Within TestController we have a findAll endpoint that effectively does the following:

flights = Flight.findAll()
flights.collect { f ->
  [number: f.number, city: f.destination.city]
}

Expected result: SQL logging shows a single query to load all rows from flight, with a join to location to include location-based fields for each flight.

Actual result: SQL logging shows initial query to fetch all flights without any join, and then n queries to fetch each flight's location, one-by-one. Here are the logs from that call - we bootstrap three flights in total, each with a single location:

''2023-08-31 13:03:18.627  INFO --- [nio-8080-exec-1] io.xh.grails.TestController              : --------------------------------------------------
''2023-08-31 13:03:18.627  INFO --- [nio-8080-exec-1] io.xh.grails.TestController              : START Find all flights >>
''2023-08-31 13:03:18.627 DEBUG --- [nio-8080-exec-1] o.g.o.hibernate.GrailsHibernateTemplate  : Found thread-bound Session for HibernateTemplate
''2023-08-31 13:03:18.671 DEBUG --- [nio-8080-exec-1] org.hibernate.SQL                        : select flight0_.id as id1_0_, flight0_.version as version2_0_, flight0_.number as number3_0_, flight0_.destination_id as destinat4_0_ from flight flight0_
''2023-08-31 13:03:18.678 DEBUG --- [nio-8080-exec-1] o.g.o.hibernate.GrailsHibernateTemplate  : Not closing pre-bound Hibernate Session after HibernateTemplate
''2023-08-31 13:03:18.678  INFO --- [nio-8080-exec-1] io.xh.grails.TestController              : << END Find all flights
''2023-08-31 13:03:18.678  INFO --- [nio-8080-exec-1] io.xh.grails.TestController              : --------------------------------------------------
''2023-08-31 13:03:18.679  INFO --- [nio-8080-exec-1] io.xh.grails.TestController              : 
''2023-08-31 13:03:18.679  INFO --- [nio-8080-exec-1] io.xh.grails.TestController              : --------------------------------------------------
''2023-08-31 13:03:18.679  INFO --- [nio-8080-exec-1] io.xh.grails.TestController              : START Render with destination.city >>
''2023-08-31 13:03:18.681 DEBUG --- [nio-8080-exec-1] org.hibernate.SQL                        : select location0_.id as id1_1_0_, location0_.version as version2_1_0_, location0_.city as city3_1_0_ from location location0_ where location0_.id=?
''2023-08-31 13:03:18.682 DEBUG --- [nio-8080-exec-1] org.hibernate.SQL                        : select location0_.id as id1_1_0_, location0_.version as version2_1_0_, location0_.city as city3_1_0_ from location location0_ where location0_.id=?
''2023-08-31 13:03:18.683 DEBUG --- [nio-8080-exec-1] org.hibernate.SQL                        : select location0_.id as id1_1_0_, location0_.version as version2_1_0_, location0_.city as city3_1_0_ from location location0_ where location0_.id=?
''2023-08-31 13:03:18.691  INFO --- [nio-8080-exec-1] io.xh.grails.TestController              : << END Render with destination.city
''2023-08-31 13:03:18.691  INFO --- [nio-8080-exec-1] io.xh.grails.TestController              : --------------------------------------------------

That same controller has another findAllWithFetchArg() example that attempts to use an explicit fetch argument to findAll, which also does not work as expected/documented:

flights = Flight.findAll(fetch: [destination: 'join'])
flights.collect { f ->
  [number: f.number, city: f.destination.city]
}

Expected result: SQL logging shows a single query to load all rows from flight, with a join to location to include location-based fields for each flight.

Actual result: SQL logging shows initial query to fetch all flights with an odd and seemingly useless inner join location, but no fields read from location, and then the same n queries to fetch each flight's location, one-by-one:

''2023-08-31 13:04:50.116  INFO --- [nio-8080-exec-3] io.xh.grails.TestController              : --------------------------------------------------
''2023-08-31 13:04:50.116  INFO --- [nio-8080-exec-3] io.xh.grails.TestController              : START Find all flights with fetch/join query arg >>
''2023-08-31 13:04:50.117 DEBUG --- [nio-8080-exec-3] o.g.o.hibernate.GrailsHibernateTemplate  : Found thread-bound Session for HibernateTemplate
''2023-08-31 13:04:50.135 DEBUG --- [nio-8080-exec-3] org.hibernate.SQL                        : select flight0_.id as id1_0_, flight0_.version as version2_0_, flight0_.number as number3_0_, flight0_.destination_id as destinat4_0_ from flight flight0_ inner join location location1_ on flight0_.destination_id=location1_.id
''2023-08-31 13:04:50.137 DEBUG --- [nio-8080-exec-3] o.g.o.hibernate.GrailsHibernateTemplate  : Not closing pre-bound Hibernate Session after HibernateTemplate
''2023-08-31 13:04:50.137  INFO --- [nio-8080-exec-3] io.xh.grails.TestController              : << END Find all flights with fetch/join query arg
''2023-08-31 13:04:50.137  INFO --- [nio-8080-exec-3] io.xh.grails.TestController              : --------------------------------------------------
''2023-08-31 13:04:50.137  INFO --- [nio-8080-exec-3] io.xh.grails.TestController              : 
''2023-08-31 13:04:50.137  INFO --- [nio-8080-exec-3] io.xh.grails.TestController              : --------------------------------------------------
''2023-08-31 13:04:50.137  INFO --- [nio-8080-exec-3] io.xh.grails.TestController              : START Render with destination.city >>
''2023-08-31 13:04:50.137 DEBUG --- [nio-8080-exec-3] org.hibernate.SQL                        : select location0_.id as id1_1_0_, location0_.version as version2_1_0_, location0_.city as city3_1_0_ from location location0_ where location0_.id=?
''2023-08-31 13:04:50.137 DEBUG --- [nio-8080-exec-3] org.hibernate.SQL                        : select location0_.id as id1_1_0_, location0_.version as version2_1_0_, location0_.city as city3_1_0_ from location location0_ where location0_.id=?
''2023-08-31 13:04:50.138 DEBUG --- [nio-8080-exec-3] org.hibernate.SQL                        : select location0_.id as id1_1_0_, location0_.version as version2_1_0_, location0_.city as city3_1_0_ from location location0_ where location0_.id=?
''2023-08-31 13:04:50.139  INFO --- [nio-8080-exec-3] io.xh.grails.TestController              : << END Render with destination.city
''2023-08-31 13:04:50.139  INFO --- [nio-8080-exec-3] io.xh.grails.TestController              : --------------------------------------------------

I know there are several gotchas and non-intuitive behaviors around GORM, Hibernate, associations, and n+1 - but this really seems like a bad break from the expected behavior for such a core and straightforward use case.

If anyone can confirm or advise we would appreciate it greatly!

[lbwexler]

Hi -- I have isolated this behavior to a problem with unconstrained calls to MyDomainObject.list() and MyDomainObject.findAll().

In contrast, all the findXXX methods and any of the following work fine --
findAllWhere(Map filter), findAll(Closure criteria), and the dynamic finders all work fine.

I was able to trace the issue down to the override of GormStaticApi.list() here --

gorm-hibernate5/grails-datastore-gorm-hibernate5/src/main/groovy/org/grails/orm/hibernate/HibernateGormStaticApi.groovy

Line 77 in 85a11a8

List<D> list(Map params = Collections.emptyMap()) {

Avoiding this method by using an empty criteria seems to workaround the problem, and I now have the following workaround in our plugin:

void doWithDynamicMethods() {
       // Workaround for issue with unconstrained findAll() and list().
       // See https://github.com/grails/gorm-hibernate5/issues/750
       grailsApplication.domainClasses.each {
           def meta = it.metaClass.static
           meta.list = meta.findAll = { delegate.findAll({}) }
           meta.list = meta.findAll = { Map params -> delegate.findAll(params, {}) }
       }
   }

[lbwexler]

Hi -- Think it might be a relatively straightforward matter to just remove the problematic list() override in HibernateGormStaticApi shown above, but am not sure what it is designed to do and if that is appropriate. Can anybody take a look? this seems like a pretty bad bug to leave in place.