큐를 활용한 배치 시스템을 분석하고 개선해보자 (1)

1. 들어가며

부끄럽게도 사실 현재 운영중인 애플리케이션의 성능과 지표를 제대로 측정하고 검토해본적이 없었습니다. 늦었지만, 이제부터라도 반년 가량 운영해본 서비스의 성능과 지표를 측정해보려고 합니다. 그래서 현재 어떤 상태인지 확인하고, 이 지표를 가지고 개선할 것들을 판단하려고 합니다.

2. 지표를 보기전, 우리 상황을 검토해보기

지표를 깊게 살펴보기 전에 우리의 상황을 검토해보려고 합니다. 지표가 있는데 잘 쓰지 못하는 경우들이 무엇이 있을까요? 저희는 지표를 제대로 측정하지 않았었는데, 아래와 같은 경우들이 저희에게 해당하는 케이스로 보입니다.

측정을 안해서 문제를 모르는 경우

리소스를 깊게 살펴보기 전에 판단해야 하는 것들이 있습니다. 특정 API가 느려지고 있어도 측정하지 않아서, 뒤늦게 발견하고 체감하는 경우들이 있었습니다.

문제라고 느끼는 것들이 실제로 문제의 원인인가?

특정 API 호출이 느린 것 같은데, 막상 수집 데이터를 보니 문제가 없었던 경험이 있었는데요, 제대로 측정하지 않으면 보이는 것만 가지고 추측하게 되고 시간과 리소스를 낭비할 위험성이 있다고 생각합니다. 따라서 더 나은 선택을 하기 위해서는 데이터가 필요하고 측정이 가능해야 합니다.

3. 그라파나 대시보드 확인

우선 저희가 수집하고 있는 그라파나 대시보드부터 확인해보려고 합니다. 크게 메모리, CPU, 패킷, 대역폭을 살펴보려고 해요.

메모리

평균 메모리 사용량

12/14 ~ 12/15: 약 0.4GB (전체 Pod 기준)
12/16 이후: 안정적으로 0.35~0.4GB 유지
배포 후 메모리 사용량이 약간 감소한 것을 확인

최대 메모리 사용량

12/14 ~ 12/15: 최대 0.7GB까지 튐 (스파이크)
12/16 이후: 최대 0.5GB로 안정화

평균은 0.4GB인데, 순간적으로 0.5GB까지 올라감 = GC(Garbage Collection) 전 메모리를 축적하고 있습니다.

5일간 최대 메모리 사용량이 지속적으로 증가하여 0.54GB까지 도달했습니다.
평균 메모리와 함께 상승하는 패턴으로 보아, 메모리 누수가 명확해 보입니다.

메모리 사용량

12/14 초반: 약 1GiB 사용 (여러 Pod 합산)
12/16 12:00 이후: 갑자기 0으로 떨어지고, 새로운 Pod들만 보임
- 배포로 인해 Pod 전체 교체
- 구 Pod: 1~1.5 GiB 사용
- 신 Pod: 0.75~1 GiB 사용
- 약 25~33% 메모리 감소

사용량이 5일간 25% 증가(800MiB→1GiB)했고, 향후 GC 비효율로 인한 메모리 부족 가능성 있습니다. (배포 전 상태)

배포 이후 메모리가 줄어든 원인?

메모리 leak 있었음 - 시간 지나면서 쌓였다가 재시작으로 리셋
데이터 캐싱 - 구 Pod가 오래 돌면서 캐시 쌓였음
GC 설정 변경 - Node.js/NestJS GC 설정 변경

메모리 누수 개선 작업이 없었으므로, 향후 3일~5일간 배포하지 않고 메모리 상태를 확인해봐야합니다. 계속 메모리가 늘어난다면, 메모리 누수가 난다고 판단할 수 있어 보여요.

진짜 OOM이 발생할 가능성?

우선 파드 스펙을 고려해보겠습니다.

Limit: 4GB
실제 사용: 최대 0.5GB ~
여유: 약 87.5%

사실 OOM이 발생할 정도로 메모리는 전혀 문제 없고, 남아도는 스펙이라서, 문제는 없습니다. 하지만 메모리를 효율적으로 사용하지 못하고 있는 것은 맞습니다.

CPU

평균 CPU 사용량

12/14 ~ 12/15: 약 0.05~0.06 cores
12/16 배포 후: 약 0.03 cores로 감소
12/16 이후: 안정적으로 0.03 cores 유지
배포 후 CPU 사용량도 약 50% 감소, 메모리와 동일한 패턴

