벤치마크와 pprof - 측정하고 할당 줄이기

이 장에서 배우는 것

앞 장에서는 표 주도 테스트와 퍼징으로 코드가 맞게 동작하는지 확인했다. 이번 장은 같은 코드가 얼마나 빠르고 메모리를 얼마나 쓰는지를 다룬다. 성능 개선은 짐작으로 시작하면 대개 엉뚱한 곳을 고친다. 그래서 먼저 벤치마크(benchmark)로 숫자를 얻고, 프로파일(profile)로 시간과 메모리가 쓰이는 위치를 찾은 뒤, 그 한 곳만 고치고 같은 조건으로 다시 잰다.

• testing.B 와 b.Loop 로 벤치마크를 작성하고 -benchmem 출력의 네 열을 읽는다.
• go test 의 프로파일 옵션과 go tool pprof 로 CPU·메모리 프로파일에서 병목을 찾는다.
• strings.Builder 와 사전 용량 할당으로 할당 횟수를 줄인다.
• 탈출 분석(escape analysis)을 -gcflags=-m 로 확인하고, 값이 힙으로 나가는 이유를 설명한다.

문제 상황

배달 주문 중계 서비스는 점심 시간마다 접수가 몰린다. 접수된 주문은 배달원 앱으로 넘기기 전에 "김밥x2, 라면x1" 같은 한 줄 요약 문자열로 만든다. 이 요약 함수는 처음에 문자열을 += 로 이어 붙이는 가장 단순한 방식으로 썼고, 테스트도 통과했다. 그런데 부하가 늘자 응답 지연이 늘고 가비지 컬렉터(GC)가 도는 시간이 눈에 띄게 늘었다.

이때 "문자열 연결이 느릴 것 같으니 전부 바꾸자"라고 하면 근거가 없다. 어느 함수가 얼마나 시간을 쓰는지, 호출마다 메모리를 몇 번 할당하는지를 먼저 측정해야 한다. 이 장은 요약 함수를 두 가지 구현으로 놓고 측정 도구를 차례로 익힌다.

벤치마크로 측정하기

벤치마크 함수 작성

벤치마크는 _test.go 파일에 Benchmark 로 시작하는 함수로 쓰고, 인자는 *testing.B 하나다. Go 1.24 부터는 for b.Loop() { … } 형태를 권장한다. b.Loop 는 반복 횟수를 알아서 늘려 가며 충분히 오래 돌리고, 루프 앞뒤의 준비·정리 코드는 측정에서 제외한다. 또 루프 안에서 호출한 함수가 최적화로 통째로 지워지는 일을 막아 준다. 예전의 for i := 0; i < b.N; i++ 도 동작하지만 이런 보장이 없어서 결과를 전역 변수에 담는 습관이 필요했다.

이 장의 예제도 결과를 전역 변수에 담는다. 이유는 b.Loop 와는 별개로, 이후 testing.AllocsPerRun 으로 할당을 셀 때 반환값이 사라지지 않게 하려는 것이다.

실행은 다음과 같이 한다.

go test -run '^$' -bench . -benchmem -count 5

-run '^$' 는 일반 테스트를 건너뛴다. -bench . 는 정규식에 맞는 벤치마크를 모두 돌린다. -count 5 는 같은 측정을 다섯 번 되풀이한다. 한 번의 숫자는 다른 프로세스, 전원 상태, 캐시 상태에 흔들리므로 비교에는 여러 번의 결과를 쓴다.

-benchmem 출력 읽기

출력 한 줄은 다음 모양이다. 숫자는 기기마다 달라서 자리표시자로 적었다.

BenchmarkSummaryConcat-8    <반복 수>    <시간> ns/op    <바이트> B/op    <횟수> allocs/op

벤치마크 출력 열이 가리키는 것

