[Spring] 스프링 컨텍스트 로딩 시간을 포함한 전체 테스트 코드 수행시간 측정하기

우리는 스프링에서 테스트 코드 수행시간을 측정하기 위해 일반적으로 IDE의 도움을 받는다.

이미 많은 사람들이 사용하고 있는 JetBrains의 IntelliJ에서는 테스트의 수행시간을 화면 상에 표시해준다.

 

하지만, 이와 같은 방법은 몇 가지 한계점이 있다.

 

바로 @SpringBootTest 혹은 @DataJpaTest 등에서 테스트 컨텍스트를 로딩하는 시간이 수행 시간에서 제외된다는 것이다.

 

사실, 테스트 자체를 수행하는 시간은 1초 이상을 넘기는 일이 잘 없으며 테스트 컨텍스트 로딩 시간이 우리가 체감하는 테스트 수행 시간의 대부분을 차지한다.

 

이 시간을 줄이기 위해선 우선 해당 시간을 정확히 측정해볼 필요가 있다.

 

컨텍스트 로딩 시간을 포함한 테스트 코드 전체 수행시간을 구하기 위해선 스프링 프레임워크에 존재하는 TestExecutionListener 인터페이스를 구현해주면 된다.

 

TestExecutionListener는 다음과 같이 생겼다.

public interface TestExecutionListener {

    /**
     * Pre-processes a test class <em>before</em> execution of all tests within
     * the class.
     * <p>This method should be called immediately before framework-specific
     * <em>before class</em> lifecycle callbacks.
     * <p>The default implementation is <em>empty</em>. Can be overridden by
     * concrete classes as necessary.
     * @param testContext the test context for the test; never {@code null}
     * @throws Exception allows any exception to propagate
     * @since 3.0
     */
    default void beforeTestClass(TestContext testContext) throws Exception {
    }

    /**
     * Prepares the {@link Object test instance} of the supplied
     * {@link TestContext test context}, for example by injecting dependencies.
     * <p>This method should be called immediately after instantiation of the test
     * instance but prior to any framework-specific lifecycle callbacks.
     * <p>The default implementation is <em>empty</em>. Can be overridden by
     * concrete classes as necessary.
     * @param testContext the test context for the test; never {@code null}
     * @throws Exception allows any exception to propagate
     */
    default void prepareTestInstance(TestContext testContext) throws Exception {
    }

    /**
     * Pre-processes a test <em>before</em> execution of <em>before</em>
     * lifecycle callbacks of the underlying test framework &mdash; for example,
     * by setting up test fixtures.
     * <p>This method <strong>must</strong> be called immediately prior to
     * framework-specific <em>before</em> lifecycle callbacks. For historical
     * reasons, this method is named {@code beforeTestMethod}. Since the
     * introduction of {@link #beforeTestExecution}, a more suitable name for
     * this method might be something like {@code beforeTestSetUp} or
     * {@code beforeEach}; however, it is unfortunately impossible to rename
     * this method due to backward compatibility concerns.
     * <p>The default implementation is <em>empty</em>. Can be overridden by
     * concrete classes as necessary.
     * @param testContext the test context in which the test method will be
     * executed; never {@code null}
     * @throws Exception allows any exception to propagate
     * @see #afterTestMethod
     * @see #beforeTestExecution
     * @see #afterTestExecution
     */
    default void beforeTestMethod(TestContext testContext) throws Exception {
    }

    /**
     * Pre-processes a test <em>immediately before</em> execution of the
     * {@link java.lang.reflect.Method test method} in the supplied
     * {@link TestContext test context} &mdash; for example, for timing
     * or logging purposes.
     * <p>This method <strong>must</strong> be called after framework-specific
     * <em>before</em> lifecycle callbacks.
     * <p>The default implementation is <em>empty</em>. Can be overridden by
     * concrete classes as necessary.
     * @param testContext the test context in which the test method will be
     * executed; never {@code null}
     * @throws Exception allows any exception to propagate
     * @since 5.0
     * @see #beforeTestMethod
     * @see #afterTestMethod
     * @see #afterTestExecution
     */
    default void beforeTestExecution(TestContext testContext) throws Exception {
    }

    /**
     * Post-processes a test <em>immediately after</em> execution of the
     * {@link java.lang.reflect.Method test method} in the supplied
     * {@link TestContext test context} &mdash; for example, for timing
     * or logging purposes.
     * <p>This method <strong>must</strong> be called before framework-specific
     * <em>after</em> lifecycle callbacks.
     * <p>The default implementation is <em>empty</em>. Can be overridden by
     * concrete classes as necessary.
     * @param testContext the test context in which the test method will be
     * executed; never {@code null}
     * @throws Exception allows any exception to propagate
     * @since 5.0
     * @see #beforeTestMethod
     * @see #afterTestMethod
     * @see #beforeTestExecution
     */
    default void afterTestExecution(TestContext testContext) throws Exception {
    }

