배치 시스템 성능 분석: Grafana와 APM으로 메모리 누수와 이벤트 루프 지연 진단하기 (1)

1. 들어가며

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

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

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

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

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

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

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

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

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

메모리

평균 메모리 사용량

• 약 0.4GB 수준이지만, 계속해서 우상향하고 있음

최대 메모리 사용량

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

평균은 0.4GB인데, 순간적으로 0.5GB까지 올라가며 GC 하기 전 메모리를 축적하고 있습니다.

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

메모리 사용량

• 12/14 초반: 약 1GiB 사용 (여러 Pod 합산)
• 12/16 12:00 이후: 배포로 인해 Pod 전체 교체 후 갑자기 0으로 떨어짐

구 Pod: 1~1.5 GiB 사용

• 신 Pod: 0.75~1 GiB 사용
• 약 25~33% 메모리 감소

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

1. 메모리 leak 있었는데, 시간 지나면서 쌓였다가 재시작으로 리셋
2. 구 Pod가 오래 돌면서 데이터 캐시 쌓였음

메모리 누수 개선 작업이 없었고 서버가 교체되면서 임시적으로 해결된 것입니다. 그래서 향후 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로 감소, 0.03 cores 유지
• 배포 후 CPU 사용량도 약 50% 감소, 메모리와 동일한 패턴

최대 CPU 사용량

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

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% 이하
• 거의 바닥에 붙어있음

5일간 Pod CPU 추세

물론 역시나 Memory나 CPU 둘다 서버가 뻗을 정도로 문제가 되는 수치가 전혀 아닙니다. 수치가 바닥에 붙어있는 것을 보면 알 수 있습니다. (저희 트래픽을 생각하면 당연한 것 같습니다.)

그렇지만 우상향하는 것으로 보아 조사가 필요해 보입니다. 지금은 넉넉한 상태지만 언젠가는 끝에 도달한다는 뜻이니까요!

패킷

패킷 전송률

• 12/14 초반: 약 50~60 p/s 메모리/CPU와 동일한 패턴으로 보이네요.

패킷 수신률

• 12/14: 약 50 p/s

전송 패킷 드롭률

전송 패킷 드롭률

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

수신 패킷 드롭률

수신 패킷 드롭률

• 전송 패킷 드롭률 그래프와 유사. 드롭된 패킷이 거의 없습니다.

대역폭

대역폭 처리율

• 12/14 초반: 약 384 KiB/s 네트워크 I/O 부하가 2배 정도 증가했다가 리셋된 것으로 판단됩니다. 하지만 역시나 우상향 하는군요!

수신 대역폭

• 거의 0에 가까움
• 수치가 상대적으로 높았을 당시에는 모집 마감등의 이벤트가 있어서 어느정도 데이터를 수신 했던 것 같습니다. (그래도 작은 수치이다)

Grafana 분석을 통해 알 수 있는 가능한 원인들

지표를 보았을 때 우상향하는 부분이 있는 것으로 보아 누수 지점이 있다는 것은 파악했습니다.

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

1. 로그

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

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

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

1. 메트릭 수집

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

4. Elastic APM 확인

Transactions

APM Transactions

주요 API 호출

1. GET /api/ping (5.9 tpm)

해당 API는 Kubernetes 등의 Ingress의 헬스체크 프로브로 10초마다 1회 호출되는 정상 패턴입니다. 실제 유저 수준의 트랜잭션이 아니며, 시간에 따른 변화가 없어 리소스 사용 모니터링 대상에서 제외했습니다.

1. OPTIONS unknown route (0 tpm)

해당 API는 브라우저에서 CORS preflight 요청으로 발생하는데, NestJS 라우터에서 매치되지 않는 경로이므로 빈번히 호출되지 않습니다. 1분당 0회로 매우 미미한 호출 수준입니다.

1. PATCH /api/submission-answers/:id/submissions/:submissionId/steps/:step/question/:questionId (0.7 tpm)

해당 API는 위에서 언급��� 두 개의 API를 제외한 가장 tpm이 높은 API입니다.

특정 API 상세

많을 때는 최대 26 tpm까지 올라가기도 했는데, 이 수치들은 "유효하지 않은 문항입니다"라는 에러가 예상치 못하게 발생하고 호출되는 경우들이 포함되어 있습니다.

사실 이 에러는 어떤 설문조사나 지원서의 특정 단계 + 특정 문항에 세팅되어 있는데, 없는 고유 id 조합으로 요청이 가서 에러가 발생하는 것입니다. 특정 호출이 계속 반복되고 있어서, 이러한 호출을 하는 FE 코드 수정이 필요해 보입니다.

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

해당 API는 위에서 언급한 세 개의 API를 제외한 가장 tpm이 높은 API입니다.

특정 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.](https://nodejs.org/ko/learn/diagnostics/memory/using-heap-snapshot)

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를 임시로 베타 환경에 붙여서 다운로드 받고 확인해보겠습니다.

개발자 도구에서 Heap Snapshot 분석

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

하지만.. 분석 실패

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

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

개발자 도구에서 Heap Snapshot 분석

6. Grafana에 NodeJS 지표 추가

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

NodeJS Event Loop 지연

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 메모리

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

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배 증가

무거운 동기 작업이나 블로킹 작업 증가 의심되고 있습니다.

• 메모리 누수 또는 캐시 증가 가능성이 있어요.

공간 관리 비효율: 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. 마치며

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