grep

EKS 컨테이너 메모리 스파이크 추적기

여기어때

2026년 8월 27일

원문에서 보기 ↗

글. Remy(유정인) / 검색플랫폼개발팀

요약: EC2에서 EKS로 옮긴 뒤 두 시간마다 메모리가 500MB씩 튀었습니다. 원인은 로그 gzip 압축과 페이지 캐시였습니다.

안녕하세요. 검색플랫폼개발팀 레미입니다.

토요일 새벽 한 시가 다 된 시각에, 메모리 사용률이 90%를 넘었다는 알림을 받았습니다.

배포한 지 일주일쯤 된 시점이었습니다. 저희 API를 띄워둔 파드 여러 대의 메모리가 며칠에 걸쳐 조금씩 올라가고 있었고, 그중 한 대는 급하게 치솟은 뒤로 내려오지 않고 있었습니다. 더 두면 알림이 계속 울릴 것 같아 전부 재시작했습니다.

상황을 정리하면서, 저는 이번 것이 전에 본 것과 비슷한 패턴이라고 적었습니다.

쓰고 나서 그 한 줄이 눈에 걸렸습니다. 처음이 아니라는 뜻이었으니까요.

이 일만 붙들고 있을 수는 없었습니다. 다른 일을 하다가 틈이 나면 그래프를 다시 열어보는 식이었습니다. 그러다 원인이 잡힌 건 두 달쯤 뒤였고, 모든 서비스에 조치가 들어간 건 넉 달쯤 뒤였습니다.

그 사이에 힙 바깥 네이티브 메모리, GC 교체, ZGC 자체를 차례로 의심했습니다. 셋 다 아니었습니다.

1. 그 전에, 서버를 옮겼습니다

이 API는 원래 EC2 여러 대에서 돌았습니다. 젠킨스가 도커 이미지를 만들어 각 서버에 띄우는 방식이었고, 그때 컨테이너에는 메모리 상한도 CPU 상한도 없었습니다. docker-compose 파일에 그런 설정 자체가 없었으니까요. 서버 자원은 넉넉했고, 로그는 호스트 디스크에 쌓였고, 그 로그는 별도의 수집 프로그램이 따로 가져갔습니다.

그러다 EC2에 있던 API들을 EKS로 옮기게 됐습니다. 저희 팀만의 일은 아니었고, 비슷한 시기에 여러 팀이 각자의 API를 옮기고 있었습니다.

저희 팀에서 이관을 진행했고, 1월 중순의 어느 하루에 커밋 두 개가 들어갔습니다. 하나는 애플리케이션 쪽, 하나는 배포 매니페스트 쪽이었습니다. 그날 바뀐 것을 지금 다시 보면 이렇습니다.

사양을 줄인 건 실수가 아니었습니다. EC2 시절에는 서버를 넉넉하게 잡아 두고 러프하게 쓰고 있었거든요. 컨테이너에 상한이 없으니 굳이 맞출 이유도 없었고요. 이관 계획서에도 자원이 놀고 있고 그만큼 비용이 새고 있다는 진단이 적혀 있었고, 기대 효과 첫 줄은 비용 절감이었습니다. 파드에 걸 상한도 그 목표에 맞춰 잡았습니다. 처음 검토했던 8GB에서 절반인 4GB로요.

여기에 하나를 더 얹어야 합니다. 저 4GB를 자바 혼자 쓰는 게 아닙니다. 자바 힙 바깥의 네이티브 메모리도, 로그 파일을 만질 때 생기는 캐시도 그 안에서 나눠 씁니다. 파드에는 애플리케이션만 뜨는 것도 아닙니다 --- 로그를 실어 나르는 수집기가 사이드카로 같이 뜨는데, 그건 자기 몫을 따로 받습니다. 저 4GB 안에서 자바 힙 밖으로 나가는 몫이 생각보다 많습니다.

EC2 시절 서버는 한 대에 8GB 였고, 그 안에서 자바 힙이 최대 2GB를 썼습니다. 나머지 6GB는 자유롭게 남아 있었습니다. EKS로 옮기면서 파드에 건 상한은 4GB 였습니다. 힙은 2GB 그대로였으니, 힙 밖에 남는 여유가 6GB에서 2GB로, 3분의 1이 됐습니다. 그리고 그 위에 90% 알림선이 그어졌습니다.

그리고 같은 커밋에 이런 변경이 하나 더 있었습니다. 커밋 메시지를 그대로 옮기면 이렇습니다.

AccessLog tomcat 방식에서 custom으로 처리 - tomcat은 압축 지원을 안하므로 변경

접속 로그를 톰캣이 쓰던 방식에서 로깅 라이브러리(logback)로 옮긴 겁니다. 이유는 압축이었습니다. 톰캣은 자기가 쓰는 접속 로그를 압축하지 못합니다. 그래서 그때까지는 다른 방법으로 처리하고 있었는데, 그 일을 애플리케이션 안으로 들여온 겁니다. 로그를 다루는 설정이 한곳에 모이니 더 깔끔해 보였습니다.

