메모리 덤프 분석을 통한 스크래핑 서버 논리적 메모리 누수 99% 개선

저희 팀은 금융사·쇼핑몰 데이터를 수집하는 스크래핑 서버를 운영하고 있습니다. 어느 날 여러 대의 스크래핑 서버 중 3번 서버 한 대만 메모리를 1GiB 가까이 쥔 채 21시간 동안 돌려주지 않는 일이 있었습니다. 애플리케이션을 재기동하고 나서야 다른 서버와 같은 수준으로 돌아왔습니다.

 

 

GC 가 있는 런타임에서 "메모리가 돌아오지 않는다"는 말은 보통 두 가지 중 하나입니다. 누군가 아직 그 객체를 참조하고 있거나, 참조는 끊겼는데 런타임이 OS 에 반납하지 않고 있거나. 이번 글은 지표와 메모리 덤프로 이 둘을 가르고, 결국 문자열을 str[i] 로 한 글자씩 읽는 평범한 코드 한 줄이 static 캐시에 정수 키를 967만 개 쌓아 둔 논리적 메모리 누수였다는 것을 밝혀낸 기록입니다.

 

논리적 메모리 누수(logical memory leak) : GC 가 있는 언어에서, 더 이상 쓰지 않는 객체가 GC 루트에서 여전히 닿을 수 있는 상태로 남아 회수되지 못하는 것. 메모리를 "잃어버린" 것이 아니라 "놓지 못한" 것입니다.

 

글은 배경 및 문제 상황 → 작업 및 행동 → 결과 및 성과 순서로 정리해보겠습니다.

 

 

 

🚩배경 및 문제 상황

 

1️⃣들어가기 전에: JS 를 실행하는 C# 엔진

이 글에는 "JS 엔진", "속성 키", "캐시" 같은 말이 계속 나옵니다. 사내 애플리케이션은 TypeScript 로 작성한 비즈니스 로직을 JavaScript 로 빌드해 두고, 기동할 때 그 JS 를 읽어 두었다가 요청이 오면 해당 함수를 실행합니다.

 

[그림 1] C#(.NET 10)으로 만든 자체 JS 엔진으로 비즈니스 로직이 존재하는 JS 스크립트를 실행

 

 

Chrome 이나 Node.js 가 V8 엔진으로 JS 를 실행하듯, 저희는 C#(.NET 10)으로 만든 자체 JS 엔진으로 JS 를 실행합니다.

그래서 JS 코드가 만드는 객체도, 엔진 내부의 캐시도 모두 .NET 관리 힙(managed heap)에 생기고 .NET GC 가 관리합니다. 이번 사고를 dotnet-dump 같은 .NET 진단 도구로 추적할 수 있었던 이유입니다.

 

2️⃣3번 서버만 메모리가 돌아오지 않았다

10월 1일 19시 25분경 3번 서버의 가용 메모리가 1.4GiB 에서 0.48GiB 로 약 1GiB 떨어진 뒤 회복되지 않았습니다. 업무가 거의 없는 야간과 새벽에도, 다음 날 업무 시간에도 0.5GiB 안팎에 머물렀고, 다른 스크래핑 서버들은 평소와 같았습니다. 이 상태는 약 21시간 이어지다가 10월 2일 17시경 애플리케이션을 재기동하고 나서야 풀렸습니다.

 

[그림 2] 10/01 ~ 10/02 대시보드. 오른쪽 아래 Free Memory 에서 노란 선(3번)만 10/01 저녁에 떨어져 재기동 전까지 그대로입니다

 

항목	값
3번 서버 가용 메모리 (10-01 19:25)	1.4 GiB → 0.48 GiB (약 1 GiB 감소)
회복되지 않고 유지된 시간	약 21시간 (10-02 17시 재기동까지)
서버 사양	4코어 / 8GB
같은 역할 서버 중 증상이 난 서버	3번 1대

 

3️⃣Grafana 지표로 범위 좁히기

가용 메모리가 떨어진 19시 25분 앞뒤 5분을 확대해 봤습니다.

 

[그림 3] 19:23 ~ 19:28 확대

• 메모리 : 19시 25분 26초부터 3번만 가용 메모리가 1.5GiB → 0.5GiB 로 떨어졌습니다.
• CPU : 같은 시각 약 20%p 올라 55 ~ 58% 구간에서 약 40초 머물렀습니다(최고 58.4%).
• Paging File : 약 8% → 12% 로 올랐습니다.
• Processor Queue Length : 7번 서버와 비슷했습니다.

토픽 여러 개를 동시에 소비해서 일이 많아진 것이라면 대기 큐 길이도 함께 늘어야 합니다. 그런데 그렇지 않았으니 "토픽 메세지 여러 개"가 아니라 토픽 메세지 하나에서 무거운 연산이 일어났다고 추정했습니다.

 

[그림 4] 같은 5분의 네트워크. 19:25:30 에 3번 서버 수신 26.3Mb/s, 약 50초 뒤 송신 스파이크

 

네트워크에서도 같은 그림이 나왔습니다. 19시 25분 30초에 3번 서버로 26.3Mb/s 수신 스파이크(같은 시각 7번은 12.5kb/s)가 있었고, 약 50초 뒤 3번만 약 17Mb/s 송신 스파이크가 있었습니다.

 

 

수신은 외부 수집처에서 매우 큰 응답을 받았다는 뜻이고, 송신은 그 결과를 워커 서버에 넘기려고 메시지 큐 테이블에 큰 쓰기를 했다는 뜻으로 해석했습니다.

 

4️⃣시작점은 고도몰 주문 수집 한 건

외부 응답 크기를 직접 남기는 지표는 없어서, 그 시각에 존(Zone: 사내에서 쓰는 운영 구역)별로 메시지 큐로 발행된 토픽을 모니터링 하는 메뉴로 조회해 봤습니다. 대부분의 존은 10개 미만이었는데, 한 회사에서만 19시 26분 22초에 토픽 385개가 한꺼번에 발행됐습니다. 발행한 서버는 역시 3번이었습니다.

