default_batch_fetch_size 설정을 지워도 지연로딩이 적용되지 않습니다.

default_batch_fetch_size 설정을 주었을때 쿼리가 나가는것과 default_batch_fetch_size 설정을 주석처리 했을때 쿼리 나가는것을 비교해보고 싶어서 테스트 코드를 아래와 같이 작성해봤습니다.

@Test
@DisplayName("회원 불러와서 getFriends 할때, default_batch_fetch_size 설정 여부에 따른 쿼리 개수 확인")
public void findOne() throws Exception {
    //given
    Member member = Member.builder()
            .name("userA")
            .build();

    Friend friendA = Friend.builder()
            .name("friendA")
            .member(member)
            .build();
    Friend friendB = Friend.builder()
            .name("friendB")
            .member(member)
            .build();
    Friend friendC = Friend.builder()
            .name("friendC")
            .member(member)
            .build();
    Friend friendD = Friend.builder()
            .name("friendD")
            .member(member)
            .build();
    Friend friendE = Friend.builder()
            .name("friendE")
            .member(member)
            .build();

    //when
    memberRepository.save(member);
    friendRepository.save(friendA);
    friendRepository.save(friendB);
    friendRepository.save(friendC);
    friendRepository.save(friendD);
    friendRepository.save(friendE);

    em.flush();
    em.clear();

    //then
    Member findMember = memberRepository.findById(member.getId()); 
    List<Friend> friends = findMember.getFriends();
    for (Friend friend : friends) {
        log.info("getClass: " + friend.getClass()); // 프록시객체를 기대..
        log.info("getClass: " + friend.getName());
    }
}

Member와 Friend는 일대다 관계이며,

Member 클래스에 있는 연관관계 필드는 다음과 같고,

@OneToMany(mappedBy = "member", cascade = CascadeType.ALL, orphanRemoval = true)
private final List<Friend> friends = new ArrayList<>();

Friend 클래스에 있는 연관관계 필드는 다음과 같습니다.

@ManyToOne(fetch = FetchType.LAZY)
@JoinColumn(name="member_id")
private Member member;

테스트코드에서,,

Member findMember = memberRepository.findById(member.getId()); 이 부분에서 member를 조회하는 쿼리가 한번,

log.info("getClass: " + friend.getClass()); 이 부분에서 프록시객체가 찍히고,

log.info("getClass: " + friend.getName()); 이 부분에서 원본 객체를 조회하기 위해 쿼리가 한번 나가서, for문을 돌면서 총 1 + 5 개의 쿼리가 나가기를 기대했습니다.

그리고 default_batch_fetch_size:100 를 글로벌설정에 주게 되면 멤버 조회하는 쿼리 1번, 해당 멤버와 관련된 전체 friend 들을 다 조회하는 쿼리 1번이 나가고 더이상 안나가게 되지 않을까 기대했습니다.

그런데, 글로벌설정을 주기도 전에 1+5개의 조회 쿼리가 나가지가 않고 2개의 조회쿼리만 나가고 끝이 나네요..

default_batch_fetch_size:100 이 옵션을 주석처리도 해보고, 아예 지워도 보고 default_batch_fetch_size:1 로도 값을 변경해보기도 하였지만 결과는 같았습니다.

로그는 다음과 같습니다.