2. 그 그래프는 무엇을 측정하고 있었나

저희가 보던 그래프는 자바 힙이 아니라 컨테이너 전체가 쓰는 메모리입니다.

자바가 객체를 올려두는 힙뿐 아니라, 그 프로세스가 만지는 파일까지 여기에 잡힙니다. 지금은 그냥 넘어가셔도 됩니다. 8장에서 이 문장이 핵심이 됩니다.

한 가지는 미리 말씀드려야겠습니다. 이 사건에는 에러 로그가 한 줄도 없었습니다. 예외도, 경고도, OOM으로 프로세스가 죽은 기록도 없었습니다. 응답도 멀쩡했고, 사용자 쪽에서는 아무 일도 일어나지 않았습니다. 저희가 가진 단서는 그래프 위의 스파이크 하나가 전부였습니다. 그래서 원인을 좁히기가 어려웠습니다.

나중에 원인을 좁히면서 정리한 수치는 이랬습니다. 평소 62%(2.48GB)를 유지하다가 스파이크가 날 때 75~76%(3.0GB)까지. 올라간 높이는 약 500MB, 지속 시간은 5분이었고 회복은 빨랐습니다.

"76%면 4GB 상한에 아직 여유가 있는데 왜 파고드나" 싶으실 수 있습니다. 알림 임계치가 90%였고, 이 서비스는 며칠에 걸쳐 기준선이 80%까지 올라간 전력이 있었습니다. 기준선이 올라간 상태에서 이 500MB가 겹치면 그대로 임계치입니다. 지금 안 터졌다는 게 안전하다는 뜻은 아니었습니다. 합산그래프

파드를 전부 합쳐서 본 메모리 사용률. 정각에 하나, 30분에 하나씩 규칙적으로 솟아 있습니다.

덧붙이자면, EC2 시절에는 이 값을 굳이 챙겨 보지 않았습니다. 상한이 없으니 사용률이라는 개념 자체가 흐릿했고, 저희가 습관적으로 열어보던 건 자바 힙 쪽 지표였습니다. EKS로 옮기고 나서야 컨테이너 전체 메모리를 상한 대비 몇 퍼센트로 보는 화면이 기본이 됐습니다.

3. 첫 번째 용의자 --- 힙 바깥의 메모리

처음 의심한 건 자바 힙 바깥이었습니다.

증상이 그쪽을 가리켰거든요. 며칠에 걸쳐 메모리가 45%, 55%, 62%, 80%로 계단을 올랐습니다. 전형적인 누수 모양입니다. 그리고 힙은 그렇게 안 늘어나고 있었습니다.

파보니 이유가 있었습니다. 외부 시스템과 통신할 때 쓰는 버퍼는 자바 힙 바깥 에 잡힙니다. 다이렉트 버퍼(Direct Buffer)라고 부르는 영역인데, 이걸 실제로 반납하는 건 힙 안 에 남아 있는 Cleaner 객체입니다. 버퍼를 쓰던 객체가 힙에서 치워져야 Cleaner가 깨어나고, 그제야 힙 바깥 메모리가 운영체제로 돌아갑니다. 여기에 안전장치가 하나 더 있습니다. 다이렉트 버퍼 한도를 다 쓰면 JVM이 마지막 수단으로 System.gc()를 불러 강제로 한 번 치웁니다. 그런데 -XX:+DisableExplicitGC가 켜져 있으면 그 마지막 한 방이 무시됩니다. 평소 GC가 멈춘다는 뜻은 아니고, 몰렸을 때 쓰는 비상구만 막혀 있었던 겁니다. 그래서 회수 타이밍을 놓치고 있었습니다.

옵션만 뺀 게 아니라 코드도 고쳤습니다. 네이티브 자원을 finalize()에 맡겨 두던 걸 try-with-resources로 바꿔서, 다 쓰고 나면 그 자리에서 바로 반납되게 했습니다. finalize()는 안전망으로 남겨 두고 주 반납 경로만 옮긴 겁니다. 요청마다 만들어졌다 사라지는 자원과 달리 서비스가 계속 붙들고 있는 객체는 try-with-resources 대상이 아니라서, 그건 빈이 소멸하는 시점에 한 번 더 닫아주게 했고요. 앞의 옵션 제거가 막혀 있던 비상구를 다시 연 것이라면, 이쪽은 비상구를 쓸 일 자체를 없앤 겁니다. GC가 언제 도는지에 기대지 않게 되니까요.

네이티브 메모리를 추적하는 옵션(-XX:NativeMemoryTracking=summary)을 켜고 파고든 뒤, 로컬에서 옛 설정과 새 설정을 나란히 놓고 부하를 걸어봤습니다. 결과는 좋았습니다. 물리 메모리 점유가 1,543MB에서 959MB로 떨어졌고, 무엇보다 계속 우상향하던 게 멈췄습니다. 확실히 고쳐야 할 문제였습니다.

