이틀 동안 운영 API가 다섯 번 죽었다

임기호·2026년 8월 22일

docker garbageCollection nodejs oom prisma v8 메모리 장애분석

Backend

목록 보기

1/2

상황은 이랬다. 15GiB짜리 서버 한 대에 Node API 컨테이너 두 개가 올라가 있었고 메모리 제한은 걸려 있지 않았다. 한 프로세스가 서버 전체를 다 쓸 수 있는 상태였다. 8월 10일과 11일에 처음 한 번씩 죽었고 그때마다 502가 났다.

첫 번째 — OCR

가장 먼저 의심한 건 수출 서류 OCR이었다. 이유는 그럴듯했다.

PDF를 300DPI 이미지로 바꾼 뒤 페이지 전체를 한 번 읽고 품목 영역을 다시 읽는다. 이미지 버퍼와 tesseract.js가 메모리를 크게 쓴다. 11일 14시 23분에 OCR 요청 세 건이 거의 동시에 들어왔고 다 끝나기 전인 5분 뒤에 프로세스가 죽었다.

시간이 맞았다. 그래서 맞다고 생각했다.

OCR을 자식 프로세스로 떼어냈다. 부모는 파일 경로만 넘기고 자식이 읽어서 처리한 뒤 종료한다. 프로세스가 끝나면 OS가 메모리를 통째로 회수하니 부모 API는 안전해진다. 동시 실행도 서버 전체에서 한 건으로 묶었다.

안 멈췄다

12일에 또 죽었다. 13일에는 네 번 죽었다.

커널 기록을 봤다.

Aug 12 15:04  node killed  anon-rss  7.60 GiB
Aug 13 10:44  node killed  anon-rss  8.57 GiB
Aug 13 14:15  node killed  anon-rss 10.12 GiB
Aug 13 14:22  node killed  anon-rss  9.86 GiB
Aug 13 14:36  node killed  anon-rss  6.22 GiB

CONSTRAINT_NONE, global_oom. cgroup 한도가 아니라 호스트 메모리가 통째로 말랐다. 죽은 건 전부 Node였다.

OCR을 격리한 뒤에도 계속 죽었다. 첫 번째 답은 틀렸다.

죽은 프로세스가 뭘 하고 있었나

이번엔 추측을 접고 죽은 컨테이너의 로그에서 서브시스템별 줄 수를 셌다.

docker logs <container> 2>&1 | grep -oE '\[[A-Za-z][A-Za-z0-9_ -]{2,40}\]' | sort | uniq -c | sort -rn

138~315줄   외부 시스템 인증 어댑터   ← 1위
 49~ 63줄   전자문서 처리 유스케이스
 19~ 23줄   파일 공유 서비스

OCR 관련 로그는 컨테이너 수명 전체에서 4~10줄이었다. OCR 한 건이면 최소 4줄이 찍힌다. 메모리로 죽은 프로세스들은 PDF를 거의 만지지 않고 있었다.

앱이 남긴 메모리 스냅샷도 정상이었다.

OCR 시작   부모 RSS 1520MB
OCR 자식   종료 시 366MB
OCR 종료   부모 RSS 1027MB

작업 전후로 부모 메모리가 오히려 줄었다.

두 번째 — 네이티브 메모리

로그를 더 봤다. 죽는 방식이 두 가지였다.

하나는 커널이 죽였다. dmesg에 global_oom과 함께 victim으로 남아 있고 컨테이너는 137, 즉 SIGKILL로 끝났다.

다른 하나는 프로세스가 스스로 접었다. 종료 직전 로그가 이랬다.

FATAL ERROR: Ineffective mark-compacts near heap limit
Mark-Compact 1995.2 (2083.6) -> 1980.4 (2084.4) MB, 699ms
average mu = 0.104, current mu = 0.022

mu(mutator utilization)는 애플리케이션과 GC가 나눠 쓴 시간에서 애플리케이션 몫이다. V8이 할당 속도와 GC 속도로 계산한 추정치라 CPU 사용률을 직접 잰 값은 아니다. 로그를 보면 average가 0.104인데 current는 0.022다. 뒤로 갈수록 GC가 시간을 더 가져갔다. 한 번 돌 때마다 15MB쯤 회수하면서 2GB 한도 앞에서 제자리걸음을 하고 있었다.

이쪽 종료 코드는 139, SIGSEGV였다. V8이 힙 한계에서 abort하면 보통 SIGABRT라 134가 남는다. 왜 139로 기록됐는지는 아직 모른다. 죽기 직전 로그가 힙 고갈을 그대로 말하고 있어서 이 케이스는 힙 쪽으로 봤다.

이상한 건 커널이 죽인 쪽이었다. RSS는 6~10GiB인데 V8 힙은 2GB를 못 넘긴다. 차이만큼의 메모리가 V8 계측에 안 잡히고 있었다.

