'Eager loading is triggering n+1 queries?

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.



Solution 1:[1]

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.

Sources

This article follows the attribution requirements of Stack Overflow and is licensed under CC BY-SA 3.0.

Source: Stack Overflow

Solution Source
Solution 1 Ken Chan