테스트 속도 개선 및 리팩토링!

테스트 너무 느려

요즘 카페서비스는 좀 더 스마트한 테스트 환경을 위해 Testcontainer를 사용하고 있다.

 

그런데, Testcontainer의 유일한 단점.
테스트 실행시 컨테이너가 실행 되는데, 이 때문에 테스트에 걸리는 시간이 늘어났다.

 

꼴랑 167개 테스트 돌리는데 58초.. 거의 1분이 걸린다.

테스트 속도를 개선 할 수는 없을까?

개선 1: Application Context

스프링 테스트 프레임워크에는 컨텍스트 캐싱 이라는 기능이 있다.

한 번 로드 된 애플리케이션 컨택스트를 캐시에 저장하고,
동일한 설정과 환경을 가진 후속 테스트에서 해당 캐시 된 컨택스트를 재사용 하는 기능이다.

 

근데 저 말을 잘 생각해보면,

후속 테스트에서 이전 테스트와 다른 설정과 환경을 갖는 다면 Application Context가 새롭게 로드 된다는 말이다.

 

Application Context 는 Bean들을 초기화하고, 의존성도 처리하는 등 뭐 이것저것 많이하는 친구인데,
테스트 진행 시 Application Context가 많이 로드 된다면, 로드 되는 시간 만큼 테스트 시간은 늘어날 수 밖에 없다.

 

이 스프링 로고가 뜰 때 마다, 새로운 Application Context가 로드 된다고 보면되는데,
전체 테스트를 돌렸을 때, 총 11번의 Application Context 생성이 일어났다.

 

Applcation Context를 사용하는 테스트가
AcceptanceTest, ServiceTest, RepositoryTest 이렇게 세 종류가 있는데,

각각 Application Context 가 한 번씩만 생성되도록 목표를 잡고 작업을 시작했다.

Application Context 생성 이유

컨텍스트 캐싱 관련 공식문서에는 캐시 키를 생성하는 구성요소들에 대해 알려주고 있는데,
그 중에 눈에 들어온게 있다.

contextCustomizers (from ContextCustomizerFactory) – this includes @DynamicPropertySource methods as well as various features from Spring Boot’s testing support such as @MockBean and @SpyBean.

@MockBean 또는 @SpyBean 사용 시 contextCustomizers요소가 변경 되므로 새로운 캐시키가 생성되고,
이전의 Application Context를 재사용 할 수 없기에, 새롭게 생성된다.

 

실제로 Application Context가 새롭게 생성되는 테스트 클래스를 확인해보니,

@MockBean 또는 @SpyBean을 사용하고 있었다.

 

모킹을 한 큐에

class LikedCafeControllerTest extends BaseControllerTest {  

    @Autowired  
    private MemberRepository memberRepository;  
    @Autowired  
    private CafeRepository cafeRepository;  
    @MockBean  
    private JwtTokenProvider jwtTokenProvider;

    ...

}

 

이런 식으로 각각의 테스트 클래스에서 모킹했던 것을 추상클래스인 BaseControllerTest에 모아서 한번에 선언해주고,

각각의 테스트에서 상속받아 사용하게끔 변경하였다.

 

@SpringBootTest(webEnvironment = WebEnvironment.RANDOM_PORT)  
@ExtendWith(RestDocumentationExtension.class)  
public abstract class BaseControllerTest extends BaseTest {  

    @LocalServerPort  
    private int port;  

    @SpyBean  
    protected S3Client s3Client;  
    @SpyBean  
    protected JwtTokenProvider jwtTokenProvider;

    ...

}

부모클래스에서 @MockBean을 사용 하게 되면 다른 클래스에서는 원치 않는 모킹을 처리해야 할 것 같아
@MockBean 으로 모킹되던 것들을 모두 @SpyBean으로 변경해주었다.

 

@SpyBean의 경우 모킹을 한 메서드는 모킹한대로 동작하지만,

그렇지 않은 메서드는 정상적으로 동작하기에, 번거로운 일을 줄일 수 있었다.

 

이 작업을 어쩔 수 없이 각각의 테스트 클래스에서 모킹을 해야되는 경우를 제외하고는
AcceptanceTest, ServiceTest, RepositoryTest에 모두 적용하였다.

 

이로 인해 Application Context가 새로 생성되는 횟수가 11회에서 4회로 줄었고,
테스트 시간도 10초 가량 줄어들었다.

 

 

개선 2: log option + 리팩토링

Application Context를 작업 하면서, 테스트를 백여차례 정도 돌리며 깨달은게 두 가지 있다.

우리 인수테스트.. 참.. 꼴보기 싫다...

일단, RestDocs로 자동문서화를 하다보니, 인수테스트코드 자체가 좀 지저분해 보인다.

 

