프로그래밍/Go

Go pprof를 사용한 어플리케이션 OOM 이슈 분석기

동네로봇 2025. 4. 11. 23:37

이슈 발생

 

Go 어플리케이션 중 하나가 갑자기 Out Of Memory가 발생하여 서비스가 죽고 CPU 사용량도 max를 치면서 서버에 hang이 걸려 서버 접속도 하지 못하는 이슈가 발생했다. 

 

 

서버와 어플리케이션을 모두 재시작했으나 동일한 이슈가 반복되어 일단은 4C/16GB 인스턴스로 scale-up 하여 임시방편으로 문제를 해결하고 원인을 파악하고자 했다. (기존 인스턴스 스펙 : 2C/8G)

 

빈번하게 배포하는 상용 서비스가 아니었고 만약 memory leak이었다면 재시작했을 때는 문제가 없었어야 하므로, 실행중이던 작업에 문제가 있다고 판단하여 go pprof를 사용해 프로파일링을 진행하기로 했다. 

 

해당 서비스는 미디어 파일을 CDN에 업로드 하는 기능과 이미지 파일을 분석한 후 CDN에 업로드 하는 두 가지 기능을 제공하는데, OOM 발생 후 재시작 시 모두 이미지 파일을 처리하다가 또다시 사망하였으므로 이미지 처리 부분에 문제가 있다고 보고 원인 분석을 시작하였다. 

 

원인 분석

pprof는 HTTP 서버를 통해서 실행중인 서비스 프로파일링을 제공하는 패키지다. 