2023-06-09 21:35:26.695  INFO 1106 --- [    Test worker] o.s.t.c.transaction.TransactionContext   : Began transaction (1) for test context [DefaultTestContext@1bdaa23d testClass = MemberRepositoryTest, testInstance = com.example.myvers.member.MemberRepositoryTest@7ae75ba6, testMethod = findOne@MemberRepositoryTest, testException = [null], mergedContextConfiguration = [WebMergedContextConfiguration@79f227a9 testClass = MemberRepositoryTest, locations = '{}', classes = '{class com.example.myvers.MyversApplication}', contextInitializerClasses = '[]', activeProfiles = '{}', propertySourceLocations = '{}', propertySourceProperties = '{org.springframework.boot.test.context.SpringBootTestContextBootstrapper=true}', contextCustomizers = set[org.springframework.boot.test.autoconfigure.actuate.metrics.MetricsExportContextCustomizerFactory$DisableMetricExportContextCustomizer@42f48531, org.springframework.boot.test.autoconfigure.properties.PropertyMappingContextCustomizer@0, org.springframework.boot.test.autoconfigure.web.servlet.WebDriverContextCustomizerFactory$Customizer@ea9b7c6, org.springframework.boot.test.context.filter.ExcludeFilterContextCustomizer@a8e6492, org.springframework.boot.test.json.DuplicateJsonObjectContextCustomizerFactory$DuplicateJsonObjectContextCustomizer@60dce7ea, org.springframework.boot.test.mock.mockito.MockitoContextCustomizer@0, org.springframework.boot.test.web.client.TestRestTemplateContextCustomizer@f73dcd6, org.springframework.boot.test.context.SpringBootTestArgs@1, org.springframework.boot.test.context.SpringBootTestWebEnvironment@43015c69], resourceBasePath = 'src/main/webapp', contextLoader = 'org.springframework.boot.test.context.SpringBootContextLoader', parent = [null]], attributes = map['org.springframework.test.context.web.ServletTestExecutionListener.activateListener' -> true, 'org.springframework.test.context.web.ServletTestExecutionListener.populatedRequestContextHolder' -> true, 'org.springframework.test.context.web.ServletTestExecutionListener.resetRequestContextHolder' -> true, 'org.springframework.test.context.event.ApplicationEventsTestExecutionListener.recordApplicationEvents' -> false]]; transaction manager [org.springframework.orm.jpa.JpaTransactionManager@7b6b466a]; rollback [true]
2023-06-09 21:35:26.749 DEBUG 1106 --- [    Test worker] org.hibernate.SQL                        : 
    call next value for hibernate_sequence
2023-06-09 21:35:26.749  INFO 1106 --- [    Test worker] p6spy                                    : #1686314126749 | took 0ms | statement | connection 16| url jdbc:h2:mem:bd08892f-1de8-4235-819c-08b14b2b1f5b
call next value for hibernate_sequence
call next value for hibernate_sequence;
2023-06-09 21:35:26.750 DEBUG 1106 --- [    Test worker] org.hibernate.SQL                        : 
    call next value for hibernate_sequence
2023-06-09 21:35:26.750  INFO 1106 --- [    Test worker] p6spy                                    : #1686314126750 | took 0ms | statement | connection 16| url jdbc:h2:mem:bd08892f-1de8-4235-819c-08b14b2b1f5b
call next value for hibernate_sequence
call next value for hibernate_sequence;
2023-06-09 21:35:26.750 DEBUG 1106 --- [    Test worker] org.hibernate.SQL                        : 
    call next value for hibernate_sequence
2023-06-09 21:35:26.750  INFO 1106 --- [    Test worker] p6spy                                    : #1686314126750 | took 0ms | statement | connection 16| url jdbc:h2:mem:bd08892f-1de8-4235-819c-08b14b2b1f5b
call next value for hibernate_sequence
call next value for hibernate_sequence;
2023-06-09 21:35:26.750 DEBUG 1106 --- [    Test worker] org.hibernate.SQL                        : 
    call next value for hibernate_sequence
2023-06-09 21:35:26.750  INFO 1106 --- [    Test worker] p6spy                                    : #1686314126750 | took 0ms | statement | connection 16| url jdbc:h2:mem:bd08892f-1de8-4235-819c-08b14b2b1f5b
call next value for hibernate_sequence
call next value for hibernate_sequence;
2023-06-09 21:35:26.750 DEBUG 1106 --- [    Test worker] org.hibernate.SQL                        : 
    call next value for hibernate_sequence
2023-06-09 21:35:26.750  INFO 1106 --- [    Test worker] p6spy                                    : #1686314126750 | took 0ms | statement | connection 16| url jdbc:h2:mem:bd08892f-1de8-4235-819c-08b14b2b1f5b
call next value for hibernate_sequence
call next value for hibernate_sequence;
2023-06-09 21:35:26.750 DEBUG 1106 --- [    Test worker] org.hibernate.SQL                        : 
    call next value for hibernate_sequence
2023-06-09 21:35:26.750  INFO 1106 --- [    Test worker] p6spy                                    : #1686314126750 | took 0ms | statement | connection 16| url jdbc:h2:mem:bd08892f-1de8-4235-819c-08b14b2b1f5b
call next value for hibernate_sequence
call next value for hibernate_sequence;
2023-06-09 21:35:26.751 DEBUG 1106 --- [    Test worker] org.hibernate.SQL                        : 
    insert 
    into
        member
        (created_date, email, grade, login_id, name, password, talk_count, member_id) 
    values
        (?, ?, ?, ?, ?, ?, ?, ?)