@Test  
@DisplayName("카페 전체 조회")  
void findAll() {  
    //given  
    saveCafe();  
    saveCafe();  

    //when, then  
    given(spec).log().all()  
            .contentType(JSON)  
            .filter(document("어드민 API/카페 전체 조회하기",  
                    responseFields(  
                            fieldWithPath("[].id").description("카페 ID"),  
                            fieldWithPath("[].name").description("카페 이름"),  
                            fieldWithPath("[].address").description("카페 도로명 주소"),  
                            fieldWithPath("[].isLiked").description("좋아요 누른 여부"),  
                            fieldWithPath("[].likeCount").description("좋아요 숫자"),  
                            fieldWithPath("[].images.[]").description("이미지 URL 배열"),  
                            fieldWithPath("[].detail.mapUrl").description("네이버 지도 URL"),  
                            fieldWithPath("[].detail.description").description("상세 설명"),  
                            fieldWithPath("[].detail.phone").description("전화번호"),  
                            fieldWithPath("[].detail.openingHours.[].day").description("요일"),  
                            fieldWithPath("[].detail.openingHours.[].open").description("영업 시작 시각"),  
                            fieldWithPath("[].detail.openingHours.[].close").description("영업 종료 시각"),  
                            fieldWithPath("[].detail.openingHours.[].opened").description("해당 요일 영업 여부"))  
            ))            .when()  
            .get("/admin/cafes")  
            .then()  
            .statusCode(is(HttpStatus.OK.value()));  
}

아....
그리고 테스트 코드만 이렇게 모아 놓고 볼 기회가 없어서 몰랐는데,
각각의 팀원들이 작성하다 보니, 테스트코드가 뭔가 좀 일관성이 없다...

특히 검증하는 부분이 특히나 그런데 위의 코드는 then()으로 바로 검증을 하고 있는데,

 

@Test  
@DisplayName("사용자가 좋아요 한 카페들의 대표 이미지들을 조회한다.")  
void getLikedCafes() {  
    //given  
    final Cafe savedCafe1 = cafeRepository.save(Fixture.getCafe("오션의 귀여운 카페", "인천 오션동", 5));  
    final Cafe savedCafe2 = cafeRepository.save(Fixture.getCafe("오션의 귀여운 카페", "인천 오션동", 5));  
    final Member member = new Member("1234", "오션", "오션.img");  
    member.updateLikedCafesBy(savedCafe1, true);  
    member.updateLikedCafesBy(savedCafe2, true);  
    memberRepository.save(member);  

    //when  
    final Response response = given(spec).log().all()  
            .filter(document("likedCafe/좋아요 카페 대표 이미지 목록 조회",  
                    queryParameters(parameterWithName("page").description("좋아요 목록 페이지 번호")),  
                    pathParameters(parameterWithName("memberId").description("멤버 ID")),  
                    responseFields(fieldWithPath("[].cafeId").description("카페 ID"),  
                            fieldWithPath("[].imageUrl").description("카페 대표 사진"))))  
            .when()  
            .get("/members/{memberId}/liked-cafes?page=1", member.getId());  

    //then  
    assertAll(  
            () -> assertThat(response.jsonPath().getLong("[0].cafeId")).isEqualTo(savedCafe2.getId()),  
            () -> assertThat(response.jsonPath().getLong("[1].cafeId")).isEqualTo(savedCafe1.getId())  
    );}

다른 테스트 클래스를 확인해보면, Response를 뽑아서 AssertJ로 검증을 한다.

 

문서화도 그렇고, 검증도 그렇고.. 아... 참.. 보기가 싫다..

 

출력 하는데도 시간이 좀 걸리는 거 같은데..?

쿼리문과 Request, Response 로그를 출력하는데도 시간이 좀 걸리는 것 같은 기분이다.
혹시나 싶어서 쿼리문 출력 옵션을 false로 설정하고 테스트를 돌려보니 조금 줄어 드는 것 같다.

 

쿼리문 출력은 yml을 수정해주면 된다지만,
given().log().all() 같이 코드로 로그를 찍는거는 매번 변경을 해주기가 쉽지않다.

 

두 개의 출력은 하나의 옵션으로 통제하고 싶다.

즐거운 반복 작업

우선은 yml 파일에 옵션을 하나 끼워 넣었다.

 

log: &log-option false

spring:
  jpa:  
    show-sql: *log-option
        properties:  
            hibernate:  
                default_batch_fetch_size: 1000  
                format_sql: *log-option

 

log 라는 값에 false를 매핑 해주고, log-option 이라는 변수를 걸어주었다.
그리고 그 변수를 쿼리 출력 옵션들에도 설정했다.

 

@SpringBootTest(webEnvironment = WebEnvironment.RANDOM_PORT)  
@ExtendWith(RestDocumentationExtension.class)  
public abstract class BaseControllerTest extends BaseTest {  

    ...

    @Value("${log}")  
    private boolean showLog;  

