Eager loading is triggering n+1 queries?

Question

This question is specific to n+1 problem when using eager loading. The issue I am seeing is, n+1 problem is happening when child entity is defined to load eagerly, is this expected.

The entity relationships are as follows. A student belongs to one college, and a college can have multiple students. So there is ManyToOne relationship between Student --> College, and a OneToMany relationship between College --> Student.

The entities are as below.

@Entity
public class College {

    @Id
    @GeneratedValue
    private int collegeId;

    private String collegeName;

    @OneToMany(targetEntity = Student.class, mappedBy = "college", cascade = CascadeType.ALL, fetch = FetchType.EAGER)
    //as you can see students is loaded eagerly.
    private List<Student> students;

and

@Entity
public class Student {

    @Id
    @GeneratedValue
    private int studentId;

    private String studentName;

    @ManyToOne
    @JoinColumn(name = "collegeId_fk")
    private College college;

Now when I run below code,

collegeRepo.findAll().forEach( c -> System.err.println("college wit students: " + c.getStudents() ) );

I see multiple queries are triggered:

2022-02-21 07:12:32.242 TRACE 19824 --- [           main] o.s.t.i.TransactionInterceptor           : Getting transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findAll]
Hibernate: 
    select
        college0_.college_id as college_1_1_,
        college0_.college_name as college_2_1_ 
    from
        college college0_
2022-02-21 07:12:32.497 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([college_1_1_] : [INTEGER]) - [1]
2022-02-21 07:12:32.500 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([college_2_1_] : [VARCHAR]) - [college1]
2022-02-21 07:12:32.501 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([college_1_1_] : [INTEGER]) - [2]
2022-02-21 07:12:32.501 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([college_2_1_] : [VARCHAR]) - [college2]
2022-02-21 07:12:32.501 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([college_1_1_] : [INTEGER]) - [3]
2022-02-21 07:12:32.501 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([college_2_1_] : [VARCHAR]) - [college3]
2022-02-21 07:12:32.501 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([college_1_1_] : [INTEGER]) - [4]
2022-02-21 07:12:32.502 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([college_2_1_] : [VARCHAR]) - [college4]
Hibernate: 
    select
        students0_.college_id_fk as college_3_12_0_,
        students0_.student_id as student_1_12_0_,
        students0_.student_id as student_1_12_1_,
        students0_.college_id_fk as college_3_12_1_,
        students0_.student_name as student_2_12_1_ 
    from
        student students0_ 
    where
        students0_.college_id_fk=?
2022-02-21 07:12:32.510 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicBinder      : binding parameter [1] as [INTEGER] - [4]
Hibernate: 
    select
        students0_.college_id_fk as college_3_12_0_,
        students0_.student_id as student_1_12_0_,
        students0_.student_id as student_1_12_1_,
        students0_.college_id_fk as college_3_12_1_,
        students0_.student_name as student_2_12_1_ 
    from
        student students0_ 
    where
        students0_.college_id_fk=?
2022-02-21 07:12:32.744 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicBinder      : binding parameter [1] as [INTEGER] - [3]
Hibernate: 
    select
        students0_.college_id_fk as college_3_12_0_,
        students0_.student_id as student_1_12_0_,
        students0_.student_id as student_1_12_1_,
        students0_.college_id_fk as college_3_12_1_,
        students0_.student_name as student_2_12_1_ 
    from
        student students0_ 
    where
        students0_.college_id_fk=?
2022-02-21 07:12:32.975 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicBinder      : binding parameter [1] as [INTEGER] - [2]
2022-02-21 07:12:33.207 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([student_1_12_1_] : [INTEGER]) - [1]
2022-02-21 07:12:33.207 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([college_3_12_1_] : [INTEGER]) - [2]
2022-02-21 07:12:33.207 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([student_2_12_1_] : [VARCHAR]) - [student1]
2022-02-21 07:12:33.207 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([college_3_12_0_] : [INTEGER]) - [2]
2022-02-21 07:12:33.208 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([student_1_12_0_] : [INTEGER]) - [1]
2022-02-21 07:12:33.211 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([student_1_12_1_] : [INTEGER]) - [2]
2022-02-21 07:12:33.211 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([college_3_12_1_] : [INTEGER]) - [2]
2022-02-21 07:12:33.211 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([student_2_12_1_] : [VARCHAR]) - [student2]
2022-02-21 07:12:33.211 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([college_3_12_0_] : [INTEGER]) - [2]
2022-02-21 07:12:33.211 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([student_1_12_0_] : [INTEGER]) - [2]
2022-02-21 07:12:33.211 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([student_1_12_1_] : [INTEGER]) - [3]
2022-02-21 07:12:33.212 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([college_3_12_1_] : [INTEGER]) - [2]
2022-02-21 07:12:33.212 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([student_2_12_1_] : [VARCHAR]) - [student3]
2022-02-21 07:12:33.212 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([college_3_12_0_] : [INTEGER]) - [2]
2022-02-21 07:12:33.212 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([student_1_12_0_] : [INTEGER]) - [3]
2022-02-21 07:12:33.212 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([student_1_12_1_] : [INTEGER]) - [4]
2022-02-21 07:12:33.212 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([college_3_12_1_] : [INTEGER]) - [2]
2022-02-21 07:12:33.212 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([student_2_12_1_] : [VARCHAR]) - [student4]
2022-02-21 07:12:33.212 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([college_3_12_0_] : [INTEGER]) - [2]
2022-02-21 07:12:33.212 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([student_1_12_0_] : [INTEGER]) - [4]
2022-02-21 07:12:33.213 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([student_1_12_1_] : [INTEGER]) - [5]
2022-02-21 07:12:33.213 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([college_3_12_1_] : [INTEGER]) - [2]
2022-02-21 07:12:33.213 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([student_2_12_1_] : [VARCHAR]) - [student5]
2022-02-21 07:12:33.213 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([college_3_12_0_] : [INTEGER]) - [2]
2022-02-21 07:12:33.213 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([student_1_12_0_] : [INTEGER]) - [5]
2022-02-21 07:12:33.213 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([student_1_12_1_] : [INTEGER]) - [6]
2022-02-21 07:12:33.213 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([college_3_12_1_] : [INTEGER]) - [2]
2022-02-21 07:12:33.213 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([student_2_12_1_] : [VARCHAR]) - [student6]
2022-02-21 07:12:33.213 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([college_3_12_0_] : [INTEGER]) - [2]
2022-02-21 07:12:33.213 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([student_1_12_0_] : [INTEGER]) - [6]
Hibernate: 
    select
        students0_.college_id_fk as college_3_12_0_,
        students0_.student_id as student_1_12_0_,
        students0_.student_id as student_1_12_1_,
        students0_.college_id_fk as college_3_12_1_,
        students0_.student_name as student_2_12_1_ 
    from
        student students0_ 
    where
        students0_.college_id_fk=?
2022-02-21 07:12:33.214 TRACE 19824 --- [           main] o.h.type.descriptor.sql.BasicBinder      : binding parameter [1] as [INTEGER] - [1]
2022-02-21 07:12:33.449 TRACE 19824 --- [           main] o.s.t.i.TransactionInterceptor           : Completing transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findAll]
college wit students: []
2022-02-21 07:12:33.450 TRACE 19824 --- [           main] o.s.t.i.TransactionInterceptor           : Completing transaction for [com.demo.MyRunner.run]
2022-02-21 07:12:33.450 DEBUG 19824 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction commit
2022-02-21 07:12:33.450 DEBUG 19824 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Committing JPA transaction on EntityManager [SessionImpl(8781131<open>)]
college wit students: [Student [studentId=1, studentName=student1, college=College [collegeId=2, collegeName=college2]], Student [studentId=2, studentName=student2, college=College [collegeId=2, collegeName=college2]], Student [studentId=3, studentName=student3, college=College [collegeId=2, collegeName=college2]], Student [studentId=4, studentName=student4, college=College [collegeId=2, collegeName=college2]], Student [studentId=5, studentName=student5, college=College [collegeId=2, collegeName=college2]], Student [studentId=6, studentName=student6, college=College [collegeId=2, collegeName=college2]]]
college wit students: []
college wit students: []
2022-02-21 07:12:33.919 DEBUG 19824 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Closing JPA EntityManager [SessionImpl(8781131<open>)] after transaction