CPU 사용량이 5일간 2배 이상 증가(0.03→0.07 cores)했는데요, 메모리와 마찬가지로 지속적인 증가 패턴으로 보아, 인메모리 leak 등이 의심됩니다.

최대 CPU 사용량

전체적으로 0.06~0.08 cores
간헐적인 스파이크 (최대 0.09 cores)
피크 타임에도 0.08 cores = 8%만 사용

최대 CPU 사용량이 5일간 40% 증가(0.06→0.085 cores)했는데요, 평균 CPU와 함께 상승하는 패턴으로 보아, 지속적인 부하 증가가 원인으로 판단됩니다.

AS-IS

requests:
  cpu: 1 core
  memory: 2Gi
limits:
  cpu: 2 cores
  memory: 4Gi

TO-BE

requests:
  cpu: 100m # 0.1 core     # 평균의 3배
  memory: 1Gi              # 현재 사용의 1.2배
limits:
  cpu: 500m # 0.5 core     # 피크의 6배 (충분한 버퍼)
  memory: 2Gi              # 여유있게 2배

CPU 사용량 (Pod)

모든 Pod가 10% 이하
거의 바닥에 붙어있음
12/16 이후 여러 Pod로 분산

Pod CPU 사용률이 5일간 2배 이상 증가하기도(7%→15%)했는데요, 모든 Pod에서 동시에 상승하는 패턴으로 보아, 애플리케이션 레벨의 문제로 판단됩니다.

패킷

패킷 전송률

12/14 초반: 약 50~60 p/s
12/15: 점진적 증가 → 100~150 p/s
12/16 00:00: Pod 교체로 리셋
12/16 이후: 75~100 p/s로 안정화
배포 전: 패킷 수가 계속 증가
배포 후: 낮아지고 안정화

메모리/CPU와 동일한 패턴으로 보이네요.

패킷 수신률

12/14: 약 50 p/s
12/15~12/16: 증가 → 150~175 p/s (3배 증가!)
12/16 배포 후: 감소
간헐적인 큰 스파이크 존재
수신 패킷도 시간에 따라 3배 증가 같은 패턴 반복

전송 패킷 드롭률

거의 0 p/s으로, 드롭된 패킷이 거의 없습니다.
네트워크 레벨에서는 문제 없으며, 패킷 손실 없이 정상 전송 중이라고 보면 될 것 같습니다.

수신 패킷 드롭률

수신 패킷 그래프와 유사. 수신 패킷이 늘어나는 1-2 시간마다, 드롭되는 패킷이 있었습니다.
패킷 증가 시 일부 손실 있으나, 대부분 시간에는 안정적입니다.

대역폭

대역폭 처리율

12/14 초반: 약 384 KiB/s
12/15: 계속 증가 → 768 KiB/s 이상 (2배!)
12/16 배포 후: 약 384 KiB/s로 리셋
12/16 배포 후: 안정화

네트워크 I/O 부하가 2배 정도 증가했다가 리셋된 것으로 판단됩니다.

수신 대역폭

거의 0에 가까움
구 Pod가 있을 당시에는 어느정도 데이터를 보내고 있었던 것 같습니다.
평균의 2배를 찍고 있었다, 일정 수준 이상으로 보낼 것은 유지하고 있었으나 이후에는 0으로 떨어진 패턴 (수신 없음)

보낼 것도 많았고 또한 동시에 패킷도 많았고 메모리/CPU도 증가가 원인으로 보이므로, 결론적으로 현재 시스템에 문제가 있었고, 배포로 리셋된 후에는 안정적으로 전환됩니다.

가능한 원인들

지표만으로 알 수 없고 누수를 발생시키는 코드를 탐색해야겠지만, 저희 시스템 구조를 생각해보면 아래와 같은 작업들이 원인의 후보로 보입니다.

로그

외부 로깅 시스템(ELK, Datadog 등)으로 전송
로그 직렬화로 인한 CPU 증가

배치 작업 추가/증가, 잘못된 설계

주기적인 외부 API 호출
데이터 큐 작업
메일 / 알림 발송

메트릭 수집

Prometheus exporter 추가
메트릭 전송 빈도 증가

4. APM

Transactions

주요 API 호출

