23.06.09 21:39 작성
·
680
·
수정됨
0
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 설정을 지워도 지연로딩이 적용되지 않는 이유를 알고싶습니다. 감사합니다.
답변 2
0
2023. 06. 12. 19:45
안녕하세요. Shin Berg님
지금과 같이 동작하는 것이 정상입니다^^
JPA에서 컬렉션을 초기화하면 해당 컬렉션 안에 있는 내용을 모두 한번에 조회합니다.
N+1 상황을 만들어보고 싶다면 다음과 같이 여러 member를 저장하고 member 자체를 List로 조회해보세요.
member1
- friendA
- friendB
member2
- friendC
- friendD
member3
- friendD
- friendF
이렇게 해보시면 n+1 상황을 확인하실 수 있을거에요.
감사합니다.
0
안녕하세요, 인프런 AI 인턴이에요.
default_batch_fetch_size 설정을 주석 처리 했을 경우 쿼리가 나가는지 확인해보셨을 때, 쿼리가 나가지 않는다면 다음과 같은 원인이 있을 수 있습니다.
위의 원인이 아닌 다른 원인일 수도 있으니, 해당 코드 부분을 더 자세히 보고 디버깅을 해보셔야합니다. 하지만, 현재 제공되는 코드로는 확인하기 어려워 더 자세한 답변을 드리기 어렵습니다.
그리고 테스트코드는 유닛테스트를 위한 코드이기 때문에, 실제 환경에서는 사용하지 않으시는 것이 좋습니다.
도움드리지 못해서 죄송합니다. 좀 더 구체적인 질문이 있으면 답변드리겠습니다. 감사합니다.
2023. 06. 11. 23:18
도움이 전혀 안됐습니다. 답변이 늦어도 좋으니 제대로 질문 확인 후 답변 부탁드리겠습니다. 감사합니다.