pprof으로 시작하는 Go 성능 프로파일링

pprof는 Go 애플리케이션 프로파일링에 사용되는 도구다. 어떤 일을 하냐면, 대략 아래처럼 애플리케이션의 병목 지점이나 성능을 체크할 수 있다.

Fibonacci를 계산하는 API를 만들고, pprof와 graphviz를 이용해 profile을 시각화하는 방법을 정리해본다.

기본적인 사용법

먼저 기본적인 사용법이다.

예시 코드

HTTP 요청을 받으면,

GET 요청으로 숫자를 받고

해당 숫자 번째의 Fibonacci 수를 계산해 반환

recursive한 fibonacci 계산함수
cache를 이용하는 fibonacci 계산함수

이렇게 2가지를 테스트해볼 예정이다.

먼저 Fibonacci 수를 계산하는 함수를 만들었다.

fibRecurr

O(2^n)으로 계산
CPU 부하를 주기 위해 사용

fibCache

O(n)으로 계산
메모리 부하를 주기 위해 사용


// fibRecurr 재귀적으로 Fibonacci 수를 계산: O(2^n)
func fibRecurr(n int) int {
	if n <= 1 {
		return n
	}
	return fibRecurr(n-1) + fibRecurr(n-2)
}


// fibCache cache를 이용해 Fibonacci 수를 계산: O(n)
func fibCache(n int) *big.Int {
	// Create a slice to store Fibonacci numbers up to n
	fibCache := make([]*big.Int, n+1)

	// Initialize the first two numbers in the Fibonacci sequence
	fibCache[0] = big.NewInt(0)
	fibCache[1] = big.NewInt(1)

	// Compute Fibonacci numbers up to n, storing each result
	for i := 2; i <= n; i++ {
		fibCache[i] = new(big.Int).Add(fibCache[i-1], fibCache[i-2])
	}

	// Return the nth Fibonacci number
	return fibCache[n]
}

handler와 main함수는 아래와 같다.

/fib/{algorithm}/{num} 으로 GET 요청이 오면 처리한다.


func handler(w http.ResponseWriter, r *http.Request) {
  // 사용할 Fibonacci 알고리즘
	algorithm := r.PathValue("algorithm")
	// n번째 Fibonacci 수를 계산하기 위한 숫자 n
	p := r.PathValue("num")
	
	// 숫자로 변환
	num, err := strconv.Atoi(p)
	if err != nil {
		http.Error(w, "number should be integer string", http.StatusBadRequest)
		return
	}
	
	// 재귀적인 방법으로 계산
	if algorithm == "recursive" {
		res := fibRecurr(num)
		fmt.Fprintf(w, "result: %d", res)
		return
	}

	// cache를 이용해 계산
	res := fibCache(num)
	fmt.Fprintf(w, "result: %d", res)
}

func main() {
	// Fibonacci calculator
	http.HandleFunc("GET /fib/{algorithm}/{num}", handler)

	fmt.Println("Starting server on :8080")
	err := http.ListenAndServe(":8080", nil)
	if err != nil {
		fmt.Println("Error starting server:", err)
	}
}

pprof 설정

pprof를 아래처럼 import해준다.


import 	_ "net/http/pprof"

이제 go run main.go로 앱을 실행하고

localhost:8080/debug/pprof/ 에 접속하면 pprof를 사용할 수 있다.

다만, allocs를 눌러보면 알겠지만, 그닥 human-friendly하지 않다 😇

graphviz를 이용해 보기좋게 UI로 확인하도록 설정해보자.

`graphviz` 설치


# mac
$ brew install graphviz

# linuk
$ sudo yum install graphviz

사용법

먼저 8080포트로 서빙이 되도록 main.go를 실행한다. 그리고 아래 명령어를 호출한다.


$ curl http://localhost:8080/debug/pprof/profile\?seconds\=20 --output profile.out

20초 동안 프로파일링을 하고 profile.out에 내용이 기록된다.