여기서 Prisma를 의심했다. 그때 확인한 버전은 ^4.16.2였고 쿼리 엔진은 Rust로 작성된 네이티브 모듈이다. 결과셋은 JS로 넘어오기 전까지 Rust의 Vec·String 같은 자료구조에 담긴다. JS 배열도 Buffer도 아니라 Rust가 자기 할당자로 잡은 메모리다. V8 힙이 아니니 heapUsed에 안 잡힌다. external은 Node가 V8에 크기를 등록해준 것만 세기 때문에 여기에도 안 나타난다. 남는 건 OS가 본 rss뿐이다. V8 GC가 직접 회수할 수 있는 영역도 아니다. JS로 넘길 때는 같은 데이터가 JS 객체로 한 벌 더 만들어진다.

증상이 딱 맞았다. 같은 증상을 보고한 이슈도 여럿이었다.

prisma#19703 — 60만 행 조회 시 RSS 2GB 초과, 힙은 정상
prisma#21471 — pod 재시작 전까지 반환 안 됨
prisma#25371 — 대용량 동시 쿼리에서 RSS 누수
prisma#22346 — updateMany 메모리 누수

조회 기간을 1년으로 늘리면 메모리가 계속 오르는 것도 재현됐다. 코드베이스에서 findMany 294개 중 take가 붙은 건 15개뿐이었다.

두 번째 답을 적었다. 상한 없는 조회에 네이티브 엔진이 메모리를 안 놓는 문제가 겹쳤다고.

세 번째 — 그냥 다 퍼올린 거였다

두 번째 답대로 움직였다. Prisma를 7.9.1로 올렸다. 이 버전은 Rust 쿼리 엔진 바이너리를 쓰지 않는다.

find node_modules -iname "*query_engine*"   →  0건
runtime/query_compiler_fast_bg.*.wasm-base64.js
@prisma/adapter-pg@7.9.1

Rust가 사라진 건 아니다. Query Compiler 자체는 Rust로 작성돼 있고, WASM으로 컴파일돼 들어와 있다. 달라진 건 도는 자리다. 네이티브 힙이 아니라 V8이 들고 있는 선형 메모리에서 돌고 SQL 생성만 할 뿐 결과셋은 만지지 않는다. 결과셋은 Rust 네이티브 구조에 쌓이지 않고 pg가 파싱해 JS 객체로 반환한다. 내가 의심했던 "V8이 못 보는 메모리" 경로가 없어졌다.

그런데도 메모리는 계속 올랐다. 두 번째 답도 틀렸다.

남은 건 조회 자체였다. 개발 서버에 만들어두고 아직 운영에 안 올린 무한스크롤이 있어서 그걸 반영했다. 한 번에 500건씩만 가져오게 하자 상승이 멎었다.

그제야 숫자가 보였다. 그전까지는 사용자가 잡은 기간에 걸리는 행을 통째로 올리고 있었다. 앞에서 메모리가 계속 오르는 걸 재현했던 그 1년 조회가 54,565행이다. 한 페이지의 109배다.

GC는 잘못이 없었다. 5만 행을 응답으로 만드는 동안 그 객체들은 전부 참조되고 있어서 GC가 언제 돌든 버릴 수가 없다. young generation은 금세 차고 scavenge가 반복되지만 살아남은 것들은 계속 old generation으로 올라간다. 그렇게 올라간 양이 그대로 peak가 된다.

메모리가 안 내려온 게 아니라 한 번에 다 퍼올렸다.

그래서 실제로 얼마나 쓰나

추측을 그만하고 응답 파이프라인을 그대로 모사해서 쟀다. 101컬럼 500행이다.

단계	heapUsed	증감
기준선	2.99 MB
DB 결과 500행	8.70 MB	+5.71
직렬화 + 전개	12.62 MB	+3.92
GC 후	9.05 MB	−3.56

직렬화가 쓴 3.92MB 중 3.56MB가 즉시 쓰레기였다. 최종 응답에 남는 건 0.35MB뿐이다.

Object.entries → map → Object.fromEntries를 거치면 행마다 임시 배열이 200개 가까이 생겼다 사라진다. 500행이면 10만 개다. 반대로 살아남는 게 0.35MB밖에 안 되는 이유는 얕은 복사가 문자열을 공유하기 때문이다. {...serialized}가 실제로 복사하는 건 포인터 101개다.

참조를 끊어도 아무 일도 안 일어난다

단계	heapUsed
응답 직전	7.88 MB
`JSON.stringify` + Buffer	12.43 MB
스코프 벗어남	12.43 MB
GC 한 번 후	7.82 MB