열	뜻	줄이려면	비고
이름 뒤 -8	측정 때의 GOMAXPROCS	해당 없음	기기마다 다름
ns/op	호출 한 번의 평균 시간	일을 줄이거나 할당을 줄인다	흔들림이 큼
B/op	호출 한 번에 힙에 할당한 바이트	버퍼 재사용, 용량 확보	GC 부담과 비례
allocs/op	호출 한 번의 힙 할당 횟수	사전 할당, 탈출 막기	거의 흔들리지 않음

시간은 흔들리지만 allocs/op 는 코드가 같으면 거의 일정하다. 그래서 할당을 줄이는 작업에서는 이 열이 가장 믿을 만한 기준이 된다. 다만 할당이 줄었다고 항상 시간이 같은 비율로 줄지는 않는다. 시간은 반드시 따로 확인한다.

pprof 로 병목 찾기

벤치마크는 "느리다"는 사실만 알려 준다. 어디서 느린지는 프로파일이 알려 준다. go test 에 옵션을 붙이면 벤치마크를 돌리면서 프로파일 파일을 남긴다.

go test -run '^$' -bench SummaryConcat -cpuprofile cpu.out -memprofile mem.out
go tool pprof -top cpu.out
go tool pprof -sample_index=alloc_space -top mem.out
go tool pprof -list 'summaryConcat' cpu.out

CPU 프로파일

CPU 프로파일은 실행 중인 프로그램을 일정 간격으로 표본 추출해 어느 함수에서 실행 중이었는지 센다. -top 출력에는 flat 과 cum 열이 있다. flat 은 그 함수 자신의 코드에서 보낸 시간, cum 은 그 함수가 부른 함수까지 합친 시간이다. 문자열 연결 구현이라면 runtime.concatstrings, runtime.mallocgc, runtime.memmove 같은 런타임 함수가 위쪽에 보이는 것이 보통이다. 내 코드의 줄이 아니라 런타임이 위에 있다면 "할당과 복사가 시간을 쓴다"는 신호다. -list 는 함수의 소스 줄마다 시간을 붙여 보여 준다.

표본 추출이므로 벤치마크가 너무 짧으면 표본이 모자란다. 이때는 -benchtime 3s 처럼 시간을 늘린다.

메모리 프로파일

메모리 프로파일은 어느 줄에서 힙 할당이 일어났는지 기록한다. -sample_index 로 보는 기준을 고른다.

메모리 프로파일의 sample_index 선택지

값	보여 주는 것	쓰는 때	시점
alloc_space	지금까지 할당한 총 바이트	GC 부담의 원인을 찾을 때	누적
alloc_objects	지금까지 할당한 총 횟수	할당 횟수를 줄일 때	누적
inuse_space	지금 살아 있는 바이트	메모리 누수를 의심할 때	현재
inuse_objects	지금 살아 있는 객체 수	작은 객체가 쌓일 때	현재

메모리 프로파일도 표본이다. 기본값은 평균 512KB 할당마다 한 번 기록한다. 작은 벤치마크에서 결과가 비어 보이면 -memprofilerate=1 로 모든 할당을 기록하게 할 수 있다. 이 옵션은 프로그램을 느리게 하므로 성능 수치를 잴 때는 쓰지 않는다. 브라우저로 보려면 go tool pprof -http=:8080 cpu.out 를 쓰는데, 이 명령은 서버를 띄운 채 기다린다. 그래프 보기는 Graphviz 가 필요하고, 불꽃 그래프(flame graph) 보기는 필요 없다.

할당 줄이기

strings.Builder 와 사전 용량 할당

Go 의 문자열은 바꿀 수 없다. 그래서 s += x 는 s 와 x 를 합친 새 문자열을 할당하고 앞부분을 복사한다. 반복할수록 복사량도 늘어난다. strings.Builder 는 내부 바이트 슬라이스에 이어 붙이다가 String() 에서 복사 없이 문자열로 넘겨 준다. 최종 길이를 대충이라도 안다면 Grow(n) 으로 미리 확보해 중간 재할당도 없앨 수 있다.