아래처럼 실행하면 9090 포트에서 결과를 그래프로 확인할 수 있다.


$ go tool pprof -http localhost:9090 profile.out

아래 항목들에 대해서 동일한 방법으로 확인 가능하다.

allocs

block

cmdline

goroutine

heap

mutex

profile

threadcreate

trace

또, 일반 그래프 외에도 flame graph 등을 지원해서 목적에 맞게 편리하게 시각화 가능하다.

부하테스트를 통한 병목지점 확인

API에 대한 프로파일링을 하려면, API 요청이 이뤄지고 있는 동안 프로파일링이 되어야 한다. 이번 글에서는 부하테스트를 실행하고 프로파일링을 한다. 이 방법으로 실제환경을 mocking해서 프로파일링을 해볼 예정이다.

이번에는 bombardier를 이용해 부하를 줘서 테스트를 해보자. 그리고 프로파일링을 해보자.

(Go로 만들어진 부하테스트용 앱이다)

실행이 조금 번거로우니, shell script로 만들어 실행하고 확인하려고 한다.

부하테스트에 사용하는 bombardier 사용법은 아래를 참고 :)

bombardier

codesenberg • Updated Sep 30, 2024

이번 테스트에서는 아래 flag들을 사용한다.


-d, --duration=10s          Duration of test
-c, --connections=125       Maximum number of concurrent connections
-t, --timeout=2s            Socket/request timeout
-l, --latencies             Print latency statistics

script 작성

아래 스크립트를 이용해 fibRecurr, fibCache의 부하테스트를 수행한다.


#!/bin/bash

echo "Load Test"

# 스크립트를 종료하면 실행 중인 profile 확인용 서버를 모두 종료함
cleanup() {
    echo "Cleaning up..."
    # Kill all child processes in the same process group
    kill 0
}

# Trap SIGINT (Ctrl + C) to run the cleanup function
trap cleanup SIGINT


# 프로파일링
curl http://localhost:8080/debug/pprof/trace\?seconds\=30 --output trace.out &
curl http://localhost:8080/debug/pprof/heap\?seconds\=30 --output heap.out &
curl http://localhost:8080/debug/pprof/profile\? seconds\=30 --output cpu.out &


# 부하를 준 상태에서 GET 요청 수행 (2개 부하테스트를 병렬로 수행)
# recursive: 30번째 숫자 계산
bombardier -t 1s -l -c 10 -d 30s \
-H "Content-Type: application/json" \
-b "$PAYLOAD" \
-m GET http://localhost:8080/fib/recursive/30 &

# using cache: 30,000번째 숫자 계산
bombardier -t 1s -l -c 10 -d 30s \
-H "Content-Type: application/json" \
-b "$PAYLOAD" \
-m GET http://localhost:8080/fib/cache/30000 &

wait
# go tool 활성화 -> port에서 각 프로파일 실행
go tool trace -http localhost:9091 trace.out &
go tool pprof -http localhost:9092 heap.out &
go tool pprof -http localhost:9093 cpu.out &

wait

명령어 중 &로 끝나는 게 있는데, 백그라운드에서 커맨드를 실행하게 하는 명령어다. 각 명령어가 blocking되지 않고 background로 동시에 실행되게 하기 위해 사용했다.

wait 키워드는 &로 끝나는 모든 프로세스가 완료될 때까지 기다리기 위해 사용했다.

결과확인

힙 사용량

go tool pprof -http localhost:9092 heap.out &

이 명령어로 heap 사용량을 확인하고 있다.

localhost:9092에 들어가서 메뉴 바에서 VIEW > Flame Graph를 선택하자.

예상한 것처럼 fibCache가 99% 이상 heap을 사용하고 있는 것을 확인할 수 있다.

CPU 사용량

go tool pprof -http localhost:9093 cpu.out &

이 명령어로 cpu를 확인하고 있으므로, localhost:9093에 들어가서 CPU 사용량을 확인해보자.

fibRecurr가 전체의 34%를 차지하며, fibCache는 16.66%를 사용 중인 것을 확인할 수 있다.

