성능 이슈 발생한 무거운 API 튜닝하기

배경

어느 날 사내 운영 환경 검증 중에 API 응답은 504 gateway timeout 이며, 어플리케이션 서버는 OOM(out of memory)이 발생하였습니다.

org.springframework.web.util.NestedServletException: Handler dispatch failed; nested exception is java.lang.OutOfMemoryError: GC overhead limit exceeded

원인은 무거운 API가 7,000 건 이상의 데이터를 처리하면서 발생한 상황이었습니다.

7,000 건 정도의 데이터가 많지 않다고 느껴질 수 있으나, 해당 API는 데이터 양이나 트래픽이 많아질 경우 충분히 이슈가 발생할 만한 상황이었습니다. 조회 API임에도 불구하고 조회하는 과정에서 많은 연관된 데이터들을 읽어들이며 복잡한 연산까지 수행하고 있었기 때문입니다. CQRS가 안되어 있었죠.

여튼 빠르게 해결해야 했기에 CQRS 패턴을 적용하여 대대적인 기능 개선을 진행하긴 어려운 상황이었습니다.

 

원인 분석

먼저, OOM 이슈에는 GC가 강하게 연관되어 있기 때문에 어디선가 많은 양의 객체가 생성되고 제거(가비지 수집)되지 않고 있을 것이라 생각했습니다.

GC 분석 툴을 사용해본 적이 없는 터라, 초반에는 코드 단에서 살펴보며 분석해보았습니다. 의심되는 부분들은 여럿 있었지만, 확신이 없었으며 코드를 수정해도 얼마나 개선 되었는지 확인이 불가능했습니다.

그래서 GC 분석 툴을 실행시키는 포스팅을 찾아다녔는데, 결국에 가장 기본적인 VisualVM을 사용하게 되었습니다.

이를 실행시켜이슈 상황을 재현하며 GC/Memory 추이를 살펴보았습니다.

VisualVM 상 어플리케이션의 heap 메모리

 

 

위 Heap 그래프에서 볼 수 있듯이, 어느 시점부터 프로세스가 메모리를 최대로 점유한 채 줄어들지 않고 있으며 사용중인 heap size도 줄지 않고 있습니다. GC는 계속 동작하는데, heap 메모리를 충분히 확보하지 못했기 때문에 GC overhead limit exceeded 이슈가 발생한 것으로 생각됩니다.

이번엔 heapdump 파일을 통해 또 다른 분석 툴()을 통해 인스턴스 현황(?)을 확인할 수 있었습니다.

—

분석 결과에서 가장 비율을 많이 차지한 인스턴스가 생성되는 곳이 몇 군데 있었는데, 디버깅을 통해 몇 가지 원인을 찾을 수 있었습니다.

 

 

문제 개선 1. 비효율적인 로직 리팩토링

먼저, 성능 개선을 진행할 수 있을 것 같은 로직(?)이 있었습니다. 예시 코드로 보겠습니다.

private Map<Long, List<SaleRecord>> before(List<Long> ids,
                                           YearMonth yearMonth) {
        // 개선 전 코드
    Map<Long, List<SaleRecord>> results = Maps.newHashMap();
    salesByIds.keySet()
              .stream()
              .filter(ids::contains)
              .forEach(id -> {
                  List<SaleRecord> sales = salesByIds.get(id);
                  sales = sales.stream()
                               .filter(isBefore(yearMonth))
                               .collect(Collectors.toList());
                  results.put(id, sales);
              });

    return results;
}

많은 분들이 예상하셨겠지만 위 코드는 이중 반복문 형태로 동작하고 있습니다. Map의 keySet() 기준으로 stream을 생성하고 그 안에서 id에 해당하는 List<SaleRecord> 값을 기준으로 다시 반복문을 실행하고 있습니다.

여기서 한 가지가 더 있는데, forEach 문을 보시면 stream 외부의 Map<Long, List<SaleRecord>> results 객체에 반복해서 데이터를 넣어주고 있습니다. Stream은 외부 객체 참조를 사용하지 않는 경우 성능이 좋은 것으로 이해하고 있습니다.

위 코드를 개선한 결과입니다.

private Map<Long, List<SaleRecord>> after(List<Long> ids,
                                          YearMonth yearMonth) {
    // 개선 후 코드
    Map<Long, List<SaleRecord>> salesByTarget = salesByIds.values()
                                                          .stream()
                                                          .flatMap(Collection::stream)
                                                          .filter(r -> isBeforeThan(YearMonth.from(r.getDate()),
                                                                                    yearMonth))
                                                          .collect(Collectors.groupingBy(
                                                              SaleRecord::getId));
    List<Long> emptySaleIds = salesByIds.entrySet()
                                        .stream()
                                        .filter(e -> e.getValue().isEmpty())
                                        .map(Map.Entry::getKey)
                                        .collect(Collectors.toList());

    for (Long emptySaleId : emptySaleIds) {
        salesByTarget.put(emptySaleId, Collections.emptyList());
    }

    return salesByTarget;
}