    protected RequestSpecification spec;  

    ...

    protected RequestSpecification customGiven() {  
        final RequestSpecification customGiven = given();  
        if (showLog) {  
            return customGiven.log().all();  
        }        
        return customGiven;  
    }  

    protected RequestSpecification customGivenWithDocs(Filter document) {  
        final RequestSpecification customGiven = given(spec).filter(document);  
        if (showLog) {  
            return customGiven.log().all();  
        }        
        return customGiven;  
    }
}

 

그리고 아까 보았던 BaseControllerTest에 @Value어노테이션을 이용해 showLog 필드에 yml에 있는 log의 값을 매핑했다.

그리고 그 값에 따라 log().all()을 사용하는 customGiven을 만들었다.

문서화가 필요한 경우에는 customGivenWithDocs() 를 사용할 수 있게 만들었다.

그리고 각각의 테스트에서 문서화에 사용 되는 Filter들을 별도의 클래스로 분리하였다.

 

public class AdminDocuments {  
    public static RestDocumentationFilter adminAllCafesFindDocument() {  
        return document("어드민 API/카페 전체 조회하기",  
                responseFields(  
                        fieldWithPath("[].id").description("카페 ID"),  
                        fieldWithPath("[].name").description("카페 이름"),  
                        fieldWithPath("[].address").description("카페 도로명 주소"),  
                        fieldWithPath("[].isLiked").description("좋아요 누른 여부"),  
                        fieldWithPath("[].likeCount").description("좋아요 숫자"),  
                        fieldWithPath("[].images.[]").description("이미지 URL 배열"),  
                        fieldWithPath("[].detail.mapUrl").description("네이버 지도 URL"),  
                        fieldWithPath("[].detail.description").description("상세 설명"),  
                        fieldWithPath("[].detail.phone").description("전화번호"),  
                        fieldWithPath("[].detail.openingHours.[].day").description("요일"),  
                        fieldWithPath("[].detail.openingHours.[].open").description("영업 시작 시각"),  
                        fieldWithPath("[].detail.openingHours.[].close").description("영업 종료 시각"),  
                        fieldWithPath("[].detail.openingHours.[].opened").description("해당 요일 영업 여부")));  
    }

    ...

}

이 작업들을 모든 인수테스트에 적용해주면 된다...ㅎㅎ
이런 반복작업은 신기하게도 지루하지만 즐겁다.

 

그 결과 이랬던 코드가

 

이렇게 변했다.

ㄹㅇ 마음이 편-안해진다.

검증 방식도 전부 통일하고,

여러 요소들을 검증하는 경우에도 assertAll 과 assertSoftly가 뒤섞여 사용되었는데, 이것도 assertSoftly로 통일해주었다.

뭐 그런거 까지 라고 생각할 수 있지만, 취향이다 취향. 존중해줬으면 한다.

모든 작업을 마치고, log 옵션을 끈 뒤, 전체 테스트를 돌려봤다.

어머. 세상 즐겁다.

한번 운좋게 빨리 끝난거 아닌가 싶어서 10번씩 돌려봤다.

 

Try Count	개선 전	Context Load 개선	Context Load + Log Option
1	58 Sec	46 Sec	42 Sec
2	57 Sec	48 Sec	43 Sec
3	58 Sec	48 Sec	44 Sec
4	56 Sec	47 Sec	44 Sec
5	56 Sec	49 Sec	43 Sec
6	57 Sec	48 Sec	44 Sec
7	55 Sec	48 Sec	44 Sec
8	57 Sec	49 Sec	43 Sec
9	57 Sec	46 Sec	43 Sec
10	56 Sec	46 Sec	43 Sec
Average	56.7 Sec	47.5 Sec	43.3 Sec

 

10번씩 돌렸을 때 평균 56.7초 걸리던 테스트가 43.3초로 23% 개선되었다.
와~

근데... 사실은...

ㅎ.. Application Context 쪽 개선하다가 알게된건데.. ㅎㅎ
테스트가.. 느린게 아니다..

내 맥북이 느리다...

 

작업하는 도중에 팀원 중 한명이 ??? 58초가 걸린다고???? 나 25초 컷인데??? 라더라.
ㅋㅋㅋㅋㅋㅋㅋㅋㅋㅋㅋㅋㅋㅋ

 

그래서 일주일쯤 전에 한번 접었던 작업이다.

근데 내내 머릿속에 멤돌더라.

추석 연휴라 시간도 많은데 해보지 뭐 하는 마음으로 작업했다.

테스트 속도 개선작업이 유의미 했는지는 모르겠지만,
덕분에 컨텍스트 캐싱도 알게되고, 테스트 코드도 싸악 리팩토링 할 수 있었어서 무의미한 시간은 아니었던 것 같다.

 

....난 행복해... ㅎ.. ㅎ