I am aware that using JOIN FETCH or NamedEntityGraph this can be solved.
However, I am more keen to understand if eager loading also (not just lazy loading) creates n+1 queries.

The eager loading is only taken into account when using `findById` as that uses `EntityManager.find`. The `findAll` uses a query and that bypasses the mapping and it thus won't eagerly load the collection. You can check the difference in the query by doing a `findAll` and `findById` the first will not have a join, the second will. — M. Deinum, Feb 21 '22 at 08:42
@M.Deinum - a related follow up Q. Among Student and College which is the owning entity for the given mappings as in the Question. — samshers, Apr 04 '23 at 13:01
@M.Deinum - i would say Student is the owning side, but few articles quoted it other way so I have to double check. — samshers, Apr 04 '23 at 13:09

score 0 · Accepted Answer · answered Feb 21 '22 at 04:15

0

Eager loading only defines when the related entities are fetched but not how the entities are fetched (i.e. whether they are fetched by a join SQL or select SQL one by one separately).

The default behavior is that it will load the entities that need to be eager fetched by the select SQL one by one. So it can cause N+1 query problem which is demonstrated by your cases.

After you load the college list , the eager loading take effect which immediately load the students for each college by a select SQL one by one.

answered Feb 21 '22 at 04:15

Ken Chan

84,777
26
143
172

so the answer confirms this is the default behavior. And n+1 issue should be addressed even in eager loading case. ++1 – samshers Feb 21 '22 at 06:01
Ken - could you help me with one info related to this Question, among Student and College which is the owning entity for the given mappings as in the Question. – samshers Apr 04 '23 at 13:00
i would say Student is the owning side, but few articles quoted it other way so I have to double check. – samshers Apr 04 '23 at 13:09

Eager loading is triggering n+1 queries?

1 Answers1