그런데 여기서 멈추지 않았습니다. 그 무렵 다른 생각이 하나 더 들었거든요.

4. 두 번째 용의자 --- 자바 버전과 GC

자바 버전이 너무 낮은 거 아닌가.

당시 API는 자바 21이었습니다. 마침 색인 구조를 개선하는 큰 작업 중에 있었고, "이참에 같이 올리자"가 됐습니다. 대단한 확신이 있어서가 아니라, 이런 기대였습니다.

자바 버전만 올려도 리소스 관리는 기본적으로 좋아지지 않나. 게다가 ZGC라는 게 있다던데.

그래서 힙 바깥을 붙들고 있던 그 옵션을 빼고, 동시에 자바 25로 올리면서 Generational ZGC로 갈아탔습니다. 옵션도 이것저것 만졌고요. 커밋 하나에 이만큼이 들어갔습니다.

- -XX:+DisableExplicitGC        (제거)
+ -XX:+UseZGC
+ -XX:+UseCompactObjectHeaders
+ -XX:+UseStringDeduplication
+ -XX:+AlwaysPreTouch
+ -XX:TrimNativeHeapInterval=1000
+ -XX:SoftMaxHeapSize=1536m
+ MALLOC_ARENA_MAX=2

솔직히 말하면 저 목록은 "이 중에 하나는 듣겠지"에 가까웠습니다. 나중에 보니 몇 개는 서로 상쇄되거나 이 조합에서는 애초에 효과가 없는 것이었고요. 마지막 줄은 JVM 옵션이 아니라 환경변수입니다.

그래도 그냥 넣지는 않았습니다. 상용에 올리기 전에 스테이징에서 한 번 걸어봤습니다. 파드 한 대에 상용 파드당 피크의 다섯 배쯤 되는 부하를 75분 동안 몰아넣는 조건이었습니다. 메모리는 63%에서 65% 사이를 오르내리다 더 올라가지 않았고, 부하를 끊자 15분 안에 제자리로 돌아왔습니다. GC가 멈춰 세우는 시간은 그 구간 내내 1밀리초를 넘지 않았고요. 여기까지 보고 상용에 넣었습니다.

배포하고 17시간 넘게 지켜봤습니다. 성과는 분명했습니다. GC가 애플리케이션을 멈춰 세우는 시간(Stop-The-World)이 수십 밀리초에서 1밀리초 아래로 내려갔습니다. 기준선이 계단으로 오르던 패턴도 잦아드는 것처럼 보였습니다. 대신 기준선 자체가 10%p쯤 올라갔습니다. 처음에는 새 GC가 더 쓰는 몫이라고 생각했는데, 나중에 보니 같은 커밋에 넣은 -XX:+AlwaysPreTouch 때문이었습니다. 힙 크기를 2GB로 묶어두는 것과, 그 2GB를 실제로 물리 메모리에 붙여두는 것은 다른 이야기입니다. 이 옵션은 기동할 때 힙 2GB를 전부 미리 짚어둡니다. 그전까지는 실제로 쓰는 만큼만 물리 메모리에 올라와 있었으니, 그 차이가 그대로 기준선으로 올라온 겁니다. 컨테이너 메모리 지표는 "얼마를 예약했나"가 아니라 "실제로 얼마를 짚었나"를 보니까요.

그런데 스파이크는 그대로였습니다.

계단으로 오르던 건 멎었고 멈춤 시간도 짧아졌는데, 5분짜리 500MB 스파이크는 여전히 같은 자리에 같은 크기로 났습니다.

첫 번째 무죄, 두 번째 무죄. 한 번의 배포로 용의자 둘이 한꺼번에 풀려났습니다.

이때가 제일 답답했습니다. 가장 유력한 용의자에 기대를 다 걸었는데, 잡고 보니 스파이크와는 아무 관계가 없었으니까요.

5. 남은 용의자를 하나씩 지웠습니다

가설을 일곱 개 세우고 여섯 개를 지웠습니다.

여섯 중 넷은 숫자 하나로 끝났습니다. 트래픽 은 시간대와 상관없이 평탄했고 스파이크가 난 시각이 특별히 바쁘지도 않았습니다. 애플리케이션 안의 예약 작업 은 정해진 대로 열세 번 정확히 돌았지만 스파이크와 시각이 겹치지 않았습니다. 잘 도는 것과 그게 범인인 것은 별개입니다. 네트워크 라이브러리가 잡아두는 다이렉트 버퍼 는 41MB, 스파이크의 12분의 1이었고요. 분산 추적 데이터는 표본을 10%만 뽑도록 돼 있어 애초에 양이 적었습니다.