(참고 : https://pkg.go.dev/net/http/pprof)

 

go pprof를 사용하기 위해 main에 아래와 같이 추가해준다.

import (
	"net/http"
	_ "net/http/pprof"
)

func main() {
	...
	go func() {
		log.Println(http.ListenAndServe("localhost:6060", nil))
	}()
	...
}

 

어플리케이션 실행 후 localhost:6060/debug/pprof 로 접속하면 아래와 같이 확인할 수 있다.

  • allocs: 모든 과거 메모리 할당에 대한 샘플링
  • block: 동기화 기본 요소에 대한 차단으로 이어진 추적 스택
  • cmdline: 현재 프로그램의 명령줄 호출
  • goroutine: 현재 모든 고루틴의 흔적을 쌓습니다. debug=2를 쿼리 매개변수로 사용하여 복구되지 않은 패닉과 동일한 형식으로 내보냅니다.
  • heap: 라이브 객체의 메모리 할당 샘플링. 힙 샘플을 채취하기 전에 GC를 실행할 go GET 매개변수를 지정할 수 있습니다.
  • mutex: 경합된 뮤텍스의 스택 트레이스
  • profile: CPU 프로필. GET 매개변수의 지속 시간을 초 단위로 지정할 수 있습니다. 프로필 파일을 받은 후 Go 도구 pprof 명령을 사용하여 프로필을 조사합니다.
  • threadcreate : 새로운 OS 스레드 생성으로 이어진 스택 트레이스
  • trace: 현재 프로그램의 실행 추적입니다. GET 매개변수의 지속 시간을 초 단위로 지정할 수 있습니다. 추적 파일을 받은 후 Go 도구 추적 명령을 사용하여 다음을 조사합니다

(그냥 파파고 돌렸다.. 위의 원문을 참고)

 

각각의 링크를 타고 들어가면 runtime/pprof.Profile에 있는 모든 프로파일 리스트를 확인할 수 있다. 하지만 자세한 내용은 CLI를 통해서 확인하는 것이 더 편리하므로 go tool을 사용해서 확인해본다.

 

실행 과정 중의 모든 메모리 할당량을 확인해야 하므로 allocs를 활용한다.

$ go tool pprof http://localhost:6060/debug/pprof/allocs

 

그동안 실행했던 어플리케이션 동작 중에서 가장 많은 메모리를 차지했던 상위 10개 함수를 top 명령어를 통해서 찾는다. 메모리 할당량 순서대로 10개의 메서드와 합산 사용량을 보여주는데 여기서 메서드 명과 나머지 리스트들은 가렸다.

$ go tool pprof http://0.0.0.0:6060/debug/pprof/allocs
Type: alloc_space
Time: Apr 11, 2025 at 10:15am (KST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 195.41MB, 96.83% of 201.80MB total
Dropped 31 nodes (cum <= 1.01MB)
Showing top 10 nodes out of 43
      flat  flat%   sum%        cum   cum%
  103.01MB 51.04% 51.04%   141.70MB 70.22%  function1
...
...

 

pprof는 메모리 사용량에 대해서 시각화하여 보여주는 기능도 제공한다. 그래프를 통해서 함수 call 순서와 메모리 사용량을 그림으로 보여주는데 이를 활용하려면 graphviz를 먼저 설치한다. 

brew install graphviz

 

설치하면 localhost:6060/debug/pprof 의 내용을 시각화해서 웹 페이지로 보여주거나, 이미지 파일로도 다운로드 받을 수 있다. 

$ go tool pprof -http 0.0.0.0:8080 http://0.0.0.0:6060/debug/pprof/allocs
$ go tool pprof -png http://0.0.0.0:6060/debug/pprof/allocs  > out.png

 

지우느라 너무 힘들었..

 

확인해보니 이미지 파일을 Decode하는 부분에서 가장 많은 메모리를 차지하고 있었다. Decode 함수를 호출한 Root 함수가 실행될 때 사용한 메모리 총량이 궁금했으므로 go tool을 사용하여 root 함수 실행 시 사용한 메모리 총량을 확인한다.

list {함수명} 을 통해서 root 함수의 코드와 함께 코드의 어떤 부분에서 얼마만큼의 메모리를 사용하는지 파악할 수 있다.

(pprof) list RootFunction
Total: 201.80MB
ROUTINE ======================== function1 in function1.go
         0   189.95MB (flat, cum) 94.13% of Total
...
...
...

 

Decode 기능을 포함하여 이미지 분석 기능을 수행하는데 총 201.80MB를 사용하고 있다는 것을 확인했다.

 

그러나 현재 8G 메모리의 서버에서 총 8개의 서비스가 동작하는데 201.80MB * 8 을 해봤자 1.61GB 이다. 그럼 8GB 메모리는 왜 부족했던 것일까?

 

Go에서 하나의 함수가 실행 완료되어도 GC가 바로 메모리 정리를 하지 않는다.

 

해당 어플리케이션에서 GC trace를 확인해보았다.

$ GODEBUG=gctrace=1 ./myapp

gc 1 @68.240s 0%: 0.042+4.3+0.006 ms clock, 0.42+4.2/3.1/1.5+0.067 ms cpu, 28->28->26 MB, 28 MB goal, 0 MB stacks, 0 MB globals, 10 P
gc 2 @68.245s 0%: 0.024+0.50+0.007 ms clock, 0.24+0.44/1.0/0.10+0.076 ms cpu, 61->61->61 MB, 61 MB goal, 0 MB stacks, 0 MB globals, 10 P
gc 3 @68.247s 0%: 0.053+0.57+0.021 ms clock, 0.53+0/0.94/0.79+0.21 ms cpu, 129->129->129 MB, 129 MB goal, 0 MB stacks, 0 MB globals, 10 P
GC forced
gc 4 @188.299s 0%: 1.0+1.6+0.006 ms clock, 10+0/2.2/0+0.069 ms cpu, 192->192->1 MB, 260 MB goal, 0 MB stacks, 0 MB globals, 10 P
  • gc 1: 첫 번째 GC
  • 28->28->26 MB: GC 전 heap 28MB, GC 도중 28MB 유지, GC 후 26MB
  • 28 MB goal: 다음 GC가 도는 시점 (heap goal)

어플리케이션에 임의로 3번의 요청을 날렸을 때의 GC trace이다.

 

총 3번의 요청을 받는 gc 3까지 메모리가 완벽하게 정리되지 않다가 요청 없이 대기하고 188s 후 1MB로 정리되는 것을 알 수 있다.

결론

 

이슈가 발생했던 시간대에 다수의 이미지 처리 요청이 몰렸고, 8대의 어플리케이션이 쉼 없이 이미지 처리를 진행하다가 memory full이 차며 OOM이 발생하였다. 

 

해결

1. 서버에서 실행하는 어플리케이션 대수를 줄여 8GB 메모리를 full로 사용하지 않도록 버퍼를 둔다.

 

2. 이번 이슈처럼 이미지 작업이 몰릴 경우를 대비하여 GC를 좀 더 자주 수행할 수 있도록 GOGC 값을 낮춘다.

$ GOGC=50 ./myapp
or
debug.SetGCPercent(50)
 
  • GOGC=100 (기본값) : 힙이 100% 커지면 GC 수행
  • GOGC=50 : 기본보다 자주 GC 수행, 메모리 절약 but CPU 사용 증가

 

잦은 GC 수행으로 CPU 사용 증가할 수 있으나 2C로 충분할 것 같다.

 

3. GOGC를 낮추더라도 일시적인 memory peak 상황에서는 OOM 발생할 수 있으므로 memoryLimit을 통해 일정 메모리 할당량을 넘어가지 않도록 조정한다.

debug.SetMemoryLimit(800 * 1024 * 1024) // 800MiB​

soft limit이므로 설정한 memory limit 값을 넘어가지 않는 것은 아니다.