[그림 5] 워커에 데이터를 저장하는 토픽의 발행 서버가 모두 스크래핑 3번서버

 

 

토픽 메세지를 확인해 보니 쇼핑몰 중에 제공하는 외부수집처인 고도몰 주문 수집 1건이었습니다. 조회를 통해 얻은 수집 데이터 결과는 10건씩 잘라 토픽 하나로 발행하므로, 385개 토픽 메세지면 한 번에 최대 3,850건을 수집했다는 뜻입니다. 게다가 고도몰은 응답을 JSON 이 아니라 XML 로 줘서 태그 때문에 응답이 훨씬 큽니다.

수신 트래픽이 그렇게 컸던 이유가 여기서 설명됩니다.

 

 

하지만 이것으로 설명되는 건 "수집하는 동안 메모리를 많이 썼다"까지입니다. 수십 MB 응답이 UTF-16 문자열로 두 배가 되고, 필터를 거친 복사본과 XML DOM 까지 한꺼번에 생기니 순간적으로 커지는 건 자연스럽습니다. 작업이 끝난 뒤에도 21시간 동안 돌려주지 않은 것은 전혀 다른 문제였습니다.

 

 

 

5️⃣ 덤프를 뜨기 전에 세운 가설

고도몰 수집 비즈니스 로직(TS)과 쇼핑몰 공통 로직을 읽어 봤지만, 수집 데이터를 static 이나 모듈 전역에 들고 있는 코드는 없었습니다. 그래서 가설을 세 개 세웠습니다.

가설	내용	당시 판단
① 살아 있는 참조	어딘가에서 큰 응답 문자열이나 XML DOM 을 계속 참조하고 있다	비즈니스 코드에서는 못 찾음. 프레임워크·엔진 쪽은 미확인
② LOH 조각화 / 힙 미반납	참조는 끊겼지만 수십 MB 문자열이 LOH 에 올라갔다 빠지며 조각나, 빈 공간을 OS 에 돌려주지 못한다	처음에는 가장 유력
③ 네이티브 메모리	GC 가 관리하지 않는 네이티브 버퍼가 남아 있다	덤프 없이는 가릴 수 없음

 

그런데 서버의 runtimeconfig.json 을 보니 GC 설정이 없어 Workstation GC 기본값으로 돌고 있었습니다. "회수는 했는데 OS 에 바로 돌려주지 않는" 성향은 코어마다 힙을 크게 잡는 Server GC 쪽 이야기이고, 게다가 21시간 동안 가용 메모리가 바닥이었으니 GC 는 그사이 여러 번 돌았을 겁니다. 그런데도 1GiB 가 그대로였다면 ② 보다는 ① 살아 있는 참조 쪽에 무게가 실렸습니다.

 

 

다만 누가 쥐고 있는지는 코드를 눈으로 쫓아서는 가릴 수 없었습니다. 그래서 같은 현상을 일부러 재현하고, 그 순간의 힙을 덤프로 떠서 직접 보기로 했습니다.

 

 

 

🔍작업 및 행동

 

1️⃣측정 도구: 추이 2개 + 덤프

덤프는 한 순간의 사진이라, 그것만으로는 "재현이 됐는지"조차 알 수 없습니다. 그래서 시간 흐름을 남기는 도구 두 개를 함께 켜 두고, 정해진 시점에 덤프를 떴습니다.

도구	남기는 것	답하는 질문
typeperf	프로세스 Private Bytes, Working Set, 서버 가용 메모리, CPU 를 5초마다	OS 관점. 언제, 얼마나 늘고 줄었나
dotnet-counters	세대별 GC 힙 크기, GC 횟수, 멈춤 시간, 할당량을 5초마다	런타임 관점. 관리 힙이 늘었나, GC 는 돌았나
dotnet-dump	그 순간의 프로세스 메모리 전체(.dmp)	힙 안. 무슨 객체가 몇 개 있고 누가 참조하나

typeperf "\Process(<프로세스명>)\Private Bytes" "\Process(<프로세스명>)\Working Set" "\Memory\Available MBytes" "\Processor(_Total)\% Processor Time" -si 5 -o mem.csv
dotnet-counters collect -p <PID> --counters System.Runtime --refresh-interval 5 --format csv -o counters.csv
dotnet-dump collect -p <PID> -o dump2_after.dmp

 

Private Bytes 와 GC 힙을 같이 보면 방향이 정해집니다. Private Bytes 만 오르고 GC 힙이 그대로면 네이티브 메모리, 둘이 같이 오르면 관리 힙에 살아 있는 참조가 있다는 뜻입니다.

작업 관리자나 tasklist 의 메모리 값(Working Set)은 쓰지 않았습니다. 메모리가 부족한 서버에서는 디스크로 밀려나 줄어든 것처럼 보일 수 있기 때문입니다.

 

2️⃣재현 환경: 목서버와 큰 응답

운영 서버에서 일부러 사고를 낼 수는 없으니 테스트 스크래핑 서버에서 같은 상황을 만들었습니다.

1. 응답 파일 : 실제 고도몰 주문 데이터 조회 HTTP Response 하나를 꺼내, 헤더와 메타 정보는 그대로 두고 주문 목록만 사고 당시 수준(3,850행)으로 늘렸습니다.
2. 목서버 : 제 PC 에 작은 Node.js 서버를 띄워, 요청이 오면 그 파일을 XML 로 응답하게 했습니다. 테스트 서버가 네트워크를 타고 제 PC 로 요청을 보내게 해서 실제 통신과 최대한 비슷하게 맞췄습니다.
3. 임시 빌드 : 고도몰 신규 주문 조회 URL 만 목서버 주소로 바꿔 테스트 서버에 배포했습니다. 응답을 받은 뒤의 처리 경로는 운영과 같습니다.

 

[그림 6] 재현 환경. 바꾼 것은 "요청이 가는 주소" 하나

3️⃣테스트 시나리오