로그를 실어 나르는 경로가 막혀서 파일이 쌓였나? 수집기에서 저장소까지 전송은 정상이었고 오류도 0건이었습니다. --- 여기서 짚고 갈 게 있습니다. 이때 저는 전송 경로만 봤지 파드 안의 로그 파일 자체는 열어보지 않았습니다. 답 바로 옆을 스쳐 지나갔습니다.

혹시 새로 넣은 ZGC가 오히려 범인인가? JVM 쪽을 의심한 세 번째이자 마지막이었습니다. 힙에 할당된 메모리를 확인하니 2GB로 고정돼 있었습니다. 최소치와 최대치를 둘 다 2GB로 묶어 두었으니(-Xms2g -Xmx2g) 힙이 반납되지도 늘어나지도 않고, 시작할 때 그 2GB를 미리 다 짚어두는 옵션(AlwaysPreTouch)까지 켜져 있으니 물리 메모리에도 처음부터 2GB가 그대로 붙어 있습니다. 즉 힙 사용량이 아무리 요동쳐도 컨테이너 메모리는 못 움직입니다. 확인은 지표 한 번이면 됐습니다.

curl -s "localhost:8080/actuator/metrics/jvm.memory.committed?tag=area:heap" | jq

그런데 스파이크는 여전히 그대로였습니다.

세 번째 무죄. 자바 쪽은 이걸로 끝이었습니다. 더 의심할 게 남아 있지 않았습니다.

여섯 개를 지우고 나니 짚이는 데가 없었습니다. 그리고 계속 걸리는 게 하나 있었습니다. 스파이크가 정각에도 나고 30분에도 났습니다. 스케줄러가 도는 거라면 시각이 일정해야 하는데 그렇지 않았습니다. 규칙적인 듯하면서 규칙에 안 맞았습니다.

6. 보는 방식을 바꿨습니다

가설이 계속 빗나가자 데이터를 다시 봤습니다. 정확히는, 보는 방식을 바꿨습니다.

여러 대를 합친 그래프 대신 파드를 하나만 골라서 그렸습니다. 대시보드의 파드 선택 변수에서 하나만 남기면 되니 클릭 두 번이었습니다.

스파이크가 하나였습니다. 단일파드

파드 하나만 떼어놓고 본 결과. 스파이크가 딱 한 번뿐입니다.

합산 그래프에 있던 나머지 스파이크들은 이 파드의 것이 아니었던 겁니다. 창을 넓혀 다른 파드를 보니 이번엔 여섯 번이 나왔습니다. 간격은 한 시간 반에서 두 시간에 한 번꼴이었고, 파드마다 조금씩 달랐고요.

그제야 그림이 맞춰졌습니다. 파드마다 각자의 주기로 한 번씩 튀고 있었던 겁니다. 파드들은 부팅 시각도 다르고 트래픽을 나눠 받는 양도 조금씩 달라서, 각자 파일이 다 차는 시점이 흩어져 있었습니다. 그걸 여러 대 합쳐 놓으니 무언가가 규칙적으로 도는 것처럼 보인 겁니다.

저를 스케줄러 쪽으로 끌고 갔던 그 규칙성은, 애초에 없는 것이었습니다.

동시에 이건 중요한 단서였습니다. 클러스터 전체를 동시에 건드리는 외부 트리거가 아니라, 파드 하나하나 안에서 벌어지는 일이라는 뜻이니까요.

7. 파드 안으로 --- 진범

이제 들어갈 곳이 하나 남았습니다. 파드 안의 로그 디렉터리. 조금 전에 스쳐 지나갔던 그곳입니다.

명령 한 줄이면 되는 일이었습니다. 그동안 한 번도 안 쳐본 그 한 줄이요.

kubectl exec POD -c api -- ls -laht /로그디렉터리/

목록이 떴습니다. 지금 쓰고 있는 로그 파일 하나, 그리고 그 아래로 .gz로 끝나는 파일들.

접속 로그 파일이 500MB 에 도달하면 로깅 라이브러리가 파일을 새로 만들고(롤오버) 이전 파일을 gz로 압축합니다. 압축이 끝나면 파일이 10분의 1도 안 되게 줄어듭니다. 디스크 사용량 면에서는 이득입니다. 여기까지는 설계한 대로였습니다.

눈에 들어온 건 파일 크기가 아니라 시각이었습니다. ls -laht는 최근 순으로 정렬해 주고, 파일마다 만들어진 시각이 찍혀 있습니다. 6장에서 스파이크를 셌던 그 창을 그대로 놓고 세어 봤습니다.

여섯 개였습니다.

그 파드의 스파이크도 여섯 개였습니다.

두 목록을 나란히 놓았습니다.

파일이 만들어진 시각과 스파이크가 난 시각을 한 줄씩 짝지었습니다. 여섯 쌍이 전부 맞았습니다. 단일파드

같은 파드의 스파이크 6회. 압축 파일 6개와 시각이 하나도 빠짐없이 맞았습니다.

