개요
본 문서는 Next.js Amplify 빌드 중에 발생한 메모리 관련 이슈를 다루고 있습니다.
장애 해결 방법
Node.js GC*, Scavenge, Mark-Sweep 이해
Next.js GC Log 분석 기반으로 OldSpace Size 지정
에러 메세지
Amplify로 배포를 하던 와중 아래와 같은 에러가 발생했습니다.
2024-08-29T02:21:19.390Z [WARNING]: <--- Last few GCs --->
[4009:0x6e9c850] 53705 ms: Mark-sweep (reduce) 2045.1 (2082.7) -> 2044.8 (2083.4) MB, 565.3 / 0.0 ms (+ 72.8 ms in 20 steps since start of marking, biggest step 5.0 ms, walltime since start of marking 657 ms) (average mu = 0.239, current mu = 0.259) a[4009:0x6e9c850] 54513 ms: Mark-sweep (reduce) 2046.0 (2083.4) -> 2044.7 (2083.4) MB, 802.6 / 0.0 ms (average mu = 0.130, current mu = 0.008) allocation failure; scavenge might not succeed
<--- JS stacktrace --->해당 이슈는 Node.js GC*의 OldSpace가 부족해서 발생한 문제로
문제가 발생한 dev 망의 OldSpace 크기를 증가시켜서 에러 해결했습니다.
NODE_OPTIONS="--max-old-space-size=4096"이후 문제 발생 원인 및 할당할 OldSpace 계산을 위한 리서치 진행했습니다.
문제 발생 원인 분석을 위한 Node.js에서 GC, Scavnege, Mark-Sweep 개요
할당할 OldSpace 계산을 위한 Next.js에서 GC Log 확인하고 디버깅하기
Node.js에서 GC, Scavenge, Mark-sweep 개요
Node.js에서는 메모리 관리를 위해서 GC*를 사용하며,
내부적으로는 Scavenge*, Mark-Sweep* 등이 사용됩니다.
이 과정을 추적하기 위해서 --trace-gc 옵션을 사용할 수 있습니다.
실제 배포 중인 어플리케이션에 대해서 아래와 같이 --trace-gc를 사용해보았습니다.
node --trace-gc ./.next/standalone/server.js그 결과 아래와 같은 GC 과정을 추적할 수 있게 되었습니다.
[10251:0x130008000] 32 ms: Scavenge 4.6 (4.8) -> 4.2 (5.8) MB, 0.3 / 0.0 ms (average mu = 1.000, current mu = 1.000) allocation failure; 기준값 | 예시 |
|---|---|
실행 중인 프로세스의 PID | 10251 |
JS 힙 인스턴스(Isolate) | 0x130008000 |
프로세스가 시작된 이후의 시간(ms) | 32ms |
GC의 유형/단계 | Scavenge |
GC 전 사용된 Heap | 4.6 |
GC 전 총 Heap | 4.8 |
GC 후 사용된 Heap | 4.2 |
GC 후 총 Heap | 5.8 |
GC에 소요된 시간 | (평균 mu = 1.000, 현재 mu = 1.000) |
GC 이유 | allocation falure; |
Node.js의 GC*
Garbage Collector의 약자로 Trash talk: the Orinoco garbage collector를 참고해주세요.
Node.js의 Scavenge*
GC*는 Scavenge 작업을 통해서 GC* 대상이 아닌 Objects를 OldSpace로 승격시킵니다. 이렇게 승격된 Objects들은 Mark-Sweep 과정에서 빈 메모리로 치환될 수 있습니다.
전체 과정은 Sample Scavenge Senario를 참고해주세요.
Node.js의 Mark-Sweep*
Mark*와 Sweep으로 구분된 작업이 진행됩니다.
OldSpace의 Live Objects/Dead Objects를 구분하는 마킹 작업을 진행합니다.
Dead Objects들을 스캔하여 이들을 빈 메모리로 변환합니다.
전체 과정은 Mark State를 참고해주세요.
Node.js GC Logs 분석하기
실제로 빌드된 Next.js Application을 실행하면,
지속적으로 Scavenge 작업이 이루어지면서 점점 더 많은 Heap을 사용하다가
MarkSweep 단계에서 OldSpace의 Dead Objects가 수거되어 더 적은 Heap으로 감소되는 것을 볼 수 있습니다.
[11770:0x140008000] 21 ms: Scavenge 4.6 (4.8) -> 4.2 (5.8) MB, 0.2 / 0.0 ms (average mu = 1.000, current mu = 1.000) allocation failure;
[11770:0x140008000] 28 ms: Scavenge 5.1 (6.3) -> 4.8 (7.1) MB, 0.2 / 0.0 ms (average mu = 1.000, current mu = 1.000) allocation failure;
[11770:0x140008000] 35 ms: Scavenge 6.4 (7.7) -> 6.0 (10.4) MB, 0.3 / 0.0 ms (average mu = 1.000, current mu = 1.000) allocation failure;
[11770:0x140008000] 43 ms: Scavenge 8.1 (10.4) -> 7.1 (11.2) MB, 0.3 / 0.0 ms (average mu = 1.000, current mu = 1.000) allocation failure;
[11770:0x140008000] 65 ms: Scavenge 9.2 (11.6) -> 8.5 (12.6) MB, 2.7 / 0.0 ms (average mu = 1.000, current mu = 1.000) allocation failure;
[11770:0x140008000] 90 ms: Scavenge 9.9 (12.6) -> 8.8 (17.3) MB, 0.7 / 0.0 ms (average mu = 1.000, current mu = 1.000) allocation failure;
[11770:0x140008000] 113 ms: Scavenge 13.6 (19.1) -> 11.6 (20.3) MB, 0.3 / 0.0 ms (average mu = 1.000, current mu = 1.000) allocation failure;
[11770:0x140008000] 143 ms: Scavenge 19.4 (24.0) -> 17.3 (25.5) MB, 0.5 / 0.0 ms (average mu = 1.000, current mu = 1.000) allocation failure;
Listening on port 3000 url: http://localhost:3000
[11770:0x140008000] 150 ms: Mark-sweep 17.9 (25.5) -> 15.9 (34.2) MB, 1.4 / 0.0 ms (+ 0.5 ms in 10 steps since start of marking, biggest step 0.1 ms, walltime since start of marking 7 ms) (average mu = 1.000, current mu = 1.000) finalize incremental marking via stack guard; GC in old space requested
[11770:0x140008000] 273 ms: Scavenge 36.2 (45.2) -> 30.2 (45.2) MB, 3.1 / 0.0 ms (average mu = 1.000, current mu = 1.000) allocation failure;
[11770:0x140008000] 288 ms: Mark-sweep 31.0 (45.5) -> 29.3 (63.2) MB, 2.0 / 0.0 ms (+ 0.3 ms in 9 steps since start of marking, biggest step 0.1 ms, walltime since start of marking 15 ms) (average mu = 0.984, current mu = 0.984) finalize incremental marking via stack guard; GC in old space requested
[11770:0x140008000] 332 ms: Scavenge 47.0 (64.7) -> 33.3 (64.7) MB, 0.6 / 0.0 ms (average mu = 0.984, current mu = 0.984) allocation failure;
[11770:0x140008000] 396 ms: Scavenge 48.5 (66.2) -> 35.8 (68.0) MB, 1.0 / 0.0 ms (average mu = 0.984, current mu = 0.984) allocation failure;
[11770:0x140008000] 430 ms: Scavenge 51.8 (69.2) -> 38.8 (71.0) MB, 0.6 / 0.0 ms (average mu = 0.984, current mu = 0.984) allocation failure;
[11770:0x140008000] 492 ms: Scavenge 54.3 (72.0) -> 41.2 (74.0) MB, 0.6 / 0.0 ms (average mu = 0.984, current mu = 0.984) allocation failure;
[11770:0x140008000] 522 ms: Scavenge 56.9 (74.5) -> 43.2 (76.2) MB, 0.6 / 0.0 ms (average mu = 0.984, current mu = 0.984) allocation failure;
[11770:0x140008000] 588 ms: Scavenge 59.1 (76.7) -> 45.4 (78.0) MB, 0.6 / 0.0 ms (average mu = 0.984, current mu = 0.984) allocation failure;
[11770:0x140008000] 618 ms: Scavenge 61.3 (78.9) -> 47.6 (80.7) MB, 0.8 / 0.0 ms (average mu = 0.984, current mu = 0.984) allocation failure;
[11770:0x140008000] 714 ms: Scavenge 67.4 (85.3) -> 55.5 (85.8) MB, 4.1 / 0.0 ms (average mu = 0.984, current mu = 0.984) allocation failure;
[11770:0x140008000] 800 ms: Mark-sweep 60.6 (87.0) -> 49.2 (87.1) MB, 3.0 / 0.0 ms (+ 9.4 ms in 167 steps since start of marking, biggest step 1.5 ms, walltime since start of marking 13 ms) (average mu = 0.977, current mu = 0.976) finalize incremental marking via task; GC in old space requested
[11770:0x140008000] 8902 ms: Mark-sweep (reduce) 49.2 (87.1) -> 48.4 (52.7) MB, 4.9 / 0.0 ms (+ 7.2 ms in 113 steps since start of marking, biggest step 0.2 ms, walltime since start of marking 13 ms) (average mu = 0.998, current mu = 0.999) finalize incremental marking via task; GC in old space requested
[11770:0x140008000] 9523 ms: Mark-sweep (reduce) 48.5 (52.7) -> 47.4 (51.5) MB, 4.2 / 0.0 ms (+ 12.9 ms in 136 steps since start of marking, biggest step 0.7 ms, walltime since start of marking 19 ms) (average mu = 0.994, current mu = 0.973) finalize incremental marking via task; GC in old space requested
[11770:0x140008000] 10151 ms: Mark-sweep (reduce) 47.4 (51.5) -> 45.7 (51.0) MB, 7.8 / 0.0 ms (+ 17.2 ms in 128 steps since start of marking, biggest step 1.3 ms, walltime since start of marking 27 ms) (average mu = 0.987, current mu = 0.960) finalize incremental marking via task; GC in old space requested최종적으로 Mark-Sweep이 완료되는 시점에는 51.0 MB가 되므로,
OldSpace의 크기를 50보다 낮게하면 에러가 발생하고 55보다 크게하면 에러가 나지 않을 것입니다.
에러 발생
node --trace-gc --max-old-space-size=50 ./.next/standalone/server.js정상 실행
node --trace-gc --max-old-space-size=55 ./.next/standalone/server.js
즉 GC* Logs를 활성화하고 이를 분석하면
Node.js Application이 실행되기 위한 최소 OldSpace를 판단할 수 있습니다.
또한 이 값을 기준으로 GC*가 많거나 Overhead*가 발생하고 있는지 알 수 있습니다.
메모리 누수를 수정한 이후 Mark-Sweep이 더 적게 발생하고
GC 후 총 Heap이 더 작은 사이즈라면 메모리 사용량이 개선된 것입니다.
Next.js에서 GC Log 확인하고 디버깅하기
Next.js를 사용하게 되면 아래의 스크립트를 사용하게 됩니다.
next build
next start따라서 build, start 단계에서 메모리 현황을 추적할 필요가 있습니다.
이 경우에는 --experimental-debug-memory-usage을 next.js 14.2.0 upper버전에서 지원하고 있습니다.
공식 문서에서는 다음의 명령어를 통해서 HeapProfile을 생성하는 것을 안내합니다.
node --heap-prof node_modules/next/dist/bin/next build하지만 저희는 다음 명령어를 사용해서 Scanvege, Mark-Sweep을 확인하고자 합니다.
node --trace-gc node_modules/next/dist/bin/next build
node --trace-gc node_modules/next/dist/bin/next start해당 내용을 기반으로 GC 후 총 Heap을 확인하면 다음의 결론을 얻을 수 있습니다.
Next.js Application Build에는 1617 * 1.1(여유) 크기의 OldSpace 필요
Next.js Application Start에는 48.2 * 1.1(여유) 크기의 OldSpace 필요
따라서 다음과 같은 스크립트를 지정하는 것이 옳아보입니다.
node --trace-gc --max-old-space-size=1780 node_modules/next/dist/bin/next build # 1778.1
node --trace-gc --max-old-space-size=53 node_modules/next/dist/bin/next start # 53.02