1. 기록 시작 + 워밍업 : typeperf, dotnet-counters 를 켜 두고 카드·은행·쇼핑몰 조회를 여러 번 돌려 메모리가 평평해질 때까지 기다립니다. 기동 직후의 자연스러운 증가를 수집 때문으로 오해하지 않기 위해서입니다.
   
   
2. 수집 전 덤프 : 작업이 없는 순간에 뜹니다. "원래 있던 것"과 "새로 생긴 것"을 가르는 기준입니다.
   
   
3. 고도몰 수집 1회 : 목서버 콘솔에 요청과 응답 크기가 찍히는지 봅니다.
   
   
4. +10분 덤프 : 그사이 다른 조회를 몇 번 돌려 GC 가 돌 기회를 줍니다. GC 는 시간이 지난다고 도는 게 아니라 할당이 쌓여야 돌기 때문입니다. "아직 GC 가 안 돌아서 남은 것"과 "GC 가 돌아도 남는 것"을 가르기 위한 덤프입니다.
   
   
5. +30분 덤프 : 다시 요청을 보내고 마지막 덤프를 뜹니다. "잠시 남은 것"인지 "영구히 남는 것"인지를 판단합니다.

판정 기준은 실험 전에 정해 뒀습니다. 수집 10분 뒤 메모리가 기준선으로 돌아오면 재현 실패, 올라간 채 유지되면 재현 성공입니다.

 

4️⃣1차 재현(30MB): 테스트 서버가 쓰러졌다

운영과 최대한 같게 하려고 30MB 응답으로 시작했는데, 테스트 스크래핑 서버가 버티지 못했습니다. 운영 서버는 4코어 / 8GB 인데 테스트 서버는 4코어 / 4GB 였고, 수집 전부터 가용 메모리가 약 0.9GB 뿐이었습니다. (이 일 뒤로 인프라 팀에서 애초에 가용메모리가 너무 적은 것 같다고 테스트 서버도 8GB 로 늘려 주셨습니다.)

 

 

엄밀히는 .NET 의 OutOfMemoryException 이 아니라 서버 전체 메모리가 고갈되어 원격 세션까지 무너진 것입니다. .NET 은 기본적으로 힙 상한이 없어서 프로세스는 조용히 계속 커지고, 서버의 다른 프로세스가 먼저 죽습니다.

 

 

그런데 이 실패한 실험이 오히려 결정적인 자료를 남겼습니다. "아직도 안 끝나네?" 싶어 수집 도중에 떠 둔 중간 덤프(5.85GB)에, 메모리를 붙잡고 있는 객체와 그 순간 실행 중이던 함수가 그대로 찍혀 있었습니다. 이 덤프에서 캐시 노드는 이미 약 2,039만 개였습니다. 뒤에서 다시 이야기하겠습니다.

 

5️⃣2차 재현(10MB): 재현 성공

응답을 10MB 로 줄이자 수집은 정상 완료됐고(토픽 134건 발행), 10분 뒤와 30분 뒤 덤프도 온전히 떴습니다.

시점	Private Bytes	GC 2세대 힙	서버 가용 메모리
21:16 워밍업 중	1,715 MB	1,627 MB	1,126 MB
21:20 수집 시작	1,780 MB	1,638 MB	564 MB
21:23 수집 중 최고점	3,721 MB	3,355 MB	74 ~ 400 MB
21:38 +10분 덤프 직전	3,420 MB	3,087 MB	927 MB
21:43 72초짜리 전체 GC 뒤	3,305 MB	3,034 MB	940 MB
22:11 기록 종료	3,306 MB	3,050 MB	297 MB

수집이 끝난 뒤 전체 GC 가 21:41, 21:43, 22:02 세 번 돌았고, 21:43 의 것은 72초 동안 워커를 멈춘 blocking GC 였습니다. 그런데도 2세대 힙은 약 3,034MB 에 고정됐습니다. 기준 대비 약 1,407MB 가 GC 를 세 번 거치고도 남은 것입니다.

Private Bytes 증가 1,585MB 중 GC 힙 커밋 증가가 1,521MB 였으니 네이티브 메모리(가설 ③)는 주 원인이 아니었습니다. 관리 힙 안에 무언가가 살아 있다는 뜻이고, 이제 덤프에서 찾으면 됩니다.

 

6️⃣덤프 분석: 큰 것에서 작은 것으로

아래는 수정 전 재현의 30분 뒤 덤프를 분석한 과정입니다. 보다가 자세하게 메모리 덤프를 분석했던 내용은 따로 글로 작성해뒀습니다. 아래 글에서 보실 수 있습니다.

https://programmer-may.tistory.com/286

메모리 덤프 직접 열어 보기 : dotnet-dump analyze와 WinDbg 로 메모리 누수 추적하기

 

 

① 힙이 얼마나 큰가 — eeheap -gc

관리 힙의 전체 크기, 세대별 영역, GC 모드를 한 번에 보여 주는 명령입니다. 이 덤프가 정말 문제 상태를 찍은 것인지부터 확인합니다.

[그림 7] eeheap -gc 아래쪽. GC Allocated Heap Size 3,360,537,568 bytes(3.3GB)

• Number of GC Heaps: 1 → 힙이 하나이니 Workstation GC 가 맞습니다(Server GC 면 코어 수만큼 나옵니다).
• 2세대(generation 2) 영역 줄이 화면을 가득 채웁니다. 오래 살아남은 객체가 쌓여 있다는 뜻입니다.
• GC Allocated Heap Size 3,360,537,568 B (약 3.36 GB). 수집 전 약 1.7GB 의 두 배입니다.
• Large object heap 영역 중 하나가 95,991,648 B(약 96 MB)인데, 이게 뒤에서 나올 버킷 배열입니다.

 

② 무슨 타입이 차지하고 있나 — dumpheap -stat

힙 전체를 훑어 타입별 개수와 총 바이트를 집계합니다. 크기 오름차순이라 맨 아래가 가장 큰 타입입니다.

[그림 8] dumpheap -stat 맨 아래 네 줄

 