GET /api/ping (5.9 tpm)
- Kubernetes 등의 Ingress의 헬스체크 프로브 6초 = 10초마다 1회 호출 (정상 패턴)
- 실제 유저 수준의 트랜잭션은 아님
- 시간에 따른 변화가 없어 리소스 사용 모니터링 대상에서 제외
OPTIONS unknown route (0 tpm)
- 브라우저에서 CORS preflight 요청
- NestJS 라우터에서 매치되지 않는 경로이므로 빈번히 호출 안됨
- 1분당 0회라서 매우 미미한 호출
PATCH /api/submission-answers/:id/submissions/:submissionId/steps/:step/question/:questionId (0.7 tpm)
- 해당 API는 위에서 언급한 세개를 제외한 가장 tpm이 높은 것입니다.

위에서 언급한 두개 API를 제외한 가장 tpm이 높은 API인데, 많을때는 최대 26 tpm까지 올라가기도 하였습니다.
이 수치들은 아래와 같은 경우들이 저희에게 해당하는 케이스로 보입니다.
- "유효하지 않은 문항입니다" - 예상치 못하게 오류가 발생하고 호출이 되기도 하는 것을 확인할 수 있습니다.
- 사실 저 에러는, 특정 스텝에 있는 특정 question이 세팅되어있는데, 다른 조합으로 요청이 가서 에러가 발생합니다.
특정 호출이 계속 반복되고 있는데, 이러한 호출을 하는 FE 코드 수정이 필요해 보입니다.

GET /api/submission-answers/:id/submissions/:submissionId/steps/:step

해당 API는 위에서 언급한 세개 API를 제외한 가장 tpm이 높은 API인데, tpm이 그렇게 많지도 않고 latency도 느리지 않고 빠릅니다.
크게 문제되는 API로 보이지 않습니다.

결국 API는 문제가 아닌것으로 보인다. 진짜 문제는 무엇일까?

API 트랜잭션은 매우 적고 (대부분 < 0.1 tpm) 에러율도 0%입니다. 하지만 그라파나에서는 네트워크 송신 6배 폭증, 메모리/CPU 증가하고 있는데요, APM 상 API 호출 수는 거의 없고 그라파나 상으로는 리소스 사용률이 계속 증가하고 있습니다.

그 원인에 대해서는 서버가 받는 API가 아니니 서버에서 외부를 호출하는 것일 텐데, APM 데이터로는 외부 호출 여부를 판단할 수 없었습니다. 그래서 현재로는 판단하기 어려워, 이 이외의 다른 지표를 더 살펴보아야 합니다.

5. heap 지표를 확인하기 위한 설정과 추가를 해보자.

Node.js — Using Heap Snapshot

Node.js® is a free, open-source, cross-platform JavaScript runtime environment that lets developers create servers, web apps, command line tools and scripts.

import { Controller, Get, Res } from '@nestjs/common';
import type { Response } from 'express';
import { writeHeapSnapshot } from 'v8';
import { createReadStream } from 'fs';
import { unlink } from 'fs/promises';

@Controller()
export class AppController {
  constructor() {}

  @Get('/debug/heap-snapshot')
  async downloadHeapSnapshot(@Res() res: Response) {
    const filename = writeHeapSnapshot();

    res.setHeader('Content-Type', 'application/octet-stream');
    res.setHeader(
      'Content-Disposition',
      `attachment; filename="heap-${Date.now()}.heapsnapshot"`,
    );

    const stream = createReadStream(filename);
    stream.pipe(res);

    stream.on('end', async () => {
      try {
        await unlink(filename);
      } catch (error) {
        console.error(
          `[Heap Snapshot] Failed to delete file: ${error}`,
        );
      }
    });

    stream.on('error', (error) => {
      res.status(500).send('Failed to download heap snapshot');
    });
  }
}

v8에서 제공하는 writeHeapSnapshot 메서드 덕분에 heapSnapshot 파일을 얻을 수 있었습니다. 해당 API를 임시로 베타에 붙여서 다운로드 받고 확인해보겠습니다.

개발자 도구의 Memory 탭을 활용해볼건데요, 해당 탭에 다운받은 heapSnapshot 파일을 업로드하면 됩니다.

하지만.. 분석 실패

string, system / context / system / JSArrayBufferData / ArrayBuffer / ArrayBuffer 등등의 지표들을 모두 하나씩 반나절 동안 살펴보았지만, 정확한 원인을 찾을 수 없었습니다. 가장 큰 원인은 해당 지표들을 제대로 볼줄 모른다는 것이고, 이외에도 너무 복잡하고 원형적인 데이터로 존재하여 분석하기 어려웠었습니다.