위에서 언급했던 내용들을 개선해보았습니다.

이중 반복문 형태로 사용하던 부분은 flatMap() 을 사용하는 형태로 변경하였습니다.

외부 객체를 참조하던 방식에서 Stream을 통해 grouping하며 예외 사항에 대해서 Stream 외부에서 데이터를 주입해주는 형태로 변경하였습니다.

실제로도 예상한 결과가 나올지 테스트를 수행해보았습니다.

테스트 결과

 

테스트는 총 100만 건 기준으로 진행하였으며, id 목록과 YearMonth는 적절히 배분하여 조건문을 수행하도록 하였습니다.

테스트 결과는 기대한 대로 기존 대비 개선한 결과가 성능이 더 높았는데, 측정된 시간이 각각 4095 ms, 164 ms 이므로 25배 정도 차이가 나는 것을 알 수 있습니다.

 

 

문제 개선 2. 과도한 객체 생성 및 Long-lived 객체

1번 사례는 처리 시간과 관련한 성능 문제였지만, 주요 문제는 heap 메모리가 가득 차고 가비지 수집을 충분히 못하는 것이었습니다.

그래서 디버깅을 진행해보며 어느 시점에 heap 메모리가 급증하는지 확인했고, VisualVm에서 제공하는 heapdump 파일을 분석하는 기능을 이용하였습니다.

VisualVM에서 heapdump 파일을 분석한 결과

 

 

보시면 객체 수, 사이즈 모두 OrderDescription 클래스가 높은 순위에 있는 것을 보실 수 있습니다.

Orderer 객체도 순위권에 있는 것을 볼 수 있는데, 이는 OrderDescription 객체를 이용해서 연산하는 과정에서 생성되는 것이라 생각했습니다.

그래서 가장 의심되는 코드를 가져와봤습니다.

// Before
public void bulkCalculateV1(OrderDescriptionDto description,
                            Map<Long, OrderDescriptionDto> descriptionsById) {
    OrderDescription rootNode = OrderDescription.from(descriptionsById.get(getFirstOrderId(order.getOrderId())), null);

    // ..
}

// After
public void bulkCalculateV2(OrderDescriptionDto description,
                            Map<Long, OrderDescription> descriptionsById) {
    OrderDescription firstOrder = descriptionsById.get(getFirstOrderId(order.getOrderId()));

    // ..
}

보시면 V1 메서드에서는 OrderDescription 객체를 생성하고, V2 메서드에서는 Map에서 꺼낸 객체를 그대로 사용하고 있습니다.

이게 그렇게 큰 영향을 미칠까 싶을 수 있지만, 해당 메서드는 반복문 형태로 호출되고 있었기에 생각보다 큰 영향을 미치고 있었습니다.

V2로 변경 시 파라미터 타입이 달라서 해당 메서드를 호출하는 쪽에 수정이 필요했습니다.

 

개선 후 heap 메모리 모습

 

꽤 많이 개선된 모습을 볼 수 있었습니다. (약 40-50% 축소)

문제가 되는 곳을 개선한 후, 리팩토링하며 이상한 점을 발견하였습니다.

대표로 추출된 id들만 특정 메서드에 인자로 넣으면 되는데, 모든 id를 주입하여 다소 복잡한 연산이 더 많이 발생하고 있었습니다.

public void calculate() {
  // ..
    createOrderDescriptions(teamId, allSaleIds); // here
    // .. 
}

public List<OrderDescription> createOrderDescriptions(Long teamId, Collection<Long> firstIds) {
    // ..
}

이전에 제가 작업한 부분과 관련이 있었는데, 파라미터명을 주의 깊게 확인하지 않았으며 기존 비지니스 로직을 깊이 이해하지 못한 채로 개발을 진행하다 보니 이러한 상황이 발생한 것 같습니다.

그래서 필요한 이전 단계 메서드에서 대표 id들을 필터링하여 주입하고, 파라미터명도 보다 명확한 네이밍 변경을 통해 개선할 수 있었습니다.

public void calculate() {
  // ..
    List<Long> firstOrderIds = getFirstOrderIdsBy(allSaleIds);
    createOrderDescriptions(teamId, firstOrderIds); // here
    // .. 
}

public List<OrderDescription> createOrderDescriptions(Long teamId, Collection<Long> firstOrderIds) {
    // ..
}

개선 후 heap 메모리 모습

 

이렇게 처리 시간 성능, heap 메모리 관점에서 리팩토링을 통해 개선해볼 수 있었습니다.

하지만 여전히 팀 내에서 해당 기능에 대한 성능과 구조 개선은 필요함을 인지하고 있기에, 이후 팀원들과 함께 지속적으로 개선해볼 예정입니다.

 

참고

Java Heap Dump 분석하기