타입	개수	총 크기
System.Int32	약 968만 개 (9,677,949)	232,270,776 B (약 232 MB)
JSKey	약 978만 개 (9,778,329)	391,133,160 B (약 391 MB)
System.String	약 1,006만 개 (10,062,683)	392,637,270 B (약 393 MB)
ConcurrentDictionary<Object, JSKey>+Node	약 978만 개 (9,777,304)	469,310,592 B (약 469 MB)
힙 전체	약 5,847만 개 (58,470,268)	3,317,109,799 B (약 3.32 GB)

여기서 가장 중요한 관찰은 서로 다른 네 타입의 개수가 전부 970만 ~ 1,000만으로 비슷하다는 점입니다. 개수가 맞아떨어지면 "하나를 만들 때마다 나머지도 하나씩 따라 생기는 묶음"이라는 신호입니다. 네 줄만 더해도 약 1,485MB 입니다.

게다가 System.Int32 가 힙에 968만 개 있다는 것 자체가 이상합니다. 정수는 원래 힙 객체가 아닙니다. object 자리에 들어가느라 박싱(boxing)된 정수라는 뜻입니다. 총 바이트를 개수로 나누면 Node 48B, JSKey 40B, Int32 24B 입니다.

 

③ Node 하나를 열어 본다 — dumpheap -mt → dumpobj

타입 이름만으로는 안에 무엇이 들었는지 모릅니다. Node 줄의 첫 열이 타입 식별자인 MT(MethodTable) 입니다. 이 MT 로 객체 주소 목록을 뽑고, 그중 하나를 열어 봤습니다.

> dumpheap -mt 7ffe38582198 -short
> dumpobj 02c2319c4008

 

[그림 9] Node 하나. Size 48 bytes, 필드는 _key, _value, _next, _hashcode

 

Size 48 bytes 로 앞에서 나눠 본 값과 같고, 필드는 _key(object), _value(JSKey), _next(다음 Node), _hashcode(Int32) 네 개입니다. 목록 중간에서 고르게 22개를 뽑아 열어 보니 21개의 키가 정수였고, 값은 1,025 ~ 9,568,797 사이였습니다.

 

④ 누가 붙잡고 있나 — gcroot

GC 는 루트(static 필드, 스레드 스택, 핸들)에서 참조를 따라가 닿는 객체만 살려 둡니다. 어떤 객체가 안 지워진다면 루트에서 그 객체까지 경로가 있다는 뜻이고, gcroot 가 그 경로를 보여 줍니다. "누가 쥐고 있는가"에 직접 답하는 명령입니다.

> gcroot 02c2319c4008

 

[그림 10] gcroot 결과. Found 1 unique roots

 

HandleTable (strong handle)
  → System.Object[]
    → ConcurrentDictionary<Object, JSKey>        (02c15e8de438)
      → ConcurrentDictionary+Tables              (02c1fa6e6b98)
        → ConcurrentDictionary+VolatileNode[]    (02c207400048)
          → ConcurrentDictionary+Node            (02c2319c4008)

위에서 아래가 참조 방향입니다. strong handle → Object[] 는 런타임이 static 필드를 보관하는 배열입니다. 루트가 이것이면 "static 이 붙잡고 있다"는 뜻이고, 프로세스가 끝날 때까지 풀리지 않습니다. 경로도 하나뿐이니 보유자는 사전 하나입니다.

ConcurrentDictionary 클래스 객체를 사용하는 소스코드를 전체 검색 해보니 엔진 소스의 JSKey._cache 필드 자료형이 ConcurrentDictionary 이었습니다. 이 딕셔너리가  JSKey._cache 라고 추측 했습니다.

 

⑤ .NET 10 ConcurrentDictionary 는 어떻게 생겼나

다음 단계로 가기 전에 사전의 내부 구조를 잠깐 보겠습니다. .NET 10 의 ConcurrentDictionary<TKey, TValue> 소스를 보면 객체가 세 겹으로 되어 있습니다.

• 본체 : _tables, _budget, _growLockArray, _comparerIsDefaultForClasses, _initialCapacity. 실제 데이터는 _tables 가 가리키는 Tables 에 있습니다.
• Tables : _buckets(버킷 배열 VolatileNode[]), _locks(잠금 객체 배열), _countPerLock(잠금 구간별 항목 수), _comparer, _fastModBucketsMultiplier.
• Node : 항목 하나. _key, _value, 같은 버킷에 걸린 다음 항목 _next, _hashcode.

버킷 배열 전체를 잠금 몇 개로 나눠 맡기고, 각 잠금이 자기 구간의 항목 수를 _countPerLock 에 따로 셉니다. 그래서 Count 는 _countPerLock 의 값을 전부 더한 것입니다. 한 구간의 항목 수가 _budget(버킷 수 ÷ 잠금 수)을 넘으면 버킷 배열을 약 두 배로 키우고, 스스로 줄어들지는 않습니다.

 

[그림 11] 덤프에서 따라간 경로를 그림으로 옮긴 것. 키 하나마다 Node + 박싱 Int32 + JSKey + String 묶음이 생깁니다

 

⑥ 사전이 스스로 센 개수와 맞춰 본다 — dumpobj → dumparray

힙에서 센 Node 978만 개가 정말 전부 이 사전 하나에 들어 있는지 확인하려면, 사전이 직접 세어 둔 _countPerLock 을 열어 보면 됩니다.

> dumpobj 02c15e8de438               # 사전 본체 → _tables 주소
> dumpobj 000002c1fa6e6b98           # Tables → _buckets, _locks, _countPerLock 주소
> dumparray -details 000002c1fa6e6b70

 

[그림 12] 사전 본체와 Tables. _initialCapacity 1931, _budget 2,999,737

 

본체의 _initialCapacity 가 1931 입니다. 엔진 소스의 new ConcurrentDictionary<object, JSKey>(ProcessorCount(), 1931) 와 같아서, 소스 쪽에서도 이 사전이 _cache 임을 한 번 더 확인했습니다. _budget 2,999,737 은 버킷 11,998,949칸 ÷ 잠금 4개와 맞습니다.

 

[그림 13] _countPerLock 네 값

2,444,090 + 2,443,997 + 2,444,692 + 2,444,525 = 9,777,304