몇 분씩 어긋난 것처럼 보이는 건 그래프의 시간 눈금 때문입니다. 눈금이 30분 단위라 스파이크가 정각과 30분에만 찍힙니다. 저를 스케줄러 쪽으로 끌고 갔던 그 "정각·30분"도 실은 눈금이 만든 착시였습니다.

두 달을 돌아서 도착한 곳이 로그 파일 목록이었습니다.

허무했고, 동시에 이상했습니다. 왜 두 달 동안 이 한 줄을 안 쳐봤을까요. 그 답은 뒤에서 다시 적겠습니다.

8. 왜 하필 500MB인가

여기서 오해하기 쉬운데, 그 500MB는 자바가 쓰는 메모리도 아니고 압축 알고리즘이 잡는 버퍼도 아닙니다. gzip이 쓰는 버퍼는 많아야 수백 KB짜리입니다.

사실 저희도 처음에는 그렇게 적었습니다. 원인을 정리하면서 압축 버퍼와 임시 파일이 5분 동안 메모리를 점유한다고 적어 뒀거든요. 그럴듯한데 틀렸습니다. 압축 버퍼는 그렇게 크지 않습니다.

진짜 이유는 따로 있습니다.

리눅스는 파일을 읽고 쓸 때 그 내용을 페이지 캐시 에 올려둡니다. 한 번 읽은 파일을 다음에 빨리 쓰려고 메모리에 얹어두는 공간인데, 책상 위에 펼쳐 둔 책 이라고 생각하시면 됩니다. 책장에 꽂아두면 꺼내 오는 데 시간이 걸리니, 자주 볼 책은 책상에 펼쳐 둡니다. 리눅스도 똑같이 합니다. 그리고 컨테이너 메모리 사용량에는 이 "책상 위"까지 포함됩니다.

500MB짜리 파일을 통째로 읽는다는 건, 500쪽짜리 책을 처음부터 끝까지 넘겨보느라 책상 위에 다 펼쳐놓는 것과 같습니다.

압축이 하는 일이 정확히 그겁니다. 그동안 파일이 통째로 캐시에 올라왔고, 그게 그래프의 스파이크였습니다. 압축이 끝나고 원본 파일이 지워지면 그 캐시도 회수되니, 5분 뒤에 내려앉은 것이고요.

한 가지 덧붙이면, 컨테이너 메모리 지표가 캐시를 집계하는 방식은 지표마다 조금씩 다릅니다. 한 번 읽고 마는 캐시는 제외하는 지표도 있습니다. 저희 쪽에서 이 500MB가 그대로 잡힌 데는, 로그를 실어 나르는 수집기가 옆에서 같은 파일을 다시 읽어 간 영향도 있었을 겁니다.

2장에서 봤듯 저 지표는 힙이 아니라 컨테이너 전체 메모리입니다. 그 차이가 여기서 의미를 갖습니다. 힙만 보고 있었다면 이 스파이크는 영원히 안 보였을 겁니다.

한 가지는 짚고 가야 공정합니다. 페이지 캐시는 메모리가 모자라면 커널이 먼저 밀어내는 영역이라, 이 500MB가 곧장 프로세스를 죽이지는 않습니다. 문제는 다른 쪽입니다. 지표와 알림은 캐시까지 포함해서 집계합니다. 기준선이 이미 높은 상태에서 이게 겹치면 임계치를 건드리고, 그러면 사람이 토요일 새벽에 불려 나옵니다.

참고로 이 정도 속도로 파일이 차는 게 유난히 로그를 많이 남기는 설정은 아닙니다. 접속 로그는 한 줄이 짧아도 줄 수가 금방 불어나서, 수백 MB는 생각보다 빨리 찹니다. 차는 속도는 서비스마다 다르니 각자 로그 디렉터리에서 파일이 갈리는 간격을 직접 재보시는 편이 빠릅니다.

앞에서 이상했던 것들이 여기서 다 풀립니다

이제 처음에 걸렸던 것들을 되짚어 보겠습니다.

왜 에러가 한 줄도 안 났나. 아무것도 고장 나지 않았기 때문입니다. 압축은 설계한 대로 돌았고, 캐시는 커널이 원래 하는 일을 했을 뿐입니다. 정상 동작만으로 알림이 울린 겁니다. 그래서 로그를 아무리 뒤져도 나올 게 없었습니다.

왜 5분 뒤에 정확히 내려앉았나. 압축이 끝나고 원본이 지워지면 캐시도 회수되니까요. 5분이라는 시간은 압축에 걸린 시간이었습니다.

왜 파드마다 시각이 달랐나. 파일이 차는 속도가 파드마다 달랐기 때문입니다. 트래픽을 나눠 받는 양도, 부팅 시각도 제각각이니까요.

그리고 하나가 더 남았습니다. 그 새벽에 제가 전에 본 것과 비슷하다고 적었던 것 말입니다.

