상황
내가 만든 로직의 성능을 테스트하고자 연속적으로 호출하는 테스트 코드를 작성해봤다.
해당 로직에서는 레디스에 접근하는 경우가 있었기 때문에, Mock 객체를 활용해 실제 레디스에 접근하는 시간은 제외한 자바 코드의 성능만을 테스트 하고자 했다.
예시 코드는 아래와 같다.
@MarsSpringBootTest
@Slf4j
class ServiceTest {
private static final int CALL_STANDARD = 10_000_000;
@Autowired
private TestService testService;
@Mock
private Repository repository;
@Test
void run() {
when(repository.find(xxx)).thenReturn(Optional.ofNullable(yyy));
doNothing().when(repository).save(zzz);
StopWatch stopWatch = new StopWatch();
stopWatch.start();
log.info("메서드 호출 시작, 현재 시간 : {}", LocalDateTime.now());
int count = 0;
while (count++ < CALL_STANDARD) {
if (count != 0 && count % (CALL_STANDARD / 10) == 0) {
log.info("{}번째 메서드 호출 중, 현재 시간 : {}", count, LocalDateTime.now());
}
testService.callMethod(); // 성능을 테스트 하고자 하는 로직
}
stopWatch.stop();
log.info("{}번 호출에 소요된 시간 : {}ms, 약 {}초", CALL_STANDARD, stopWatch.getTotalTimeMillis(), stopWatch.getTotalTimeMillis() / 1_000);
}
.. // 기타 생략
}
testService의 callMethod()의 성능을 테스트하는 것이 목표이고, CALL_STANDARD에 수를 변경하며 로직에 걸리는 시간을 얻을 수 있었다.
허나 이 테스트 코드에서 CALL_STANDARD를 천만번 이상으로 설정하자 700만번 근처에서 더 이상 로그가 남지 않았으며 오랜 시간 뒤에 OOM이 발생했다.
Async Profiler를 이용한 CPU, Heap Memory 모니터링
인텔리제이에 내장된 Async Profiler를 이용해 해당 테스트 코드를 모니터링한 결과이다.
총 700만번의 메서드 호출을 한 결과인데 마지막에는 Heap Memory가 4000MB까지 치솟는 것을 확인할 수 있었다.
Thread에 대한 정보는 아래와 같았다.
하지만 해당 플러그인으로는 더욱 디테일한 결과를 분석하기 어려웠다.
Visual VM을 이용한 Heap Dump
Visual VM을 설치하여 모니터링한 결과이다.
CPU 및 Heap Memory의 그래프는 Async Profiler에서와 유사한 듯 하다.
Summary는 간단하게 Heap Dump한 결과에 대해서 알려주는데 우측 하단에 보이듯 배열 및 컬렉션이 많은 힙 메모리를 할당받고 있음을 알 수 있다.
스레드 정보에서는 크게 건질만한 정보가 없다.
가장 중요한 Heap Dump에서 어떤 자료구조가 메모리를 많이 차지하는지 알 수 있는 도표이다.
처음에는 배열이나 컬렉션에 할당된 메모리가 GC에 의해 제대로 회수되지 않거나, 지연되는 상황일 거라 예상했다.
그러나 코드 어디에서도 순환 참조 및 static 메모리 사용 등은 없었고, 심지어 모니터링 결과에서도 알 수 있듯 GC는 그다지 활성화된 적도 없다.
Eclipse Memory Analyzer를 사용한 Dominator tree 분석
앞서 사용한 툴은 구체적으로 어떤 객체로 인해서 OOM이 발생하는지 원인을 파악하기 어려웠으며, 이에 MAT이라 불리는 Eclipse Memory Analyzer를 사용해 Heap Dump File을 분석해봤다.
Visual VM에서 받은 dump 파일의 크기만 해도 6GB 이상이었기 때문에 Analyzer에 할당된 메모리 크기를 늘려주는 작업도 필요했다..
이상하다. 97%의 Heap Memory가 LinkedList에 할당되어 있다.
그런데 내가 테스트한 로직에는 LinkedList를 전혀 사용하지 않았다.
그리고 자세히 살펴보면 org.mockito의 InvocationContainerImpl이 뭔가 메모리를 많이 잡아먹는 듯 하다.
Mockito 코드 내부
public class DefaultRegisteredInvocations implements RegisteredInvocations, Serializable {
private static final long serialVersionUID = -2674402327380736290L;
private final LinkedList<Invocation> invocations = new LinkedList<>();
@Override
public void add(Invocation invocation) {
synchronized (invocations) {
invocations.add(invocation);
}
}
@Override
public void removeLast() {
// TODO: add specific test for synchronization of this block (it is tested by
// InvocationContainerImplTest at the moment)
synchronized (invocations) {
if (!invocations.isEmpty()) {
invocations.removeLast();
}
}
}
@Override
public List<Invocation> getAll() {
List<Invocation> copiedList;
synchronized (invocations) {
copiedList = new LinkedList<>(invocations);
}
return copiedList.stream()
.filter(invocation -> !isToStringMethod(invocation.getMethod()))
.collect(Collectors.toList());
}
@Override
public void clear() {
synchronized (invocations) {
invocations.clear();
}
}
@Override
public boolean isEmpty() {
synchronized (invocations) {
return invocations.isEmpty();
}
}
}
디버깅을 사용해 코드를 타고 들어가다보면 위의 코드를 만날 수 있다.
그리고 해당 클래스에서 LinkedList를 사용한다..
매번 add가 호출되고 clear가 호출되지 않는지를 직접 테스트해봤다.
맨 처음에는 add에 디버깅이 걸린다.
그 다음에는 isEmpty에 디버깅이 걸리고
removeLast에 디버깅이 걸리면서 LinkedList 내부의 객체가 삭제된다.
어라? 그러면 왜 OOM이 발생할까?
1번이 아닌 100번을 연속해서 호출해봤더니 1번째 호출에 대해서는 위의 과정을 거치는데 이후에는 add 메서드만 계속 호출되는 것을 확인할 수 있었다.
점점 LinkedList<Invocation> invocations의 사이즈가 커지는 것을 실제로 확인할 수 있었다.
테스트 코드 수정
private static class RepositoryImplForTest implements Repository {
@Override
public void save() {
}
@Override
public Optional<xxx> find(yyy) {
return Optional.ofNullable(zzz);
}
}
위의 예시코드와 같은 repository 구현체를 테스트 클래스 하단에 추가하고 해당 repository를 사용해 테스트를 구성했다.
결과
700만번의 호출에 대해서 2분 가량 걸리던 테스트 코드가 52초 안에 끝났으며, Heap Memory 또한 많이 사용되지 않음을 확인할 수 있었다.
'트러블 슈팅' 카테고리의 다른 글
| Transaction propagation option & silent rollback (0) | 2022.12.28 |
|---|---|
| [예외 처리] getMessage를 출력했는데 null이 왜 나와? (0) | 2022.01.25 |