사전이 스스로 센 항목 수가 dumpheap -stat 에서 센 Node 수(9,777,304)와 정확히 일치합니다. 978만 개 Node 는 전부 이 사전 하나에 들어 있고, 다른 곳으로 새어 나간 것은 없습니다.

 

⑦ 다른 용의자를 지운다 — dumpheap -stat -min 1000000

남은 가설 ①(큰 응답 문자열이 붙잡혀 있다)과 ②(LOH 조각화)를 직접 확인하려고 1MB 이상인 객체만 봤습니다. 큰 문자열이 남아 있다면 여기 나오고, 조각화가 심하면 Free(빈 공간)가 크게 나옵니다.

 

[그림 14] 1MB 이상 객체는 13개뿐

• System.String 줄이 없습니다. 10MB 응답 문자열(UTF-16 으로 약 19MB)은 이미 회수됐습니다. 가설 ① 중 "응답 문자열을 붙잡고 있다"는 기각입니다.
• Free 는 9,453,840 B(약 9.45 MB). LOH 약 152MB 중 빈 공간이 10MB 도 안 되니 조각화가 아닙니다. 가설 ② 도 기각입니다.
• 가장 큰 객체는 VolatileNode[] 1개, 95,991,616 B(약 96 MB). 항목이 978만 개라 약 1,200만 칸까지 자란 사전의 버킷 배열입니다.

정리하면, 힙에 남은 1.4GB 의 정체는 static 필드 JSKey._cache 가 붙잡고 있는 정수 키 약 978만 개였습니다. 처음에 가장 유력하다고 봤던 LOH 조각화는 틀렸습니다.

 

7️⃣엔진 소스에서 JSKey 캐시 찾기

덤프가 알려 주는 것은 "지금 무엇이 있고 누가 붙잡고 있는가"까지입니다. "누가 만들었는가"는 담기지 않습니다. 그래서 엔진 소스에서 JSKey._cache 에 무엇이 들어가는지 찾아봤습니다.

JavaScript 에서 a[b] 는 "a 라는 객체에서 b 라는 이름의 속성을 읽어라"입니다. a 가 객체든 배열이든 문자열이든 문법은 하나이고, arr[3] 도 규격상으로는 이름이 "3" 인 속성을 읽는 것입니다. 엔진은 속성을 찾기 전에 그 이름을 내부 키 객체로 바꾸는데, 저희 엔진에서는 그게 JSKey 입니다.

// JSKey.cs - 제거 로직이 없는 static 사전
private static ConcurrentDictionary<object, JSKey> _cache = new ConcurrentDictionary<object, JSKey>(ProcessorCount(), 1931);
private static JSKey[] _indexCache = new JSKey[1025];

public static JSKey Intern(int key)
{
    if (key >= 0 && key <= 1024) {
        return _indexCache[key];                                   // 작은 정수: 미리 만든 것 재사용
    }
    return _cache.GetOrAdd(key, static (o) => new JSKey((int)o));  // 1025 이상: 사전에 영구 등록
}

 

속성 이름 키("orderNo" 같은 것)는 소스에 적힌 만큼만 있어서 캐시해 두면 이득이고, 실제로 약 10만 개에서 멈춥니다. 문제는 이 전제를 깨는 키, 즉 입력 데이터의 길이만큼 종류가 늘어나는 정수 키가 같은 캐시에 들어올 때입니다. 0 ~ 1024 는 고정 배열이 처리하지만 1,025 이상은 전부 _cache 에 영구 등록됩니다. 사전의 키 타입이 object 라서 정수는 박싱되고, JSKey 는 정수를 문자열로도 들고 있습니다. 덤프에서 본 Node · Int32 · JSKey · String 네 묶음이 정확히 이것입니다.

 

[그림 15] 속성이름키는 미리 캐싱, 정수 인덱스 키는 매번 캐싱. 심지어 캐싱 데이터가 없다면 매번 생성 후 캐싱

 

글자 하나에 생기는 객체	크기	왜 생기나
Node	48 B	사전의 항목 하나
박싱된 Int32	24 B	키 타입이 object 라서 정수를 포장
JSKey	40 B	캐시의 값
String	약 36 B	정수를 "2954227" 같은 문자열로도 보관
버킷 배열 지분	약 10 B	약 96MB 배열을 항목 수로 나눈 몫
합계	약 158 B	응답 100만 글자당 약 150MB 가 영구 점유

 

 

8️⃣고도몰 수집 로직에서 str[i] 찾기

이제 고도몰 수집 경로에서 1,025 이상 정수로 무언가[i] 에 접근하는 곳을 찾아야 했습니다. 로직을 따라가며 훑어 보는 와중 레거시 코드 중에  응답 전체를 글자 단위로 도는 코드는 XML 의 잘못된 문자를 걸러 내는 filterBadXMLCharactors 함수 하나를 발견했습니다. 1차 재현의 중간 덤프를 clrstack -all 로 보니 수집 스레드도 정확히 이 함수 안에 있었습니다.

// 수정 전
for (let i = 0; i < xml_string.length; i++) {
    current = xml_string.charCodeAt(i);          // 메서드 호출. i 는 인자일 뿐 → 키를 만들지 않음
    if (_.vIsEquals(current, [0x9, 0xa, 0xd]) || (current >= 0x20 && current <= 0xd7ff) || ...) {
        filtered_string.append(xml_string[i]);   // 속성 접근. i 가 속성 키가 됨 → 1,025 이상이면 영구 등록
    }
}

 

[그림 16] 대괄호 접근 한 번이 지나는 길. charCodeAt(i) 는 메서드 인자라 이 길을 타지 않습니다

 

10MB 짜리 XML 응답 문자열을 한 글자씩 xml_string[i] 로 읽으면서, 글자 번호마다 JSKey 를 하나씩 만들어 static 사전에 넣고 있던 것입니다. 이 추론을 숫자로 검증해 봤습니다.

 

 