슬라이스도 같은 원리다. append 는 용량이 모자라면 더 큰 배열을 할당하고 복사한다. 원소 수를 알면 make([]T, 0, n) 으로 용량을 잡는다. 요소가 8개인 문자열 슬라이스를 빈 상태에서 하나씩 붙이면 용량 1, 2, 4, 8 로 네 번 할당하고, 용량을 잡아 두면 한 번이다.

탈출 분석

할당은 스택과 힙 두 곳에서 일어난다. 스택은 함수가 끝나면 저절로 사라져서 GC 부담이 없고, 힙은 GC 가 치워야 한다. 컴파일러는 값이 함수 밖에서도 살아 있을 수 있다고 판단하면 힙에 둔다. 이를 탈출(escape)이라 한다. 확인은 컴파일러 옵션으로 한다.

go build -gcflags=-m main.go

출력에서 &Order{...} escapes to heap 는 그 복합 리터럴이 힙에 할당된다는 뜻이고, moved to heap: x 는 변수 x 가 힙으로 옮겨졌다는 뜻이다. can inline f 는 함수가 호출 지점에 펼쳐질 수 있다는 뜻이다. 줄 번호와 문구는 Go 버전에 따라 조금 다르므로 문구의 의미를 본다. 더 자세한 이유는 -gcflags=-m=2 로 볼 수 있다.

작은 구조체를 값으로 반환하면 호출자의 스택에 놓일 수 있다. 같은 구조체를 포인터로 반환해 전역 변수 같은 곳에 저장하면 힙으로 나간다. "복사를 피하려고 포인터를 쓴다"는 판단은 작은 구조체에서는 오히려 할당을 늘릴 수 있다.

완성 코드

main.go

package main

import (
	"fmt"
	"strconv"
	"strings"
	"testing"
)

// Item 은 주문에 담긴 한 줄이다.
type Item struct {
	Name  string
	Qty   int
	Price int
}

// Order 는 접수된 주문의 요약이다.
type Order struct {
	ID    int
	Total int
}

// 측정한 결과가 최적화로 사라지지 않도록 붙잡아 두는 전역 변수다.
var (
	sinkString string
	sinkNames  []string
	sinkOrder  *Order
	sinkTotal  int
)

func sampleItems() []Item {
	return []Item{
		{"김밥", 2, 3500},
		{"라면", 1, 4500},
		{"떡볶이", 1, 5000},
		{"순대", 1, 4000},
		{"튀김", 3, 1500},
		{"어묵", 2, 2000},
		{"쫄면", 1, 5500},
		{"만두", 4, 1000},
	}
}

func summaryConcat(items []Item) string {
	s := ""
	for i, it := range items {
		if i > 0 {
			s += ", "
		}
		s += it.Name + "x" + strconv.Itoa(it.Qty)
	}
	return s
}

func summaryBuilder(items []Item) string {
	n := 0
	for _, it := range items {
		n += len(it.Name) + 5
	}
	var b strings.Builder
	b.Grow(n)
	for i, it := range items {
		if i > 0 {
			b.WriteString(", ")
		}
		b.WriteString(it.Name)
		b.WriteByte('x')
		b.WriteString(strconv.Itoa(it.Qty))
	}
	return b.String()
}

// 아래 두 함수는 컴파일러가 지역 슬라이스를 스택에 두는 최적화와
// 무관하게 측정하려고 결과를 전역 변수에 담는다.
func fillNamesGrow(items []Item) {
	sinkNames = nil
	for _, it := range items {
		sinkNames = append(sinkNames, it.Name)
	}
}

func fillNamesPrealloc(items []Item) {
	sinkNames = make([]string, 0, len(items))
	for _, it := range items {
		sinkNames = append(sinkNames, it.Name)
	}
}

func orderTotal(items []Item) int {
	total := 0
	for _, it := range items {
		total += it.Qty * it.Price
	}
	return total
}

func newOrderValue(id int, items []Item) Order {
	return Order{ID: id, Total: orderTotal(items)}
}