세 번째 줄이 핵심이다. 도달 불가능해진 순간에는 아무 변화가 없다. JS에는 free()가 없고 다음 GC까지 그대로 남는다. GC 없이 다섯 번 반복하면 죽은 응답이 겹쳐 쌓인다.

12.40 → 16.73 → 21.10 → (V8이 알아서 GC) 12.46 → 16.83 MB

GC는 함수 실행 도중에 끼어든다

global.gc()를 한 번도 부르지 않고 GC 이벤트만 관측했다.

const { PerformanceObserver, performance, constants } = require('perf_hooks');
const KIND = {
  [constants.NODE_PERFORMANCE_GC_MAJOR]: 'MAJOR(mark-compact)',
  [constants.NODE_PERFORMANCE_GC_MINOR]: 'minor(scavenge)',
};
const events = [];
new PerformanceObserver(l => { for (const e of l.getEntries())
  events.push({ start: e.startTime, dur: e.duration, kind: KIND[e.detail?.kind] });
}).observe({ entryTypes: ['gc'] });

map 구간 17.5ms  ← 동기 함수 호출 한 건

  t=32.1ms  minor 1.07ms  ★ map() 실행 도중
  t=35.6ms  minor 0.78ms  ★ map() 실행 도중
  t=43.5ms  minor 0.20ms  ★ map() 실행 도중

GC는 따로 도는 타이머가 아니다. 새 객체를 young generation에 넣으려는데 자리가 없으면 그 할당 시점에 바로 scavenge가 돈다. 그래서 .map() 하나가 끝나기 전에 세 번 끼어든다.

덕분에 앞의 "3.56MB 회수"도 과소평가다. map이 도는 동안 이미 세 번 걷어간 뒤의 숫자다.

누수는 없었다

480회를 8라운드로 나눠 돌렸다.

라운드	누적 요청	작업 중 peak RSS	GC 후 heapUsed	GC 후 RSS
시작	0	–	3.5 MB	42.7 MB
1	60	122.1 MB	2.8 MB	80.9 MB
4	240	122.7 MB	2.8 MB	76.0 MB
8	480	122.3 MB	2.8 MB	76.6 MB

heapUsed가 매 라운드 정확히 2.8MB다. 480번을 돌려도 안 쌓인다. RSS는 첫 라운드에 42MB에서 80MB로 뛴 뒤 76MB대에 고정됐다. 누적이 아니라 수렴이다.

RSS가 안 내려오는 건 V8이 회수한 페이지를 자기 free list에 쥐고 있어서다. 다음 요청에서 또 쓸 테니 굳이 OS에 돌려주지 않는다. 다만 "반납하지 않는다"고 쓰면 과하다. Unmapper가 백그라운드에서 실제로 munmap을 하고 유휴 상태가 되면 memory reducer가 추가 GC로 힙을 줄인다. 정확히는 즉시, 적극적으로는 반납하지 않는다. 위 테스트에서 76MB가 유지된 건 계속 부하를 주고 있었기 때문이다.

실무에서 중요한 건 안정 상태의 76MB가 아니라 요청이 겹칠 때의 peak 122MB다. 메모리는 요청이 끝난 뒤 어느 정도 수렴하지만, 동시에 여러 요청이 들어오면 각 요청의 작업 메모리가 겹치면서 peak는 커진다.

이 숫자로 8월의 OOM을 되짚으면 앞뒤가 맞는다. 500행만으로도 heapUsed가 약 9.6MB 증가했으니, 54,565행이면 GB 단위까지 커질 수 있다.

정리

세 번 원인을 좁히는 동안 두 번 틀렸다. 돌아보니 이유는 비슷했다. 측정하기 전에 설명부터 만들었다.

시간이 맞으면 원인이라고 생각했다. OCR 세 건 뒤에 죽었으니 OCR이라고 봤다. 정작 죽은 프로세스가 뭘 하고 있었는지는 사흘 뒤에야 셌다.

고쳐놓고 나아졌는지도 바로 확인하지 않았다. OCR을 격리한 뒤에도 이틀을 더 죽고 나서야 첫 번째 가설이 틀렸다는 걸 인정했다.

그럴듯한 설명일수록 검증을 건너뛰었다. 네이티브 엔진이 메모리를 안 놓는다는 건 증상과 아귀가 맞았고 같은 보고도 많았다. 그래서 정작 운영에 어떤 버전이 올라가 있는지를 확인하지 않았다. node_modules를 한 번 뒤지면 끝날 일이었다.

답을 준 건 전부 실측이었다. 로그의 줄 수를 센 것, 설치된 버전을 확인한 것, 조회 행수를 센 것, 같은 코드를 480번 돌린 것. 어려운 건 하나도 없었다. 어려운 설명을 만들기 전에 쉬운 확인부터 했어야 했다.

임기호

다음 포스트