amcclain opened a new issue, #14343: URL: https://github.com/apache/grails-core/issues/14343
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](https://gorm.grails.org/latest/hibernate/manual/index.html#_configuring_eager_fetching) 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: ```groovy class Flight { String number Location destination static mapping = { destination fetch: 'join' } } ``` Child class: ```groovy class Location { String city } ``` Within `TestController` we have a `findAll` endpoint that effectively does the following: ```groovy 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: ```groovy 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! -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. To unsubscribe, e-mail: [email protected] For queries about this service, please contact Infrastructure at: [email protected]
