프로파일링이란 프로그램의 성능 지표를 프로그램이 실행 중에 실시간으로 측정 기록하는 것을 말합니다. 프로파일링으로 측정하는 성능 지표는 프로그램 실행 시간, 메모리 사용량, 함수 호출 시간과 빈도, 메모리가 생성되는 시점과 빈도 등이 있습니다. 프로파일링 도구를 통해서 수집된 데이터는 파일 형태로 저장되어서 분석 툴을 사용해 성능 지표들을 분석하게 됩니다.
프로그램의 성능 지표를 수집해 프로그램 성능을 최적화하는 데 주로 사용됩니다. 프로그램 성능이 저하되는 여러 이유가 있지만 대부분의 경우 병목 지점이 발생해 전체 프로그램 성능이 저하되는 경우가 많이 발생합니다. 프로파일링은 이런 병목 지점들과 병목 지점들이 발생하는 원인을 파악하는 데 도움을 주기 때문에 성능 최적화에 가장 기본적인 툴입니다.
1. 특정 구간 프로파일링
Go 언어에서 프로파일링 데이터를 수집하는 방법은 몇 가지가 있습니다. 그중에서 특정 구간을 프로파일링하는 법을 살펴보겠습니다. 이 방법은 성능 개선을 원하는 특정 함수나 구간을 조사할 때 유용한 방법입니다.
- 성능 측정을 시작하길 원하는 곳에 pprof.StartCPUProfile() 함수를 콜합니다. 이것으로 성능 측정을 시작합니다.
- 성능 측정을 끝내는 곳에 pprof.StopCPUProfile( ) 함수를 콜합니다. 이로써 성능 측정을 마무리하고 결과를 저장합니다.
그런 뒤 생성된 파일을 go의 프로파일링 툴인 pprof를 사용해 결과를 분석합니다. 예제를 통해서 살펴보겠습니다.
예제 코드: https://github.com/tuckersGo/mustHaveGo2/blob/main/ch27/profiling1/main.go
package main
import (
"fmt"
"log"
"os"
"runtime/pprof"
"time"
)
func Fib(n int) int {
if n == 0 {
return 0
} else if n == 1 {
return 1
} else {
return Fib(n-1) + Fib(n-2)
}
}
func main() {
// ① 프로파일링 결과를 저장할 파일을 만듭니다
f, err := os.Create("cpu.prof")
if err != nil {
log.Fatal(err)
}
defer f.Close()
// ② 프로파일링을 시작합니다.
pprof.StartCPUProfile(f)
// ③ 프로그램 종료 전에 프로파일링을 종료합니다
defer pprof.StopCPUProfile()
fmt.Println(Fib(50))
// 10초를 대기합니다.
time.Sleep(10 * time.Second)
}
12586269025
① 프로파일링 결과를 저장할 파일 핸들을 만듭니다. ② 프로파일링을 시작합니다. 이때 인수로 앞서 만든 파일 핸들을 넣어줍니다. ③ 프로그램 종료 전에 프로파일링을 종료합니다. 앞서 만든 파일에 프로파일링 결과를 저장하게 됩니다.
프로그램 실행이 종료된 후에 cpu.prof 파일이 생성된 것을 알 수 있습니다. 이제 pprof 툴을 통해서 프로그래밍 결과를 분석합니다. 아래 명령을 실행해 pprof 툴을 시작합니다.
go tool pprof cpu.prof
pprof 툴을 실행하면 다음과 같은 내용이 출력됩니다.
PS C:\Users\kongb\goprojects\profiling> go tool pprof cpu.prof
File: profiling.exe
Build ID: C:\Users\kongb\goprojects\profiling\profiling.exe2023-08-27
16:30:19.3298906 -0700 PDT
Type: cpu
Time: Aug 27, 2023 at 4:30pm (PDT)
Duration: 74.69s, Total samples = 42.86s (57.38%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)
pprof 툴 콘솔이 실행된 것으로 여기에 명령어를 입력해 분석하게 됩니다. 첫 번째로 top 명령을 실행하겠습니다.
(pprof) top
Showing nodes accounting for 42.05s, 98.11% of 42.86s total
Dropped 67 nodes (cum <= 0.21s)
Showing top 10 nodes out of 16
flat flat% sum% cum cum%
41.37s 96.52% 96.52% 41.43s 96.66% main.Fib
0.48s 1.12% 97.64% 0.48s 1.12% runtime.stdcall1
0.06s 0.14% 97.78% 0.27s 0.63% runtime/pprof.(*profMap).lookup
0.03s 0.07% 97.85% 0.26s 0.61% runtime.findRunnable
0.03s 0.07% 97.92% 0.51s 1.19% runtime.semawakeup
0.03s 0.07% 97.99% 0.61s 1.42% runtime.wakep
0.02s 0.047% 98.04% 0.85s 1.98% runtime.schedule
0.01s 0.023% 98.06% 0.81s 1.89% runtime.park_m
0.01s 0.023% 98.09% 0.55s 1.28% runtime.startm
0.01s 0.023% 98.11%. 0.28s 0.65% runtime/pprof.(*profileBuilder).
addCPUData
(pprof)
top 명령은 가장 점유율이 높은 순으로 표시해줍니다. 결과에서 알 수 있듯이 Fib( ) 함수가 전체 중 96.52%를 차지하는 것을 알 수 있습니다. 이로써 어떤 함수가 전체 성능에 가장 많은 영향을 주는지 알 수 있습니다. 즉 Fib() 함수 성능만 개선하면 전체 프로그램 성능이 개선되는 것을 알 수 있습니다.
두 번째 명령어인 web을 실행하겠습니다.
(pprof) web
failed to execute dot. Is Graphviz installed? Error: exec: "dot": executable
file not found in %PATH%
web을 실행하려면 Graphviz가 설치되어 있어야 한다는 메시지입니다. Graphviz는 그래프를 그릴 수 있는 오픈 소스 프로그램입니다. Graphviz를 설치하겠습니다.
1.1 윈도우에서 Graphviz 설치하기
01 윈도우에서는 https://graphviz.org/download/#Widows에서 설치 파일을 다운로드받을 수 있습니다. 최신 버전의 Win64 EXE 인스톨러를 다운로드받습니다.
다운로드받은 설치 파일을 더블클릭해 설치합니다.
02 설치 옵션 중 두 번째를 선택해 Graphviz를 PATH 환경 설정에 추가되게 합니다.
1.2 리눅스에서 Graphviz 설치하기
우분투 같은 데비안 계열에서는 다음 명령어로 설치할 수 있습니다.
sudo apt install graphviz
페도라 계열에서는 다음 명령어를 사용합니다.
sudo yum install graphviz
1.3 맥OS에서 Graphviz 설치하기
다음 명령어로 설치합니다.
brew install graphviz
1.4 Web 실행하기
Graphviz를 설치한 뒤 다시 pprof 툴을 실행해 web 명령을 실행합니다. 그러면 자동으로 인터넷 브라우저가 실행되어 분석 결과가 그래프 형태로 출력됩니다.
그래프에서 보이는 것과 같이 전체 41.43초의 실행 시간 중 Fib( ) 함수가 41.37초가 차지해 전체의 96.52%를 차지하는 것을 알 수 있습니다.
자 이제 이 프로그램을 개선하겠습니다.
package main
import (
"fmt"
"log"
"os"
"runtime/pprof"
"time"
)
// ① 피보나치 결과를 저장할 맵
var fibMap [65535]int
func Fib(n int) int {
// ② 이미 계산했다면 바로 반환합니다.
f := fibMap[n]
if f > 0 {
return f
}
if n == 0 {
return 0
} else if n == 1 {
f = 1
} else {
f = Fib(n-1) + Fib(n-2)
}
// ③ 결과를 저장합니다.
fibMap[n] = f
return f
}
func main() {
f, err := os.Create("cpu.prof")
if err != nil {
log.Fatal(err)
}
defer f.Close()
pprof.StartCPUProfile(f)
defer pprof.StopCPUProfile()
fmt.Println(Fib(50))
// 10초를 대기합니다.
time.Sleep(10 * time.Second)
}
12586269025
결과를 맵에 저장해 이미 계산한 결과가 있다면 바로 반환하도록 개선했습니다. 이와 같이 메모리를 사용해 중간 결과를 저장하는 방식을 다이나믹 프로그래밍 중 메모이징 방식이라고 합니다.
① 중간 결과를 저장할 맵을 만듭니다. 최대 65535까지의 결과를 저장합니다. ② 이미 맵에 결과가 저장되어 있다면 바로 반환합니다. ③ 결과를 저장합니다. 이로써 다시 중간 결과를 사용할 수 있습니다.
(pprof) top
Showing nodes accounting for 30ms, 100% of 30ms total
Showing top 10 nodes out of 21
flat flat% sum% cum cum%
10ms 33.33% 33.33% 10ms 33.33% runtime.findRunnable
10ms 33.33% 66.67% 10ms 33.33% runtime.stdcall1
10ms 33.33% 100% 10ms 33.33% runtime.stdcall4
0 0% 100% 10ms 33.33% runtime.(*fixalloc).alloc
0 0% 100% 10ms 33.33% runtime.(*mheap).alloc.func1
0 0% 100% 10ms 33.33% runtime.(*mheap).allocMSpanLocked
0 0% 100% 10ms 33.33% runtime.(*mheap).allocSpan
0 0% 100% 20ms 66.67% runtime.mcall
0 0% 100% 10ms 33.33% runtime.notewakeup
0 0% 100% 20ms 66.67% runtime.park_m
(pprof)
top 실행 결과를 보면 Fib() 함수가 상위 결과에서 없어진 것을 알 수 있습니다. 그만큼 Fib() 함수 성능이 개선되었고 그럼으로써 전체 프로그램 성능도 비약적으로 향상된 것을 알 수 있습니다.
2. 서버에서 프로파일링
일반적으로 웹 서버와 같이 계속 실행되는 서버 프로그램에서는 특정 구간만 프로파일링을 하기가 어렵습니다. 이번에는 계속 상주하고 실행되는 웹 서버에서 프로파일링하는 법을 살펴보겠습니다.
예제 코드: https://github.com/tuckersGo/mustHaveGo2/blob/main/ch27/webprofiling/main.go
package main
import (
"math/rand"
"net/http"
_ "net/http/pprof" // 1 웹 프로파일링을 실행합니다.
"time"
)
func main() {
http.HandleFunc("/log", logHandler)
http.ListenAndServe(":8080", nil)
}
func logHandler(w http.ResponseWriter, r *http.Request) {
ch := make(chan int)
go func() {
// simulation of a time consuming process like writing logs into db
time.Sleep(time.Duration(rand.Intn(400)) * time.Millisecond)
ch <- http.StatusOK
}()
select {
case status := <-ch:
w.WriteHeader(status)
case <-time.After(200 * time.Millisecond):
w.WriteHeader(http.StatusRequestTimeout)
}
}
① net/http/pprof 패키지를 임포트하면 자동으로 웹 프로파일링이 실행됩니다. 이 패키지는 임포트하면 자동으로 실행되기 때문에 빈 칸 지시자( _ )를 통해서 임포트가 사라지지 않도록 해줍니다.
빌드를 하고 실행하면 웹 서버가 실행됩니다. 웹 브라우저를 실행해 http://localhost:8080/log에 접속하면 ‘200 Status OK’ 또는 ‘400 Bad Request’가 랜덤하게 발생하는 것을 알 수 있습니다. 이제 웹 브라우저에 http://localhost:8080/debug/pprof/를 입력하면 다음과 같은프로파일링 화면을 볼 수 있습니다.
우리가 net/http/pprof 패키지를 임포트했기 때문에 이 프로파일링 페이지가 자동으로 제공됩니다. 메뉴를 하나씩 살펴보겠습니다.
- allocs: 프로그램에서 할당된 모든 메모리와 어디에서 할당되었는지 소스 위치를 통해알수있게해줍니다.
- block: Mutex나 WaitGroup, 채널 등과 같은 멀티 스레드 환경에서 현재 대기하는 객체들을 보여줍니다.
- cmdline: 이 프로그램이 실행될 때 어떤 실행 인수로 실행되었는지 보여줍니다.
- goroutine: 현재 실행되고 있는 모든 고루틴을 보여줍니다.
- heap: 현재 메모리가 할당되어 사용 중인 객체들을 보여줍니다.
- mutex: 현재 대기 중인 Mutex의 콜스택을 보여줍니다.
- profile: CPU 프로파일링을 시작하고 그 결과를 파일로 다운로드받을 수 있습니다. 프로파일링하는 시간은 seconds 파라미터로 조정하거나 파라미터가 없으면 30초 동안 동작합니다. 프로파일링 결과는 Go 프로파일링 툴을 통해서 분석할 수 있습니다. http://localhost:8080/debug/pprof/profile?seconds=5와 같이 입력하면 5초만 동작하게 됩니다.
- threadcreate: 새로운 OS 스레드를 생성한 콜스택을 보여줍니다.
- trace: 트레이스 정보 수집을 시작한 뒤 그 결과를 파일로 다운로드받을 수 있습니다. 트레이스 정보는 Go 프로파일링 툴을 통해서 분석할 수 있습니다.
2.1 Hey로 부하 테스트하기
Hey 프로그램을 사용해 웹 서버에 부하를 줘서 테스트하겠습니다. Hey는 웹 서버에 요청을 반복 전송해 웹 서버 성능을 테스트할 때 사용됩니다.
Hey는 https://github.com/rakyll/hey에서 받으셔도 되고 소스 예제 폴더에 포함시켜 뒀으니 그것을 사용하셔도 됩니다. 아래 명령을 실행해 웹 서버에 부하를 줍니다.
.\hey.exe http://localhost:8080/log
실행 결과를 통해서 웹 서버 요청에 대한 응답 속도를 알 수 있습니다.
Summary:
Total: 0.8360 secs
Slowest: 0.2259 secs
Fastest: 0.0148 secs
Average: 0.1524 secs
Requests/sec: 239.2377
http://localhost:8080/debug/pprof/를 다시 접속하면 allocs나 goroutine 등 여러 수치들이 변경된 것을 알 수 있습니다.
2.2 프로파일링 결과 분석
이제 프로파일링을 하겠습니다. http://localhost:8080/debug/pprof/의 profile을 클릭해 프로파일링을 실행합니다. 그런뒤 hey를 다시 실행해 부하를 주겠습니다. 30초가 지난 뒤 profile 결과를 다운로드받을 수 있습니다.
프로파일 결과를 다운로드받은 폴더에서 다음 명령을 실행해줍니다.
go tool pprof profile
뒤의 profile은 다운로드받은 파일명입니다. 다른 이름으로 저장하셨다면 변경한 파일명을 입력해야 합니다.
pprof 프롬프트에 top5를 입력하면 가장 많은 CPU 실행시간을 차지한 상위 5개의 함수를 볼 수 있습니다.
(pprof) top5
Showing nodes accounting for 210ms, 46.67% of 450ms total
Showing top 5 nodes out of 82
flat flat% sum% cum cum%
70ms 15.56% 15.56% 70ms 15.56% runtime.stdcall1
60ms 13.33% 28.89% 60ms 13.33% runtime.cgocall
40ms 8.89% 37.78% 40ms 8.89% runtime.stdcall6
20ms 4.44% 42.22% 20ms 4.44% runtime.(*waitq).dequeue
20ms 4.44% 46.67% 20ms 4.44% runtime.acquirem
(pprof)
pprof 프롬프트에 web을 입력하면 앞에서 봤던 것처럼 그래프 형태로 알려줍니다.
이렇게 프로파일링과 부하테스트를 통해서 우리는 CPU 성능이 어떤 곳에서 주로 사용되는지 알 수 있고 이를 통해 병목점을 발견하고 개선해 전체 성능을 향상시킬 수 있습니다. 프로그래밍에는 80:20 법칙이 적용된다고 합니다. 전체 코드 중 20%의 코드가 전체 성능 중 80%를 차지한다고 말합니다. 그래서 프로그램 성능을 증가시키기 위해서 전체 코드를 모두 개선할 필요가 없고 성능 비중이 높은 20% 코드만 찾아내서 개선해도 전체 성능이 크게 향상됩니다. 프로파일링은 성능 비중이 높은 일부 코드를 찾아낼 때 사용되는 툴입니다.
핵심 요약
- 프로파일링을 통해서 함수별 CPU 사용량을 알 수 있습니다.
- CPU뿐 아니라 메모리, 고루틴 등 다양한 지표를 얻을 수 있습니다.
- HTTP 프로파일링 페이지를 통해서 서버 프로그램의 다양한 지표를 얻을 수 있습니다.
- 프로파일링은 프로그램 성능 중비 중이 높은 코드를 찾는 데 도움을 줍니다.