재귀적으로는 30번째 수를 계산했고, cache를 이용해서는 30,000번째 수를 계산했는데도, 재귀적인 방법이 2배 이상 CPU를 더 사용함을 알 수 있다.

GC

GC는 1371번 발생했다. 빈도가 매우 빈번한 것을 고려할 때 heap 사용량이 높아 자주 GC가 동작한 것으로 추론할 수 있었다.

참고)

Wall Duration: GC에 사용된 총 시간

Self time: GC에 직접적으로 사용된 시간 (연관 함수 실행시간 등 제외)

Average Wall Duration: GC당 평균 소요시간 (이 경우 5.5ms)

Occurrences: GC 횟수

만약 재귀적 방법과 cache를 이용한 방법 모두 30번째 수를 계산한다면?

fibRecurr(30)

fibCache(30)

두 개 알고리즘 모두 30번째 수를 계산하게 했다. 이제는 heap 사용량에서 두 함수는 찾아볼 수도 없으며, 기존에 0.3GB가 사용된 대 반해 이제는 4.5MB 정도로도 처리가 가능하다.

다음으로 CPU를 확인해 보면 여전히 재귀적인 방법이 압도적인 비율로 CPU를 사용하고 있다.

전체의 67%가 이제 재귀적 함수 실행에 사용 중이다.

마지막으로 GC가 일어난 주기를 살펴본다.

총 26번이 발생했다.

GC가 동작한 총 시간은 기존보다 40배 가까이 줄었음을 확인할 수 있었다.

어떤 항목들이 heap으로 escape하고 있는지도 확인해봤다.


$  go run -gcflags="-m" main.go

# command-line-arguments
./main.go:35:26: inlining call to big.NewInt
./main.go:36:26: inlining call to big.NewInt
./main.go:48:26: inlining call to http.(*Request).PathValue
./main.go:49:18: inlining call to http.(*Request).PathValue
./main.go:48:26: inlining call to http.(*Request).patIndex
./main.go:49:18: inlining call to http.(*Request).patIndex
./main.go:71:13: inlining call to fmt.Println
./main.go:72:28: inlining call to http.ListenAndServe
./main.go:74:14: inlining call to fmt.Println
./main.go:32:18: make([]*big.Int, n + 1) escapes to heap
./main.go:35:26: []big.Word{...} escapes to heap
./main.go:35:26: &big.Int{...} escapes to heap
./main.go:36:26: []big.Word{...} escapes to heap
./main.go:36:26: &big.Int{...} escapes to heap
./main.go:40:20: new(big.Int) escapes to heap
./main.go:47:14: leaking param: w
./main.go:47:37: r does not escape
./main.go:58:14: ... argument does not escape
./main.go:58:32: res escapes to heap
./main.go:64:13: ... argument does not escape
./main.go:71:13: ... argument does not escape
./main.go:71:14: "Starting server on :8080" escapes to heap
./main.go:72:28: &http.Server{...} escapes to heap
./main.go:74:14: ... argument does not escape
./main.go:74:15: "Error starting server:" escapes to heap
Starting server on :8080

cache를 이용하는 함수 fibCache 에서 힙으로 할당이 이뤄지고 있음을 확인할 수 있었다.

결론

이번 분석을 통해 pprof을 통해 성능을 확인하는 방법을 알 수 있었다.

더불어 다음과 같은 사실을 확인했다.

재귀적인 방법으로 Fibonacci 수를 계산하는 함수는 CPU 자원을 크게 소모한다.

cache를 이용한 Fibonacci 수를 계산하는 함수는 CPU를 매우 적게 소비하지만, 큰 수를 계산하게 되면 힙을 많이 사용하게 된다.

big.Int를 사용하지 않더라도 make([]*big.Int, n + 1) 로 slice를 생성할 때 heap에 할당된다.
heap 사용량이 많아지면 GC 빈도와 GC가 발생하는 시간도 길어지게 된다.