다만 힙 덤프에는 키가 언제 들어왔는지 기록되지 않고, 같은 사전에 속성 이름 키까지 섞여 있습니다. 게다가 10MB 재현 때는 수집 전 덤프를 빠뜨려서, Node 수를 빼서 비교하면 다른 프로세스의 기준값을 써야 합니다. 그래서 정수 키에만 생기는 박싱된 Int32 개수로 맞춰 봤습니다. 사전의 키 타입이 object 라서 정수 키마다 박싱 객체가 하나씩 생기고, 문자열 키에는 생기지 않기 때문입니다.

항목	값
10MB 응답의 글자 수	약 967만 개 (9,673,214)
예측한 정수 키 수 : 글자 수 − 1,025 (고정 배열 몫)	약 967만 개 (9,672,189)
실측 : 수정 전 30분 뒤 덤프의 박싱 Int32	약 968만 개 (9,677,949)
실측 − 예측	5,760개
참고 : 수정 후 덤프 3장의 박싱 Int32 (정수 키가 쌓이지 않은 평소 값)	5,420 ~ 6,201개

실측이 예측보다 5,760개 많은데, 이 차이가 평소 박싱 Int32 개수 범위 안에 들어갑니다. 즉 "정수 키 약 967만 개 + 평소에 있던 Int32 약 5,800개"로 설명됩니다. 평소 값은 다른 프로세스에서 빌려 온 것이라 키를 하나하나 센 증명은 아니지만, 약 967만이라는 규모가 응답 글자 수와 일치합니다. "응답 문자열 전체를 0 부터 끝까지 [i] 로 읽은 루프"로 범위를 좁히기에는 충분했습니다.

 

 

이 누수는 횟수가 아니라 "지금까지 처리한 가장 긴 문자열"에 비례한다는 점도 특이합니다. 키가 글자 번호라서 같은 길이를 다시 처리하면 이미 있는 키를 씁니다. 그래서 평소 작업으로는 전혀 늘지 않다가, 유난히 긴 응답이 한 번 들어올 때만 계단처럼 오릅니다. 여러 대 중 3번 서버만 그랬던 것도 그 대량 응답을 처리한 서버가 3번뿐이었기 때문입니다.

 

9️⃣수정: 문자열을 인덱스 키로 읽지 않게 바꾸기

"이게 문제니 빼자"로 끝내기 전에, 이 필터가 왜 들어왔는지부터 확인했습니다. 예전에 고객이 주문 상품명에 XML 에 올 수 없는 제어 문자(0x08 등)를 넣어 XML 파싱 예외가 난 일이 있었고, 그런 문자를 미리 걸러 내려고 넣은 함수였습니다. 목적은 필요했고, 문제는 구현 방식과 "항상 호출"하는 조건이었습니다.

안	판단
xml_string[i] → charAt(i)	메서드 호출이라 키를 만들지 않아 누수는 막힙니다. 하지만 글자 단위 반복문과 "항상 호출"은 그대로입니다.
채택	먼저 파싱하고, 실패했을 때만 정규식으로 금지 문자를 지운 뒤 한 번 더 파싱합니다. 정상 응답은 반복문도 치환도 거치지 않고, 정규식 치환은 엔진의 C# 쪽에서 한 번에 처리되어 JS 키를 만들지 않습니다.

// 수정 후 (요지)
private static readonly INVALID_XML_CHARS = /[\x00-\x08\x0B\x0C\x0E-\x1F￾￿]/g;

static parseXml(response_body: string): XmlDocument {
    try {
        return ShoppingUtil.loadXml(xml_string);                                    // ① 정상 응답은 여기서 끝
    } catch {
        const stripped = xml_string.replace(ShoppingUtil.INVALID_XML_CHARS, '');   // ② 실패했을 때만 금지 문자 제거
        return ShoppingUtil.loadXml(stripped);
    }
}

 

쇼핑몰마다 각자 갖고 있던 XML 파싱 유틸도 이 공통 parseXml 하나로 모았습니다. 그리고 이 수정을 다시 테스트 서버에 배포해서, 유추한 원인이 진짜 원인이 맞는지 같은 시나리오로 똑같이 검증했습니다.

 

 

 

📊결과 및 성과

 

1️⃣같은 조건 재검증: 논리적 누수 99% 제거

조건은 같습니다. 같은 테스트 서버, 목서버의 같은 10MB 응답(주문 670개, 수집 1,340행)입니다. 다만 응답 안에 0x08 을 일부러 넣어서 첫 파싱이 실패하고 정규식 경로를 타게 했습니다. 즉 고친 코드가 실제로 실행되는 경우를 쟀습니다. 이번에는 수집 전, 10분 뒤, 30분 뒤 덤프 세 개를 모두 같은 프로세스에서 떴습니다.

 

[그림 17] 수집 시작을 0분으로 맞춰 겹친 Private Bytes. 빨강이 수정 전, 초록이 수정 후입니다

 

수정 전은 2분 만에 3,722MB 까지 올라 30분 뒤에도 3,300MB 에 머물렀고, 수정 후는 1,915MB 까지 잠깐 올랐다가 30초 안에 제자리로 돌아왔습니다.

지표	수정 전	수정 후	변화
캐시 Node 증가 (원인)	+약 967만 개 (+9,671,798)	+548개	99.99% 감소
캐시 버킷 배열	95,991,616 B (약 96 MB)	1,251,520 B (약 1.25 MB, 기동 때 그대로)	98.7% 감소
GC 힙 증가 (수집 전 → 30분 뒤)	+1,480 MB	+11 MB	99.3% 감소
Private Bytes 증가 (수집 전 → 30분 뒤)	+1,520 MB	+39 MB	97.4% 감소
Private Bytes 최고점	3,721 MB	1,915 MB	48.5% 감소
수집 구간 2세대 GC 멈춤 합계	40.6초 (최장 19.6초)	5.7초 (최장 3.2초)	86.0% 감소
수집 뒤 전체 GC	72초짜리 1회	없음	–
수집 구간 할당량	6.86 GB	0.31 GB	95.5% 감소
저장된 수집 행	1,340	1,340 (특수 문자 11건 기대값과 일치)	기능 동일