    /**
     * Post-processes a test <em>after</em> execution of <em>after</em>
     * lifecycle callbacks of the underlying test framework &mdash; for example,
     * by tearing down test fixtures.
     * <p>This method <strong>must</strong> be called immediately after
     * framework-specific <em>after</em> lifecycle callbacks. For historical
     * reasons, this method is named {@code afterTestMethod}. Since the
     * introduction of {@link #afterTestExecution}, a more suitable name for
     * this method might be something like {@code afterTestTearDown} or
     * {@code afterEach}; however, it is unfortunately impossible to rename
     * this method due to backward compatibility concerns.
     * <p>The default implementation is <em>empty</em>. Can be overridden by
     * concrete classes as necessary.
     * @param testContext the test context in which the test method was
     * executed; never {@code null}
     * @throws Exception allows any exception to propagate
     * @see #beforeTestMethod
     * @see #beforeTestExecution
     * @see #afterTestExecution
     */
    default void afterTestMethod(TestContext testContext) throws Exception {
    }

    /**
     * Post-processes a test class <em>after</em> execution of all tests within
     * the class.
     * <p>This method should be called immediately after framework-specific
     * <em>after class</em> lifecycle callbacks.
     * <p>The default implementation is <em>empty</em>. Can be overridden by
     * concrete classes as necessary.
     * @param testContext the test context for the test; never {@code null}
     * @throws Exception allows any exception to propagate
     * @since 3.0
     */
    default void afterTestClass(TestContext testContext) throws Exception {
    }

}

관심이 있다면 하나씩 읽어봐도 좋다. 우리가 쓸 것은 afterTestClass()와 beforeTestClass()다.

 

해당 메서드를 오버라이딩하면 클래스 기준으로 테스트 시작 전과 후에 해당 메서드를 실행시켜준다.

import org.jetbrains.annotations.NotNull;
import org.springframework.test.context.TestContext;
import org.springframework.test.context.TestExecutionListener;

public class TestExecutionTimeListener implements TestExecutionListener {

    private Long startTime;

    @Override
    public void beforeTestClass(@NotNull TestContext testContext) {
        startTime = System.currentTimeMillis();
    }

    @Override
    public void afterTestClass(@NotNull TestContext testContext) {
        long endTime = System.currentTimeMillis();
        long executionTime = endTime - startTime;
        System.out.println("컨텍스트 로딩을 포함한 전체 테스트 실행 시간: " + executionTime + "ms");

    }

}

위 처럼 테스트 클래스 시작 전과 후에 시간 측정 코드를 적어주고, 클래스 단위의 테스트를 돌려보자.

위 처럼, IDE에 표기된 순수 테스트코드 수행 시간은 713ms지만 컨텍스트 로딩을 포함한 전체 테스트 실행 시간은 10513ms가 된다.

 

이를 통해서 컨텍스트 로딩 시간은 (10513ms - 713ms) 9800ms인 것을 알 수 있다. (배보다 배꼽이 더 크다)

 

물론, 돌려봐야하는 테스트 클래스가 수백개인데 이걸 하나씩 돌려보면서 더하고 있을 순 없다.

 

또한, 하나씩 돌리면 컨텍스트 캐싱이 안되니깐 진짜 찐 수행시간을 구할 수 없기도 하다.

 

테스트 패키지에 포함된 전체 테스트 코드의 수행 시간을 구하기 위해서 다음 코드를 추가해주자.

import org.jetbrains.annotations.NotNull;
import org.springframework.test.context.TestContext;
import org.springframework.test.context.TestExecutionListener;

public class TestExecutionTimeListener implements TestExecutionListener {

    private Long startTime;
    private static Long totalTime = 0L;

    @Override
    public void beforeTestClass(@NotNull TestContext testContext) {
        startTime = System.currentTimeMillis();
    }

    @Override
    public void afterTestClass(@NotNull TestContext testContext) {
        long endTime = System.currentTimeMillis();
        long executionTime = endTime - startTime;
        System.out.println("컨텍스트 로딩을 포함한 전체 테스트 실행 시간: " + executionTime + "ms");

        totalTime += executionTime;
        System.out.println("지금까지 걸린 시간: " + totalTime + "ms");
    }

}

totalTime 값은 유지되어야하므로, static으로 선언하고 현재 테스트 클래스의 수행시간을 toatlTime에 더해줘서 출력해주자.

 

 

총 339개 테스트에 대해서 IDE에 표시된 순수 테스트코드 수행시간은 20670ms(20초), 컨텍스트 로딩 시간을 포함한 전체 테스트코드 수행 시간은 48372ms(48초)가 걸린 것을 확인할 수 있다.