func newOrderPointer(id int, items []Item) *Order {
	return &Order{ID: id, Total: orderTotal(items)}
}

func main() {
	items := sampleItems()

	concatText := summaryConcat(items)
	builderText := summaryBuilder(items)
	fmt.Println("요약(연결):", concatText)
	fmt.Println("요약(Builder):", builderText)
	fmt.Println("두 결과 동일:", concatText == builderText)

	const runs = 100
	concat := testing.AllocsPerRun(runs, func() { sinkString = summaryConcat(items) })
	builder := testing.AllocsPerRun(runs, func() { sinkString = summaryBuilder(items) })
	fmt.Printf("Builder 할당 횟수: %.0f\n", builder)
	fmt.Println("연결이 Builder 보다 많다:", concat > builder)

	grow := testing.AllocsPerRun(runs, func() { fillNamesGrow(items) })
	prealloc := testing.AllocsPerRun(runs, func() { fillNamesPrealloc(items) })
	fmt.Printf("append 만 쓴 할당 횟수: %.0f\n", grow)
	fmt.Printf("사전 용량 할당 횟수: %.0f\n", prealloc)

	byValue := testing.AllocsPerRun(runs, func() { sinkTotal += newOrderValue(1, items).Total })
	byPointer := testing.AllocsPerRun(runs, func() { sinkOrder = newOrderPointer(1, items) })
	fmt.Printf("값 반환 할당 횟수: %.0f\n", byValue)
	fmt.Printf("포인터 반환 할당 횟수: %.0f\n", byPointer)

	fmt.Println("주문 합계(값/포인터):", newOrderValue(1, items).Total, newOrderPointer(1, items).Total)
}

main_test.go

package main

import "testing"

func BenchmarkSummaryConcat(b *testing.B) {
	items := sampleItems()
	for b.Loop() {
		sinkString = summaryConcat(items)
	}
}

func BenchmarkSummaryBuilder(b *testing.B) {
	items := sampleItems()
	for b.Loop() {
		sinkString = summaryBuilder(items)
	}
}

func BenchmarkNamesGrow(b *testing.B) {
	items := sampleItems()
	for b.Loop() {
		fillNamesGrow(items)
	}
}

func BenchmarkNamesPrealloc(b *testing.B) {
	items := sampleItems()
	for b.Loop() {
		fillNamesPrealloc(items)
	}
}

줄별 해설

sink… 전역 변수 네 개는 측정 대상이 만든 값을 붙잡는 용도다. 결과를 아무도 쓰지 않으면 컴파일러가 계산을 줄일 수 있고, 전역에 저장하면 값이 함수 밖에서 살아 있어야 하므로 그대로 실행한다.

summaryConcat 은 구분자 ", " 를 붙일 때와 항목을 붙일 때 모두 새 문자열을 만든다. 항목이 8개면 할당이 여덟 번을 넘는다. strconv.Itoa 는 100 미만의 작은 수에는 미리 만들어 둔 문자열을 돌려주므로 여기서는 할당이 생기지 않는다.

summaryBuilder 는 먼저 항목마다 이름 바이트 수에 5를 더해 필요한 크기를 넉넉하게 어림한다. 5는 x 한 글자, 수량 두 자리, 구분자 두 글자의 합이다. Grow(n) 으로 한 번 확보하면 이후 쓰기는 재할당 없이 끝나고, String() 은 버퍼를 복사하지 않는다. 그래서 할당은 한 번이다. 한글은 한 글자가 UTF-8 로 3바이트이므로 len 은 글자 수가 아니라 바이트 수를 센다는 점을 기억한다.

fillNamesGrow 와 fillNamesPrealloc 은 차이가 make 한 줄뿐이다. 앞쪽은 용량 1, 2, 4, 8 로 네 번 늘어나고, 뒤쪽은 처음에 8을 잡아 한 번이다. 결과를 전역에 저장하는 것은 컴파일러가 지역 슬라이스의 저장 공간을 스택에 두는 최적화와 섞이지 않게 하려는 장치다. 실제 코드에서는 슬라이스를 반환하는 일반적인 형태로 쓴다.