수집이 끝난 뒤에도 남던 GC 힙 1,480MB 가 11MB 로 줄었으니 논리적 메모리 누수의 99.3% 를 없앤 것입니다. 남은 11MB 도 캐시와는 관계가 없습니다. 캐시 Node 는 548개 늘었고 10분 뒤와 30분 뒤가 같았습니다. 응답 글자 수 967만과 무관한 수라서, 고도몰 플러그인 코드가 이 워커에서 처음 실행되며 등록된 속성 이름으로 보입니다.

기능도 깨지지 않았습니다. 응답에 심어 둔 특수 문자 케이스 11건(0x08, 0x01·0x0B·0x0C·0x1F, CDATA 안의 &, 결합 이모지, 탭·줄바꿈, U+200B·U+FEFF 등)을 DB 에서 꺼내 코드포인트 단위로 대조했고, 금지 문자만 지워지고 나머지는 그대로 들어왔습니다.

 

2️⃣덤프로 다시 확인: 증상이 아니라 원인이 사라졌다

"메모리가 안 늘었다"만 보고 끝낼 수도 있었지만, 메모리는 여러 이유로 안 늘 수 있습니다. 그래서 수정 전과 수정 후의 30분 뒤 덤프를 창 두 개에 나란히 열고 같은 명령을 쳤습니다.

[그림 18] dumpheap -stat 비교. 왼쪽이 수정 전, 오른쪽이 수정 후입니다

 

항목	수정 전	수정 후	변화
힙 객체 수	약 5,847만 개 (58,470,268)	약 1,951만 개 (19,513,305)	66.6% 감소
힙 크기	3,317,109,799 B (약 3.32 GB)	1,808,771,066 B (약 1.81 GB)	45.5% 감소
JSKey	약 978만 개 (9,778,329)	약 10만 개 (106,631)	98.9% 감소
캐시 Node	약 978만 개 (9,777,304)	약 10만 개 (105,606)	98.9% 감소

오른쪽에는 Int32·JSKey·String·Node 네 줄이 맨 아래에서 사라지고, 기동 때 읽은 JS 모듈의 구문 트리(AST) 타입이 맨 아래를 차지합니다. 이게 이 워커의 정상 상태입니다. 양쪽에서 변하지 않아야 할 AST 리터럴 객체 수(약 144만 개)가 거의 같다는 점이, 두 덤프를 나란히 비교해도 된다는 근거입니다.

[그림 19] dumpheap -stat -min 1000000 비교. 버킷 배열이 기동 때 크기 그대로입니다

원인이라고 지목한 바로 그 객체(캐시 Node)의 증가가 약 967만 개 → 548개로 바뀐 것을 확인했기 때문에, "원인이 사라져서 증상이 사라졌다"고 말할 수 있었습니다.

 

3️⃣운영 배포 후 3번 서버 가용 메모리

수정을 운영 스크래핑 서버에 배포한 뒤, 배포 전(10월 13일 15시)과 배포 후(10월 14일 15시) 같은 시각의 Free Memory 를 비교해 보면 3번 서버의 가용 메모리가 584 MiB → 1.20 GiB(약 1,229 MiB), 약 2.1배가 되었습니다.

[그림 20] 배포 전(10/13 15시)과 배포 후(10/14 15시)의 Free Memory

 

다만 같은 시각 다른 서버들의 값도 함께 올라서, 이 그림 한 장을 수정 효과의 증거로 삼지는 않았습니다. 효과의 근거는 앞의 같은 조건 재검증과 덤프 비교이고, 운영에서는 3번 서버가 다른 서버들과 비슷한 범위(1.20 / 1.37 / 1.44 GiB)로 돌아온 것을 확인한 정도로 봐 주시면 됩니다.

 

4️⃣엔진 팀에 건의: 1,024 를 넘는 정수 키는 캐싱하지 않기로

비즈니스 코드를 고친 것은 급한 불을 끈 것이고, 근본 원인은 엔진에 있었습니다. str[i] 는 ES5 부터 표준인 가장 흔한 표기이고, Node.js 나 브라우저에서는 10MB 문자열을 str[i] 로 돌아도 메모리가 쌓이지 않습니다. V8 은 정수 인덱스 속성을 이름 있는 속성(named properties)과 따로 "elements" 로 다루기 때문입니다. 저희 쪽은 누구든 평범하게 str[i] 나 arr[i] 로 큰 데이터를 도는 순간 같은 일이 재발할 수 있는 구조였습니다.

그래서 엔진을 담당하는 팀에 조사 내용과 함께 이렇게 건의했습니다.

속성 이름 키를 인터닝하는 건 같은 이름이 요청마다 반복되니 이득이지만, 큰 정수 키는 인터닝이 기대는 두 전제(키의 종류가 유한하다, 같은 키가 반복해서 쓰인다)를 모두 만족하지 않습니다. 1,025 이상 정수 키를 영구 캐시에 두는 게 의도한 설계인지 궁금합니다.

 

엔진 팀에서 내부 논의를 거친 결과, 정수 키는 1,024 를 넘으면 캐싱하지 않고 요청마다 JSKey 객체를 새로 만들어 반환하기로 했습니다. 큰 정수 키를 캐싱해서 얻는 이점보다 메모리를 무한히 잡아먹는 위험이 훨씬 크고, 매번 JSKey 를 만드는 쪽이 오히려 오버헤드가 낮다고 판단했다고 합니다. 제가 이해하기로도, 잠깐 쓰고 버려지는 작은 객체는 0세대 GC 에서 싸게 회수되니 static 사전에 쌓아 두고 버킷 배열까지 키우는 것보다 가볍습니다.

이 변경이 들어가면 특정 비즈니스 코드 한 곳이 아니라 엔진 위에서 도는 모든 코드에서 같은 종류의 누수가 생길 길이 막힙니다.

 

5️⃣덤프 분석 대시보드를 만들어 사내에 공유