2023-06-09 21:35:26.752  INFO 1106 --- [    Test worker] p6spy                                    : #1686314126752 | took 0ms | statement | connection 16| url jdbc:h2:mem:bd08892f-1de8-4235-819c-08b14b2b1f5b
insert into member (created_date, email, grade, login_id, name, password, talk_count, member_id) values (?, ?, ?, ?, ?, ?, ?, ?)
insert into member (created_date, email, grade, login_id, name, password, talk_count, member_id) values (NULL, NULL, NULL, NULL, 'userA', NULL, 1, 33);
2023-06-09 21:35:26.752 DEBUG 1106 --- [    Test worker] org.hibernate.SQL                        : 
    insert 
    into
        friend
        (age, created_date, gender, image_name, mbti, member_id, name, friend_id) 
    values
        (?, ?, ?, ?, ?, ?, ?, ?)
2023-06-09 21:35:26.752  INFO 1106 --- [    Test worker] p6spy                                    : #1686314126752 | took 0ms | statement | connection 16| url jdbc:h2:mem:bd08892f-1de8-4235-819c-08b14b2b1f5b
insert into friend (age, created_date, gender, image_name, mbti, member_id, name, friend_id) values (?, ?, ?, ?, ?, ?, ?, ?)
insert into friend (age, created_date, gender, image_name, mbti, member_id, name, friend_id) values (0, NULL, NULL, NULL, NULL, 33, 'friendA', 34);
2023-06-09 21:35:26.752 DEBUG 1106 --- [    Test worker] org.hibernate.SQL                        : 
    insert 
    into
        friend
        (age, created_date, gender, image_name, mbti, member_id, name, friend_id) 
    values
        (?, ?, ?, ?, ?, ?, ?, ?)
2023-06-09 21:35:26.752  INFO 1106 --- [    Test worker] p6spy                                    : #1686314126752 | took 0ms | statement | connection 16| url jdbc:h2:mem:bd08892f-1de8-4235-819c-08b14b2b1f5b
insert into friend (age, created_date, gender, image_name, mbti, member_id, name, friend_id) values (?, ?, ?, ?, ?, ?, ?, ?)
insert into friend (age, created_date, gender, image_name, mbti, member_id, name, friend_id) values (0, NULL, NULL, NULL, NULL, 33, 'friendB', 35);
2023-06-09 21:35:26.753 DEBUG 1106 --- [    Test worker] org.hibernate.SQL                        : 
    insert 
    into
        friend
        (age, created_date, gender, image_name, mbti, member_id, name, friend_id) 
    values
        (?, ?, ?, ?, ?, ?, ?, ?)
2023-06-09 21:35:26.753  INFO 1106 --- [    Test worker] p6spy                                    : #1686314126753 | took 0ms | statement | connection 16| url jdbc:h2:mem:bd08892f-1de8-4235-819c-08b14b2b1f5b
insert into friend (age, created_date, gender, image_name, mbti, member_id, name, friend_id) values (?, ?, ?, ?, ?, ?, ?, ?)
insert into friend (age, created_date, gender, image_name, mbti, member_id, name, friend_id) values (0, NULL, NULL, NULL, NULL, 33, 'friendC', 36);
2023-06-09 21:35:26.753 DEBUG 1106 --- [    Test worker] org.hibernate.SQL                        : 
    insert 
    into
        friend
        (age, created_date, gender, image_name, mbti, member_id, name, friend_id) 
    values
        (?, ?, ?, ?, ?, ?, ?, ?)
2023-06-09 21:35:26.753  INFO 1106 --- [    Test worker] p6spy                                    : #1686314126753 | took 0ms | statement | connection 16| url jdbc:h2:mem:bd08892f-1de8-4235-819c-08b14b2b1f5b
insert into friend (age, created_date, gender, image_name, mbti, member_id, name, friend_id) values (?, ?, ?, ?, ?, ?, ?, ?)
insert into friend (age, created_date, gender, image_name, mbti, member_id, name, friend_id) values (0, NULL, NULL, NULL, NULL, 33, 'friendD', 37);
2023-06-09 21:35:26.753 DEBUG 1106 --- [    Test worker] org.hibernate.SQL                        : 
    insert 
    into
        friend
        (age, created_date, gender, image_name, mbti, member_id, name, friend_id) 
    values
        (?, ?, ?, ?, ?, ?, ?, ?)