newOrderValue 는 작은 구조체를 값으로 돌려주고 호출자가 필드만 읽으므로 힙이 필요 없다. newOrderPointer 는 만든 포인터가 전역 sinkOrder 에 저장되므로 힙에 할당된다.

main 은 testing.AllocsPerRun 으로 함수를 100번 돌려 호출당 평균 할당 횟수를 얻는다. 이 함수는 일반 프로그램에서도 쓸 수 있고, 실행 시간과 달리 값이 정수로 안정적이라 출력 결과가 결정적이다. 연결 방식의 정확한 횟수는 구현에 따라 달라질 수 있어서 Builder 보다 많은지만 출력한다.

main_test.go 의 벤치마크는 준비 코드(sampleItems)를 루프 앞에 두고 b.Loop 안에는 측정할 호출만 둔다.

실행 결과

$ go run main.go
요약(연결): 김밥x2, 라면x1, 떡볶이x1, 순대x1, 튀김x3, 어묵x2, 쫄면x1, 만두x4
요약(Builder): 김밥x2, 라면x1, 떡볶이x1, 순대x1, 튀김x3, 어묵x2, 쫄면x1, 만두x4
두 결과 동일: true
Builder 할당 횟수: 1
연결이 Builder 보다 많다: true
append 만 쓴 할당 횟수: 4
사전 용량 할당 횟수: 1
값 반환 할당 횟수: 0
포인터 반환 할당 횟수: 1
주문 합계(값/포인터): 38500 38500

벤치마크는 go test -run '^$' -bench . -benchmem 으로 따로 돌린다. 그 출력의 시간 값은 기기마다 달라서 여기에 싣지 않는다. 다만 allocs/op 열은 위 출력과 같은 경향으로 나온다.

실무에서 자주 틀리는 것

준비 코드를 측정 루프 안에 넣는다

틀린 코드는 매 반복마다 입력을 새로 만들어 그 비용까지 잰다.

func BenchmarkSummaryBuilder(b *testing.B) {
	for b.Loop() {
		items := sampleItems()
		sinkString = summaryBuilder(items)
	}
}

고친 코드는 입력을 루프 앞에서 한 번 만든다. b.Loop 는 루프 앞의 코드를 측정에서 제외한다.

func BenchmarkSummaryBuilder(b *testing.B) {
	items := sampleItems()
	for b.Loop() {
		sinkString = summaryBuilder(items)
	}
}

한 번 잰 숫자로 결론을 낸다

틀린 방식은 다음처럼 한 번만 돌려 두 구현의 ns/op 가 몇 퍼센트 차이라고 말하는 것이다.

go test -run '^$' -bench Summary

고친 방식은 반복 횟수를 늘리고, 실행 사이의 분산을 보고 판단한다.

go test -run '^$' -bench Summary -benchmem -count 6

여섯 번의 값이 서로 크게 겹치지 않을 때만 차이가 있다고 본다. 노트북에서는 다른 프로그램을 닫고 전원을 연결한 상태로 재는 것이 좋다.

make 에 길이를 넣고 append 한다

용량을 잡겠다고 길이 자리에 숫자를 넣으면 앞에 빈 문자열이 생긴다.

names := make([]string, len(items))
for _, it := range items {
	names = append(names, it.Name)
}
// len(names) 는 16 이고 앞 8개는 빈 문자열이다.

길이는 0, 용량은 원소 수로 둔다.

names := make([]string, 0, len(items))
for _, it := range items {
	names = append(names, it.Name)
}

복사를 피하려고 무조건 포인터를 돌려준다

작은 구조체를 포인터로 돌려주면 값이 힙으로 나가 할당이 한 번 늘 수 있다.

func newOrder(id int, items []Item) *Order {
	return &Order{ID: id, Total: orderTotal(items)}
}