이러한 고민이 있는 찰나에 함께 협업하는 SRE팀에 자문을 구했을때 수동으로 heapSnapShot 파일을 분석하지 말고, 지표를 추가하여 그라파나로 확인하는 것을 추천해주셨습니다.

6. NodeJS 지표 추가

이에 우선 그라파나를 잘 활용하기로 하였고, NodeJS 기본 지표들을 더 분석하여 메모리 관련 문제를 더욱 확실하게 확인하였습니다.

NodeJS Event Loop 지연

이벤트 루프 지연 (밀리초)

12/31 ~ 01/04: 약 100~150ms로 안정적 유지
01/05 00:00 이후: 급격히 증가하여 150~250ms로 상승
01/06: 최대 400ms까지 스파이크 발생
노란색 인스턴스가 특히 높은 지연을 보임

이벤트 루프 지연이 급증하면 요청 처리가 지연되고, API 응답 시간이 느려지는데요, 01/05 이후 급격한 증가는 특정 배치 작업이나 외부 API 호출 증가가 원인일 가능성이 있습니다.

p99 지연

전체 기간 동안 10~13ms로 매우 안정적
간헐적인 스파이크만 존재 (최대 13ms)
대부분의 요청은 11ms 이내에 처리됨
p99 지연은 안정적이지만, 평균 이벤트 루프 지연이 높다는 것은 일부 무거운 작업이 이벤트 루프를 블로킹하고 있다는 신호로 보입니다.

NodeJS Heap 메모리

사용중인 힙 메모리

12/31 ~ 01/02: 약 150~165MB로 안정적
01/03 이후: 점진적으로 상승하여 160~180MB 유지
01/06: 최대 220MB까지 스파이크 발생
지속적인 상승 추세가 관찰됨

할당된 총 힙 메모리

12/31 ~ 01/04: 약 150~200MB
01/05 이후: 200~250MB로 증가
01/06: 최대 250MB까지 도달
사용중인 힙과 유사한 패턴으로 증가

할당된 총 힙이 증가한다는 것은 V8 엔진이 더 많은 메모리를 필요로 한다고 판단했다는 의미로, 이는 실제로 메모리 사용량이 증가하고 있음을 나타내고 있습니다.

힙 사용률 (%)

대부분의 시간: 85~95% 유지
주기적인 하락 패턴: GC(Garbage Collection) 실행 시점
01/01 이후: 80~95% 사이에서 톱니 패턴 반복

85%가 많아보일 수 있지만, 전체 최대 힙 크기는 4096MB 이상이기 때문에 장애가 나는 수준이 절대 아니고, 오히려 넉넉한 편입니다.

처음 혼동한 것이 있었는데, 할당된 총 힙 메모리가 NodeJS앱의 할당된 총 힙 메모리가 아닌, 그 시점에 OS로부터 할당받은 메모리이기 때문에 전체 사용량을 절대 넘어서지 않습니다.

NodeJS Space

New Space Size (Young Generation)

좌측 하단 그래프를 보면, 노란색과 녹색으로 표시된 두 인스턴스의 New Space 크기를 확인할 수 있습니다.
전체 기간 동안 주기적인 톱니 패턴이 반복됨
01/05 이후: 스파이크가 더 자주 발생하고, 피크 값이 증가
우측 상단의 작은 그래프에서도 01/06 시점에 급격한 스파이크 확인
New Space는 새로 생성된 객체들이 할당되는 영역입니다. 주기적인 톱니 패턴은 Minor GC(Scavenge)가 정상적으로 작동하고 있다는 의미이지만, 스파이크가 증가한다는 것은 새로운 객체 생성이 급증했다는 신호입니다.

Old Space Size (Old Generation)

좌측 하단 그래프의 더 높은 선들이 Old Space를 나타냅니다.
12/31 ~ 01/04: 비교적 안정적
01/05 이후: 점진적 증가 추세
우측 하단 그래프에서도 여러 메트릭들이 시간에 따라 증가하는 패턴 확인

Old Space는 Minor GC에서 살아남은 장수 객체들이 이동하는 영역입니다. Old Space가 지속적으로 증가한다는 것은 메모리에서 해제되지 않는 객체들이 계속 누적되고 있다는 의미로, 메모리 누수의 강력한 증거로 보입니다. 여기서 누수라는 것을 확정지을 수 있겠네요!