2023-06-09 21:35:26.753  INFO 1106 --- [    Test worker] p6spy                                    : #1686314126753 | took 0ms | statement | connection 16| url jdbc:h2:mem:bd08892f-1de8-4235-819c-08b14b2b1f5b
insert into friend (age, created_date, gender, image_name, mbti, member_id, name, friend_id) values (?, ?, ?, ?, ?, ?, ?, ?)
insert into friend (age, created_date, gender, image_name, mbti, member_id, name, friend_id) values (0, NULL, NULL, NULL, NULL, 33, 'friendE', 38);
2023-06-09 21:35:26.759 DEBUG 1106 --- [    Test worker] org.hibernate.SQL                        : 
    select
        member0_.member_id as member_i1_1_0_,
        member0_.created_date as created_2_1_0_,
        member0_.email as email3_1_0_,
        member0_.grade as grade4_1_0_,
        member0_.login_id as login_id5_1_0_,
        member0_.name as name6_1_0_,
        member0_.password as password7_1_0_,
        member0_.talk_count as talk_cou8_1_0_ 
    from
        member member0_ 
    where
        member0_.member_id=?
2023-06-09 21:35:26.760  INFO 1106 --- [    Test worker] p6spy                                    : #1686314126760 | took 0ms | statement | connection 16| url jdbc:h2:mem:bd08892f-1de8-4235-819c-08b14b2b1f5b
select member0_.member_id as member_i1_1_0_, member0_.created_date as created_2_1_0_, member0_.email as email3_1_0_, member0_.grade as grade4_1_0_, member0_.login_id as login_id5_1_0_, member0_.name as name6_1_0_, member0_.password as password7_1_0_, member0_.talk_count as talk_cou8_1_0_ from member member0_ where member0_.member_id=?
select member0_.member_id as member_i1_1_0_, member0_.created_date as created_2_1_0_, member0_.email as email3_1_0_, member0_.grade as grade4_1_0_, member0_.login_id as login_id5_1_0_, member0_.name as name6_1_0_, member0_.password as password7_1_0_, member0_.talk_count as talk_cou8_1_0_ from member member0_ where member0_.member_id=33;
2023-06-09 21:35:26.765 DEBUG 1106 --- [    Test worker] org.hibernate.SQL                        : 
    select
        friends0_.member_id as member_i8_0_0_,
        friends0_.friend_id as friend_i1_0_0_,
        friends0_.friend_id as friend_i1_0_1_,
        friends0_.age as age2_0_1_,
        friends0_.created_date as created_3_0_1_,
        friends0_.gender as gender4_0_1_,
        friends0_.image_name as image_na5_0_1_,
        friends0_.mbti as mbti6_0_1_,
        friends0_.member_id as member_i8_0_1_,
        friends0_.name as name7_0_1_ 
    from
        friend friends0_ 
    where
        friends0_.member_id=?