필드가 두세 개인 구조체는 값으로 돌려준다. 호출자가 수정해야 하거나 구조체가 아주 크거나 nil 이 의미를 가질 때만 포인터를 쓴다. 판단이 서지 않으면 -gcflags=-m 과 allocs/op 로 확인한다.

func newOrder(id int, items []Item) Order {
	return Order{ID: id, Total: orderTotal(items)}
}

한눈에 보기

측정과 개선 도구를 목적별로 정리한 표

목적	도구·명령	읽을 곳	주의
속도·할당 측정	go test -bench . -benchmem	ns/op, B/op, allocs/op	-count 로 반복
시간 병목	-cpuprofile 와 pprof -top	flat, cum	너무 짧으면 표본 부족
할당 위치	-memprofile 와 alloc_objects	줄별 할당	표본 추출 방식
문자열 조립	strings.Builder + Grow	allocs/op 감소	길이는 바이트 기준
슬라이스 조립	make([]T, 0, n)	allocs/op 감소	길이 0 으로 시작
탈출 확인	go build -gcflags=-m	escapes to heap	문구는 버전마다 다름

개선 전후에 확인할 항목

단계	하는 일	산출물	다음 판단
1	벤치마크 작성과 기준선 측정	기준 숫자 여러 번	느린지 판단
2	프로파일로 위치 확인	상위 함수와 줄	고칠 곳 하나 선택
3	한 곳만 수정	작은 변경	테스트 통과 확인
4	같은 조건으로 재측정	전후 비교	줄지 않으면 되돌림

연습 문제

1. summaryBuilder 에서 b.Grow(n) 호출을 지우면 AllocsPerRun 결과가 어떻게 바뀔지 예측하고, 이유를 설명하라.
2. 한 구현은 1200 ns/op 640 B/op 16 allocs/op, 다른 구현은 300 ns/op 160 B/op 1 allocs/op 였다. 각 구현에서 할당 한 번당 평균 바이트를 계산하고, 두 구현의 차이를 한 문장으로 해석하라.
3. newOrderValue 와 newOrderPointer 중 어느 쪽에서 escapes to heap 가 나올지 예측하고, 확인에 쓸 명령을 적어라.
4. 메모리 프로파일에서 할당된 바이트가 아니라 할당 횟수가 많은 줄부터 보고 싶다. 어떤 명령을 쓰는가?

정답과 해설

1. 1보다 커진다. Grow 가 없으면 Builder 내부 버퍼가 비어 있다가 쓰기 중 용량이 모자랄 때마다 더 큰 배열을 할당하고 복사한다. 요약 문자열이 80바이트 안팎이므로 작은 크기부터 두 배씩 커지며 여러 번 할당한다. 정확한 횟수는 구현에 따라 다르므로 1보다 크다는 점만 확인하면 된다.
2. 첫째는 640 ÷ 16 = 40바이트, 둘째는 160 ÷ 1 = 160바이트다. 첫째는 작은 할당을 여러 번 하는 구현이고 둘째는 큰 버퍼를 한 번 잡는 구현이다. 전체 바이트도 넷의 일이고 횟수도 열여섯 대 하나이므로, 둘째가 할당 횟수와 바이트 양 모두 적다고 해석한다. 시간 차이의 대부분이 할당 횟수에서 왔을 가능성이 높지만 프로파일로 확인해야 한다.
3. newOrderPointer 쪽에서 &Order{...} escapes to heap 가 나온다. 결과 포인터가 전역 변수에 저장되어 함수 밖에서도 살아 있기 때문이다. 확인 명령은 go build -gcflags=-m main.go 이고, 이유까지 보려면 -gcflags=-m=2 를 쓴다. newOrderValue 쪽에는 이 줄이 나오지 않고 can inline newOrderValue 같은 줄이 보인다.
4. go tool pprof -sample_index=alloc_objects -top mem.out 을 쓴다. alloc_space 는 바이트 기준이고 alloc_objects 는 횟수 기준이다. 표본이 모자라면 프로파일을 만들 때 -memprofilerate=1 을 붙인다.