그건 다른 사건이었습니다. 며칠에 걸쳐 계단으로 오르던 그 현상은 힙 바깥 메모리가 안 돌아오던 문제였고, 그건 봄에 잡혔습니다. 스파이크는 처음부터 별개였습니다. 제가 둘을 하나로 묶어 놓고 보고 있었던 겁니다. 그게 이 사건이 길어진 이유 중 하나였고요.

9. 그런데, EC2에서는 왜 멀쩡했을까

원인을 알고 나니 확인하고 싶은 게 생겼습니다. 그럼 EC2에서는 왜 아무 일도 없었지?

1장에서 "다른 방법으로 처리하고 있었다"고만 적고 넘어간 그것, 이제 정체를 밝힐 차례입니다. 운영체제의 로그 정리 도구( **logrotate)**가 배치로 돌면서 접속 로그를 압축하고 있었습니다. 설정은 이랬습니다.

copytruncate     # 원본을 복사한 뒤 잘라낸다
compress         # 압축한다
daily            # 하루에 한 번

EKS 쪽보다 오히려 더 무거운 방식입니다. copytruncate는 원본을 통째로 복사한 뒤 잘라내는 방식이라, 읽고 쓰고 다시 압축까지 합니다. 파일 전체를 만지는 건 EC2 쪽이 더했으면 더했지 덜하지 않았습니다.

바뀐 건 압축의 유무가 아니었습니다. 빈도였습니다.

같은 일이 열 배 넘게 자주 일어나게 된 겁니다. 하루에 한 번 5분이면 그래프에서 눈에 띄지도 않습니다. 두 시간에 한 번이면 하루 종일 스파이크가 찍힙니다.

그리고 환경도 그 사이에 바뀌어 있었습니다. 세 가지가 함께 달라졌습니다.

먼저 압축하는 자리가 컨테이너 바깥에서 안으로 들어왔습니다. EC2에서는 운영체제 배치가 호스트 쪽에서 파일을 만졌으니 그 500MB도 호스트 몫이었습니다. 이제는 애플리케이션이 컨테이너 안에서 직접 만지니 같은 파일이라도 파드 몫으로 계산됩니다. 로그가 놓인 자리도 호스트 디스크에서 파드의 임시 볼륨으로 함께 옮겨갔고요.

그리고 EC2 시절에는 그런 그래프 자체가 없었습니다. 컨테이너가 붙들고 있는 메모리 전체를 한 장으로 보는 대시보드는 EKS로 옮기면서 생겼습니다.

마지막으로 여유가 줄었습니다. 8GB 중 힙 밖 6GB에서, 4GB 중 힙 밖 2GB로요.

처음 검토했던 8GB였다면

세 번째가 결정적입니다. 숫자를 넣어보면 이렇습니다.

이 8GB는 제가 지어낸 숫자가 아닙니다. 이관을 준비하면서 처음 검토했던 값이 그것이었습니다.

같은 500MB인데 4GB에서는 알림이 울리고 8GB에서는 안 울립니다. 스파이크는 똑같이 나지만, 8GB였다면 그래프에서 거의 눈에 띄지 않았을 겁니다. 아무도 안 들여다봤을 거고요.

그러니까 정확히 말하면 이렇습니다. 압축이 열 배 자주 돌게 됐고, 그걸 담을 여유는 3분의 1로 줄었습니다. 둘이 겹치지 않았다면 알림까지는 가지 않았을 겁니다.

자원을 조인 그 판단은 잘못된 게 아니었습니다. 넉넉하게 잡아두고 러프하게 쓰던 걸 실제 쓰는 만큼으로 맞춘 것이고, 비용을 줄이자는 이관의 목표와도 맞았습니다. 그때로 돌아가도 같은 값을 넣었을 겁니다.

다만 이렇게 되는 겁니다. 합리적인 결정 셋이 겹치는 자리에, 아무도 예상하지 못한 것이 있었습니다. 압축을 켠 것도 맞고, 로그를 표준 위치에 둔 것도 맞고, 자원을 조인 것도 맞습니다. 셋 다 맞는데 문제가 생겼습니다.

그리고 1장의 그 커밋 메시지가 여기서 돌아옵니다.

"tomcat은 압축 지원을 안하므로 변경"

디스크를 아끼려고 옮긴 그 압축이, 넉 달 뒤에 메모리 그래프의 범인이 됐습니다. 압축을 켤 때 그게 메모리로 계산될 거라고는 저희 중 누구도 생각하지 못했습니다. 압축은 디스크 이야기지 메모리 이야기가 아니니까요.

그 문장을 다시 읽는 데 한참 걸렸습니다.

10. 세 가지가 겹치면 어디서든 생깁니다

원인을 확인하고 나니 범위가 신경 쓰였습니다. 해당 서비스에만 있는 조건이 아니었거든요.