2023-06-09 21:35:26.766  INFO 1106 --- [    Test worker] p6spy                                    : #1686314126766 | took 0ms | statement | connection 16| url jdbc:h2:mem:bd08892f-1de8-4235-819c-08b14b2b1f5b
select friends0_.member_id as member_i8_0_0_, friends0_.friend_id as friend_i1_0_0_, friends0_.friend_id as friend_i1_0_1_, friends0_.age as age2_0_1_, friends0_.created_date as created_3_0_1_, friends0_.gender as gender4_0_1_, friends0_.image_name as image_na5_0_1_, friends0_.mbti as mbti6_0_1_, friends0_.member_id as member_i8_0_1_, friends0_.name as name7_0_1_ from friend friends0_ where friends0_.member_id=?
select friends0_.member_id as member_i8_0_0_, friends0_.friend_id as friend_i1_0_0_, friends0_.friend_id as friend_i1_0_1_, friends0_.age as age2_0_1_, friends0_.created_date as created_3_0_1_, friends0_.gender as gender4_0_1_, friends0_.image_name as image_na5_0_1_, friends0_.mbti as mbti6_0_1_, friends0_.member_id as member_i8_0_1_, friends0_.name as name7_0_1_ from friend friends0_ where friends0_.member_id=33;
2023-06-09 21:35:26.768  INFO 1106 --- [    Test worker] c.e.myvers.member.MemberRepositoryTest   : getClass: class com.example.myvers.domain.Friend
2023-06-09 21:35:26.768  INFO 1106 --- [    Test worker] c.e.myvers.member.MemberRepositoryTest   : getClass: friendA
2023-06-09 21:35:26.768  INFO 1106 --- [    Test worker] c.e.myvers.member.MemberRepositoryTest   : getClass: class com.example.myvers.domain.Friend
2023-06-09 21:35:26.768  INFO 1106 --- [    Test worker] c.e.myvers.member.MemberRepositoryTest   : getClass: friendB
2023-06-09 21:35:26.768  INFO 1106 --- [    Test worker] c.e.myvers.member.MemberRepositoryTest   : getClass: class com.example.myvers.domain.Friend
2023-06-09 21:35:26.768  INFO 1106 --- [    Test worker] c.e.myvers.member.MemberRepositoryTest   : getClass: friendC
2023-06-09 21:35:26.768  INFO 1106 --- [    Test worker] c.e.myvers.member.MemberRepositoryTest   : getClass: class com.example.myvers.domain.Friend
2023-06-09 21:35:26.768  INFO 1106 --- [    Test worker] c.e.myvers.member.MemberRepositoryTest   : getClass: friendD
2023-06-09 21:35:26.768  INFO 1106 --- [    Test worker] c.e.myvers.member.MemberRepositoryTest   : getClass: class com.example.myvers.domain.Friend
2023-06-09 21:35:26.768  INFO 1106 --- [    Test worker] c.e.myvers.member.MemberRepositoryTest   : getClass: friendE
2023-06-09 21:35:26.771  INFO 1106 --- [    Test worker] p6spy                                    : #1686314126771 | took 0ms | rollback | connection 16| url jdbc:h2:mem:bd08892f-1de8-4235-819c-08b14b2b1f5b

;
2023-06-09 21:35:26.772  INFO 1106 --- [    Test worker] o.s.t.c.transaction.TransactionContext   : Rolled back transaction for test: [DefaultTestContext@1bdaa23d testClass = MemberRepositoryTest, testInstance = com.example.myvers.member.MemberRepositoryTest@7ae75ba6, testMethod = findOne@MemberRepositoryTest, testException = [null], mergedContextConfiguration = [WebMergedContextConfiguration@79f227a9 testClass = MemberRepositoryTest, locations = '{}', classes = '{class com.example.myvers.MyversApplication}', contextInitializerClasses = '[]', activeProfiles = '{}', propertySourceLocations = '{}', propertySourceProperties = '{org.springframework.boot.test.context.SpringBootTestContextBootstrapper=true}', contextCustomizers = set[org.springframework.boot.test.autoconfigure.actuate.metrics.MetricsExportContextCustomizerFactory$DisableMetricExportContextCustomizer@42f48531, org.springframework.boot.test.autoconfigure.properties.PropertyMappingContextCustomizer@0, org.springframework.boot.test.autoconfigure.web.servlet.WebDriverContextCustomizerFactory$Customizer@ea9b7c6, org.springframework.boot.test.context.filter.ExcludeFilterContextCustomizer@a8e6492, org.springframework.boot.test.json.DuplicateJsonObjectContextCustomizerFactory$DuplicateJsonObjectContextCustomizer@60dce7ea, org.springframework.boot.test.mock.mockito.MockitoContextCustomizer@0, org.springframework.boot.test.web.client.TestRestTemplateContextCustomizer@f73dcd6, org.springframework.boot.test.context.SpringBootTestArgs@1, org.springframework.boot.test.context.SpringBootTestWebEnvironment@43015c69], resourceBasePath = 'src/main/webapp', contextLoader = 'org.springframework.boot.test.context.SpringBootContextLoader', parent = [null]], attributes = map['org.springframework.test.context.web.ServletTestExecutionListener.activateListener' -> true, 'org.springframework.test.context.web.ServletTestExecutionListener.populatedRequestContextHolder' -> true, 'org.springframework.test.context.web.ServletTestExecutionListener.resetRequestContextHolder' -> true, 'org.springframework.test.context.event.ApplicationEventsTestExecutionListener.recordApplicationEvents' -> false]]

결론: default_batch_fetch_size 설정을 지워도 지연로딩이 적용되지 않는 이유를 알고싶습니다. 감사합니다.