이번 조사를 하면서 가장 손이 많이 간 건 csv 두 개를 엑셀로 그려 보고, 콘솔에서 dumpheap, gcroot, dumpobj 결과를 한 줄씩 읽고, 덤프 두 개를 창 두 개에 띄워 숫자를 눈으로 맞추는 일이었습니다. 다음에 누가 같은 일을 겪어도 이 과정을 반복하지 않도록, 자주 쓰는 명령의 결과를 그래프와 표, 노드·간선 그래프로 보여 주는 로컬 대시보드를 만들어 팀에 공유했습니다.

외부 의존성 없이 Node.js 서버 하나로 돌고, 서버가 덤프마다 dotnet-dump analyze 프로세스를 하나 띄워 두고 명령을 보낸 뒤 출력을 파싱해서 화면에 그립니다. 한 번 실행한 명령 결과는 텍스트로 캐시해서, 다음부터는 몇 분씩 기다리지 않고 바로 볼 수 있게 했습니다.

화면	보여 주는 것	쓰는 명령·파일
메모리 사용 타임라인	Private Bytes, Working Set, GC 힙을 한 축에 그리고 GC 발생 시각(세대별 점선), 덤프 생성 시각을 표시. GC 멈춤 시간, 할당량, 단편화, 스레드풀, 예외, CPU 보조 차트	mem.csv, counters.csv
덤프 파일 분석	세대별 힙 영역 막대, 타입별 메모리 표, 객체 목록, 참조 그래프, 객체 상세, 스레드 스택	eeheap -gc, dumpheap -stat / -mt / -min, gcroot, dumpobj, clrstack -all
메모리 사용 비교	여러 테스트의 csv 를 기준 시각(T0)에 맞춰 겹쳐 그림	mem.csv, counters.csv
덤프 파일 비교	덤프 두 개 이상의 타입 통계를 나란히 놓고 증감과 변화율 순으로 정렬	각 덤프의 dumpheap -stat
명령 콘솔	선택한 덤프에 임의의 SOS 명령 실행	syncblk, finalizequeue 등

 

① 메모리 사용 타임라인

 

[그림 21] 메모리 사용 타임라인. 위의 카드에 피크 값과 GC 횟수(gen0 631 / gen1 523 / gen2 13), 멈춤 합계 117.44초가 바로 나옵니다

 

수정 전 재현의 csv 두 개를 올리면, 이번 글 앞부분에서 표로 정리했던 내용이 한 화면에 나옵니다. 빨간 점선이 2세대 GC 이고, 초록 실선이 덤프를 뜬 시각입니다. GC 가 여러 번 돌았는데도 힙이 내려오지 않는 모양이 한눈에 보입니다.

 

[그림 22] 보조 차트. 72초짜리 GC 멈춤과 수집 구간의 할당량 폭증을 따로 볼 수 있습니다

 

② 덤프 파일 분석

[그림 23] eeheap -gc 결과를 세대별 막대로(Gen2 93%), dumpheap -stat 결과를 크기 내림차순 표로 보여 줍니다

 

[그림 24] gcroot 결과를 노드와 간선으로 그린 참조 그래프. 노드를 누르면 dumpobj 결과가 아래에 열립니다

 

콘솔에서 주소를 복사해 dumpobj 를 치고, 그 결과에서 다시 주소를 복사하던 일을 클릭 한 번으로 바꿨습니다. 앞에서 명령 세 번으로 따라간 사전 본체 → Tables → _countPerLock 경로도 그래프에서 노드를 차례로 누르면 됩니다.

 

③ 메모리 사용 비교 / 덤프 파일 비교

[그림 25] 수정 전(파랑)과 수정 후(초록)의 GC 힙을 수집 시작 시각(T0)에 맞춰 겹친 화면

 

[그림 26] 덤프 비교. Node 99%, JSKey 99%, Int32 100% 감소가 변화율 순으로 정렬됩니다

 

이번 글의 "결과" 표를 만들려고 덤프 두 개를 나란히 띄워 숫자를 맞추던 작업이, 덤프 두 개를 고르고 버튼 한 번 누르는 일이 됐습니다.

 

6️⃣결과 및 배운 점

1. "그냥 OO 이 이유겠지" 하고 고치지 않을 수 있었습니다.

코드를 읽어서 세운 가설은 셋이었고, 처음 가장 유력했던 LOH 조각화는 틀렸습니다. 지레짐작으로 GC 설정을 바꿔 배포했다면 효과 없는 수정을 운영에 올렸을 겁니다. 덤프는 "무엇이 메모리에 있고 누가 붙잡고 있는가"를 숫자로 보여 줬습니다.

2. 예측을 먼저 적고 실측과 맞췄습니다.

"글자 수 − 1,025 개의 정수 키가 쌓일 것"이라는 예측이 덤프의 박싱 Int32 개수와 들어맞았을 때 설명이 단단해졌습니다. 수정 뒤에도 "메모리가 안 늘었다"가 아니라 원인으로 지목한 객체의 개수를 다시 셌습니다.

3. 실패한 실험도 자료였습니다.

서버를 쓰러뜨린 1차 재현에서 "끝나면 뜨자"고 기다렸다면 아무것도 남지 않았을 겁니다. 이상하다 싶은 순간에 떠 둔 중간 덤프가 원인 객체와 실행 중인 함수를 함께 알려 줬습니다.

4. 캐시는 키의 종류가 유한할 때만 캐시입니다.

제거 로직이 없는 static 캐시에 입력 데이터에 비례하는 키가 들어오는 순간, 그건 캐시가 아니라 누수입니다. 그리고 그 원인은 str[i] 처럼 아주 평범한 코드였습니다.

GC 가 있다고 누수가 없는 게 아닙니다. GC 는 "닿을 수 없는 것"만 치워 줄 뿐, "닿을 수 있지만 쓸모없는 것"은 끝까지 지켜 줍니다.

 

 

 

참고 자료

• dotnet-dump - Microsoft Learn
• dotnet-counters - Microsoft Learn
• Workstation vs. server garbage collection - Microsoft Learn
• The large object heap on Windows systems - Microsoft Learn
• ConcurrentDictionary.cs (.NET 10) - dotnet/runtime
• Fast properties in V8 - V8 blog