흔한 구성입니다. 나중에 같은 구성으로 도는 다른 API들을 확인해 보니 그쪽 그래프에도 같은 무늬가 있었습니다. 빈도만 낮았는데, 로그가 500MB까지 쌓이는 속도가 느렸을 뿐입니다. 안 생기는 게 아니라 아직 안 생긴 것이었습니다.

범위를 조금 더 넓히면, 이건 로그만의 이야기도 아닙니다. 컨테이너 안에서 대용량 파일을 통째로 읽거나 쓰는 작업은 전부 같은 방식으로 메모리 그래프에 나타납니다. 배치가 큰 파일을 내려받는 것도, 사이드카가 파일을 훑는 것도 마찬가지입니다.

11. 고치기 --- 기준을 바꿔서 물었습니다

결론부터 말씀드리면 압축을 껐습니다. 대신 보관 정책을 조여서 디스크를 지켰고요. 거기까지 가는 데 후보가 넷 있었습니다.

후보를 따지기 전에, 알림 임계치를 90%에서 95%로 올려 덮는 길도 검토했다가 접었습니다. 4GB짜리 파드에서 알림선을 95%로 올리면 정말 모자랐을 때 손쓸 여유가 남지 않습니다. 알림이 불편하다고 알림을 옮기는 건 문제를 옮기는 것이지 푸는 게 아니었습니다.

압축만 끄면 스파이크는 즉시 사라지지만 디스크 사용량이 몇 배로 뜁니다. 파일 크기를 5분의 1로 줄이면 스파이크의 높이와 지속 시간도 5분의 1이 되지만 대신 5배 자주 생깁니다. 작은 스파이크가 더 자주 나는 셈이라 근본 해결은 아니고요.

나머지 둘은 더 일찍 접었습니다. 로그 쓰기를 비동기 큐로 감싸는 안 은 실행 스레드만 바꿀 뿐 500MB를 통째로 읽는다는 사실을 못 바꾸고, 대기열이 넘치면 로그가 유실될 위험까지 생깁니다. 헬스체크 같은 걸 걸러 로그 양을 줄이는 안은 파일이 차는 주기만 늘릴 뿐입니다.

덧붙이면, 나중에 로깅 라이브러리 소스를 직접 열어보고 알았는데 저희가 쓰던 정책에서는 압축이 원래부터 별도 스레드에 던져지고 있었습니다. 날짜와 크기를 함께 보는 계열이 그렇고, 크기만 보는 정책은 그 자리에서 압축을 끝내고 넘어갑니다. 그러니 세 번째 안은 처음부터 답이 될 수 없었습니다. 스레드를 옮겨도 500MB를 읽는 일은 그대로 일어나니까요.

그래서 판단 기준을 바꿔서 물었습니다.

압축해서 오래 보관한 로그를 우리가 실제로 쓰기는 하는가.

답이 명확했습니다. 로그는 이미 수집기가 중앙 저장소로 실어 보내고, 거기서 로컬보다 훨씬 오래 보관됩니다. 파드가 재시작되면 로컬 파일은 어차피 사라지고, 그마저도 실시간으로 들여다볼 때나 썼습니다. 압축해서 쌓아둘 이유가 크지 않았습니다.

디스크는 이렇게 지켰습니다

파일 크기( maxFileSize)는 500MB 그대로 두고, 보관 기간( maxHistory)을 7일에서 1일로 줄이면서 총량 상한( totalSizeCap)을 새로 걸었습니다. 접속 로그와 그 밖의 로그에 각각 상한을 두고, 넘으면 오래된 것부터 자동으로 지웁니다. 오늘 쓰는 로그와 어제 것은 남으니 로그가 0개가 되는 상황도 피했습니다.

파일 크기를 줄이는 쪽보다 이편이 나았습니다. 원래 문제는 메모리 스파이크 하나가 아니었거든요. 압축을 해도 7일치가 쌓이면서 실제로 디스크가 부족해진 적이 있었습니다. 보관 기간만 줄이면 하루치가 얼마나 커질지는 여전히 트래픽에 달려 있는데, 총량 상한은 거기에 천장을 씌워 줍니다. 다만 이 천장이 딱 떨어지지는 않습니다. 지금 쓰고 있는 파일은 상한 계산에 안 들어가고, 상한이 검사하는 구간과 삭제가 시작되는 구간도 한 칸 어긋나 있습니다. 그래서 실제로 쌓이는 양은 걸어둔 숫자보다 넉넉하게 잡아 두는 편이 안전합니다.

바꾸기 전에 하나는 확인하고 갔습니다. 압축을 끄면 수집기가 보는 파일의 확장자가 달라지니, .gz가 아닌 파일도 그대로 실어 나르는지 먼저 봤습니다. 문제없었습니다.

파일 크기를 굳이 줄이지 않아도 되는 이유도 여기서 나옵니다. 압축을 없앴으니 파일을 갈아치우는 일이 이름만 바꾸는 작업이 됐습니다. 500MB를 통째로 읽어 들일 일이 사라졌으니, 파일 크기를 줄일 이유도 함께 없어진 겁니다.