결론

이벤트 루프 지연 급증: 01/05 이후 2~4배 증가
- 무거운 동기 작업이나 블로킹 작업 증가 의심되고 있습니다.
힙 메모리 증가: 150MB → 220MB (약 46% 증가)
- 메모리 누수 또는 캐시 증가 가능성이 있어요.
공간 관리 비효율: New Space 스파이크 증가, Old Space 증가 가속화
- New Space에서 생성된 객체들이 정상적으로 정리되지 않고 Old Space로 계속 승급되고 있으며, Old Space에서도 제대로 해제되지 않고 있습니다. 이는 전형적인 메모리 누수 패턴으로, 특정 객체에 대한 참조가 의도치 않게 계속 유지되고 있을 가능성이 높습니다.

7. 근데, 현실적인 트래픽을 생각해보자.

트래픽이나 API 요청수를 추정했을 때 하루에 약 93,288건이 호출되는 것을 확인할 수 있습니다.

이 수치는 아래와 같이 정리할 수 있있습니다.

93,288건 / 일
- 시간당: 약 3,887건
- 분당: 약 64.8건
- 초당: 약 1.1건
서버 스펙
- CPU: 1-2코어 (requests-limits)
- 메모리: 2-4GB

현실적으로 초당 1.1건은 솔직히 말해서 트래픽이 거의 없는 수준입니다. 이는 Elastic APM 화면을 보니 더 명확한데요, 히스토그램 보면 트래픽이 고르게 분산되어 있고, 특별한 피크 타임도 없습니다. 트래픽이 매우 낮은 상태에서 과분한 리소스를 할당받은게 아닌가라는 생각도 해야할 필요도 있는 것 같습니다. 가능하면 리소스를 줄이고 최적화된 서버 스펙에 맞춰서 운영하는게 좋아보입니다.

8. 회사, 제품에 이득을 가져와야 한다.

지금 상황에서 CPU/메모리 최적화를 한다고 하면, 아래와 같은 결과를 낼 것입니다.

서버 비용이 거의 나가지도 않는 상황에서, 회사가 비용을 크게 절감하지도 않음
사용자 경험이 개선되지도 않음 (이미 충분히 빠름)
팀이나 회사가 원하는 [안정성]이 체감할 수준으로 올라가지도 않음

대신 조금 틀어서 생각해서 [안정성을 위한 측정과 개선]을 한다로 방향을 잡아보려고 합니다.

느린 API (latency가 높은 트랜잭션) 찾아서 개선
메모리 leak 모니터링 (장기간 추세)
비동기 큐의 잘못된 설계 개선
비동기 큐의 에러 처리, 운영 가시화

이러한 것들이 실질적인 안정성 개선이고, 회사와 팀의 발전을 위해 작업하고 보고할 가치가 있어보입니다. 저는 우선 이중에서 아래 비동기 큐를 중점적으로 점검해보려고 합니다.

비동기 큐의 잘못된 설계 개선
- 비동기 큐의 잘못된 설계로 인한 운영 안정성 저하 방지
- 추가적으로 메모리 및 CPU 하드웨어 자원 비효율 개선
비동기 큐의 에러처리, 운영 가시화
- 비동기 큐가 잘 돌아가고 있지만, 개발자가 직접적으로 확인하기 어려움
- 복구할 수 있는 에러에 대해서는 에러처리를 할 수 있어야 함
- 에러에 대해서 올바르게 처리할 수 있어야 함
- 성공에 대해서도 올바르게 모니터링 할 수 있어야 함

9. 마치며

이번 경험을 통해 측정하지 않으면 개선할 수 없다는 것을 다시 한번 배웠습니다.
측정도 잘못된 데이터나 쿼리로 측정하면 잘못된 결론을 낸다는 것을 깨닫기도 했습니다.
하지만 모든 것을 측정해야 한다는 것은 아니라고 생각합니다.
제한된 리소스 안에서 무엇을 측정할지 선택하는 것이 중요하고 개선하는 것이 중요하다고 생각해요.
그래서 측정한 지표를 바탕으로 지속적으로 개선해나가고 싶습니다. 이제 다음 스텝은 누수를 일으킬만한 코드와 설계들을 확인해보고, 차근 차근 개선해보는 절차를 밟아보려고 합니다.

← 이전글

임시저장 기능 고도화 해보기 (5)

큐를 활용한 배치 시스템을 분석하고 개선해보자 (2)