디스크 쪽도 며칠에 걸쳐 따로 확인했습니다. 압축을 껐으니 파일은 커졌지만 보관 기간과 총량 상한이 함께 걸려 있어, 사용량은 여유 있는 수준에서 평평했습니다.

한 서비스에 먼저 넣고 4주를 지켜본 뒤, 같은 구성을 쓰는 나머지 서비스로 확대했습니다. 결과는 그래프가 말해줍니다. 적용 시점을 기준으로 왼쪽에는 스파이크가 규칙적으로 나 있고, 오른쪽에는 하나도 없습니다.

빨간 선이 조치를 적용한 시점입니다. 왼쪽(AS-IS)의 바늘들이 오른쪽(TO-BE)에서 완전히 사라졌습니다.

12. 남는 것 세 가지

합쳐서 보는 그래프는 없던 규칙성을 만들어냅니다. 여러 대가 각자의 주기로 하는 일을 하나로 합쳐 놓으면, 존재하지 않는 주기가 눈에 보입니다. 저는 그걸 어딘가에서 스케줄러가 도는 탓이라고 읽었고, 그래서 한참을 돌아갔습니다. 인스턴스가 여러 개인 환경에서 원인을 찾을 때는 하나만 떼어놓고 보는 것이 가설을 좁히는 첫 단추입니다. 클릭 두 번이면 되는 일이었습니다.

앞에서 남겨둔 질문 --- 왜 두 달 동안 그 한 줄을 안 쳐봤나 --- 의 답이 이겁니다. 증상이 둘인데 한 사건으로 묶어 보면 오래 걸립니다. 며칠에 걸쳐 계단으로 오르던 기준선과 5분짜리 스파이크, 저는 이 둘을 하나로 보고 있었습니다. 기준선을 올리던 힙 바깥 메모리를 잡으면 스파이크도 따라 잡힐 거라고 생각했고, 그래서 네이티브 메모리와 GC를 차례로 의심했습니다. 새것을 들이면 그다음 문제가 전부 새것 탓으로 보이는 것도 한몫했고요. GC를 바꾼 뒤에 메모리가 튀었으니 GC를 의심한 건 합리적이었습니다. 다만 합리적인 것과 맞는 것은 다릅니다.

두 증상이 같은 사건인지부터 확인했어야 했습니다. 주기가 다르면 원인도 다릅니다. 계단은 며칠 단위였고 스파이크는 두 시간 단위였는데, 저는 그 둘의 주기를 나란히 놓고 비교해 본 적이 없었습니다. 그리고 가장 유력해 보이는 가설일수록 명확한 숫자 하나로 빨리 기각하는 편이 낫습니다. 이번 건에서 그 숫자는 "힙 할당량이 2GB로 고정"이라는 한 줄이었습니다.

그리고 이게 제일 하고 싶은 말입니다. 플랫폼을 옮기면, 같은 지표라도 측정 범위가 달라집니다.

저희는 API가 동작하는 방식을 바꾼 게 아닙니다. 로그를 누가, 얼마나 자주, 어디에 쓰느냐를 바꿨을 뿐입니다. 그리고 그것만으로 없던 알림이 울리기 시작했습니다. 옮기기 전과 후에 같은 500MB가 같은 자리에 올라왔는데, 한쪽에서는 아무 일도 아니었고 다른 쪽에서는 새벽 호출이 됐습니다. 바뀐 건 로직이 아니라 그 로그가 놓인 자리와, 그것을 측정하는 범위였습니다.

저희는 그 플랫폼을 처음 썼습니다. 그리고 **"압축은 디스크를 아끼는 기능이지만, 컨테이너 안에서는 메모리로 계산된다"**는 문장은 어디에도 적혀 있지 않았습니다. 알았다면 이렇게까지 길어지지 않았을 겁니다. 그래서 이 글을 씁니다.

이관 체크리스트에 한 줄만 더 넣으시면 좋겠습니다.

이 지표는 무엇을 측정하는가? 옮기기 전과 달라졌는가?

마치며

이 글을 읽고 확인할 게 있다면 세 가지입니다. 로그를 파일 크기 기준으로 갈아치우고 있는지, 그때 압축을 켜 두었는지, 그 파일이 수백 MB까지 커지는지. 셋 다 해당한다면 파일 하나가 가득 차는 시점에 컨테이너 메모리가 그 파일 크기만큼 뛰고 있을 겁니다. 로깅 설정에서 파일명 패턴이 .gz로 끝나는지와 파일 크기 기준값이 얼마인지, 두 줄만 보시면 됩니다.

확인은 파드 하나를 골라 그래프를 그려보는 것으로 시작하시면 됩니다. 합쳐서 보면 안 보입니다.

아직 문제가 안 보인다면, 로그가 아직 그 크기까지 안 찼을 가능성이 큽니다.