Caddy 프로파일링

원문 보기 위키 갱신 2026.10.03

Caddy 프로파일링 (Profiling Caddy)

출처: Caddy 공식 문서

본문

**프로그램 프로파일(program profile)**은 런타임 시 프로그램이 리소스를 사용하는 방식의 스냅샷이에요. 프로파일은 문제 영역을 식별하고, 버그와 충돌을 해결하며, 코드를 최적화하는 데 매우 유용할 수 있어요.

Caddy는 프로파일 캡처에 Go의 도구를 사용해요. 이를 pprof라고 하며 go 명령에 내장되어 있어요.

프로파일은 CPU와 메모리의 소비자를 보고하고, 고루틴(goroutine)의 스택 트레이스를 보여주며, 교착 상태(deadlock)나 경합이 높은 동기화 프리미티브를 추적하는 데 도움을 줘요.

Caddy에서 특정 버그를 보고할 때 프로파일을 요청할 수 있어요. 이 글이 도움이 될 거예요. Caddy로 프로파일을 얻는 방법과 결과 pprof 프로파일을 일반적으로 사용하고 해석하는 방법을 모두 설명해요.

시작하기 전에 알아야 할 두 가지:

Caddy 프로파일은 보안에 민감하지 않아요. 메모리 내용이 아닌 무해한 기술적 판독값을 포함해요. 시스템에 대한 접근 권한을 부여하지 않아요. 공유해도 안전해요.
프로파일은 가벼우며 프로덕션에서 수집할 수 있어요. 사실 많은 사용자에게 권장되는 모범 사례이기도 해요. 이 글의 뒷부분을 참고하세요.

프로파일 얻기

프로파일은 admin 인터페이스의 /debug/pprof/에서 사용할 수 있어요. Caddy가 실행 중인 머신에서 브라우저로 열어보세요:

http://localhost:2019/debug/pprof/

기본적으로 admin API는 로컬에서만 접근 가능해요. 원격, VM, 컨테이너에서 실행 중이라면 이 엔드포인트에 접근하는 방법은 다음 섹션을 참고하세요.

카운트와 링크의 단순한 표가 보일 거예요. 예:

Count	Profile
79	allocs
0	block
0	cmdline
22	goroutine
79	heap
0	mutex
0	profile
29	threadcreate
0	trace
	full goroutine stack dump

카운트는 누수를 빠르게 식별하는 편리한 방법이에요. 누수가 의심되면 페이지를 반복해서 새로고침하면 하나 이상의 카운트가 계속 증가하는 것을 볼 수 있어요. heap 카운트가 증가하면 메모리 누수 가능성이 있고, goroutine 카운트가 증가하면 고루틴 누수 가능성이 있어요.

프로파일을 클릭해서 어떻게 생겼는지 확인해보세요. 일부는 비어 있을 수 있는데, 자주 있는 일이라 정상이에요. 가장 흔히 사용되는 것은 goroutine(함수 스택), heap(메모리), profile(CPU)이에요. 다른 프로파일들은 뮤텍스 경합이나 교착 상태를 해결하는 데 유용해요.

맨 아래에 각 프로파일에 대한 간단한 설명이 있어요:

allocs: 과거의 모든 메모리 할당 샘플
block: 동기화 프리미티브에서 블로킹을 유발한 스택 트레이스
cmdline: 현재 프로그램의 명령줄 호출
goroutine: 현재 모든 고루틴의 스택 트레이스. debug=2를 쿼리 파라미터로 사용하면 복구되지 않은 panic과 같은 형식으로 내보내요.
heap: 살아있는 객체의 메모리 할당 샘플. gc GET 파라미터를 지정해 heap 샘플을 찍기 전에 GC를 실행할 수 있어요.
mutex: 경합하는 뮤텍스의 보유자 스택 트레이스
profile: CPU 프로파일. seconds GET 파라미터로 기간을 지정할 수 있어요. 프로파일 파일을 얻은 후 go tool pprof 명령을 사용해 프로파일을 조사해요.
threadcreate: 새 OS 스레드 생성으로 이어진 스택 트레이스
trace: 현재 프로그램 실행의 트레이스. seconds GET 파라미터로 기간을 지정할 수 있어요. 트레이스 파일을 얻은 후 go tool trace 명령을 사용해 트레이스를 조사해요.

"goroutine"과 "full goroutine stack dump"의 차이는 ?debug=2 파라미터예요. 전체 스택 덤프는 panic 이후 보는 출력과 같고, 더 상세하며 특히 동일한 고루틴을 접지(collapse)하지 않아요.

프로파일 다운로드하기

위의 pprof 인덱스 페이지에서 링크를 클릭하면 텍스트 형식의 프로파일을 얻을 수 있어요. 디버깅에 유용하며, 추가 도구 없이 명확한 단서를 찾기 위해 훑어볼 수 있기 때문에 우리 Caddy 팀이 선호하는 방식이에요.

하지만 바이너리가 실제로 기본 형식이에요. HTML 링크는 ?debug= 쿼리 문자열 파라미터를 붙여 텍스트로 형식화하는데, 텍스트 표현이 없는 (CPU) "profile" 링크는 예외예요.

설정할 수 있는 쿼리 문자열 파라미터는 다음과 같아요 (Go 문서 출처):

debug=N (cpu 제외 모든 프로파일): 응답 형식: N = 0: 바이너리(기본), N > 0: 일반 텍스트
gc=N (heap 프로파일): N > 0: 프로파일링 전에 가비지 컬렉션 주기 실행
seconds=N (allocs, block, goroutine, heap, mutex, threadcreate 프로파일): 델타 프로파일 반환
seconds=N (cpu, trace 프로파일): 주어진 기간 동안 프로파일링

이것들은 HTTP 엔드포인트이므로 curl이나 wget 같은 모든 HTTP 클라이언트로 프로파일을 다운로드할 수 있어요.

프로파일을 다운로드한 후 GitHub 이슈 댓글에 업로드하거나 pprof.me 같은 사이트를 사용할 수 있어요. CPU 프로파일은 특히 flamegraph.com도 옵션이에요.

원격 접근

이미 admin API에 로컬로 접근할 수 있다면 이 섹션은 건너뛰어요.

기본적으로 Caddy의 admin API는 루프백 소켓에서만 접근할 수 있어요. 그러나 Caddy의 /debug/pprof 엔드포인트에 원격으로 접근하는 방법은 적어도 3가지가 있어요:

사이트를 통한 리버스 프록시

쉬운 방법 중 하나는 사이트에서 그냥 리버스 프록시하는 것이에요:

reverse_proxy /debug/pprof/* localhost:2019 {
	header_up Host {upstream_hostport}
}

물론 이렇게 하면 사이트에 연결할 수 있는 사람에게 프로파일이 제공돼요. 원하지 않는다면 원하는 HTTP 인증 모듈로 인증을 추가할 수 있어요.

(/debug/pprof/* 매처를 잊지 마세요. 그렇지 않으면 admin API 전체를 프록시하게 돼요!)

SSH 터널

또 다른 방법은 SSH 터널을 사용하는 것이에요. 이것은 여러분의 컴퓨터와 서버 사이의 SSH 프로토콜을 사용하는 암호화된 연결이에요. 컴퓨터에서 이런 명령을 실행해요:

ssh -N [email protected] -L 8123:localhost:2019

이는 localhost:8123(로컬 머신에서)을 example.com의 localhost:2019로 터널링해요. username, example.com, 포트를 필요에 따라 바꿔주세요.

이 명령은 포그라운드에서 실행돼요. Ctrl+Z로 프로세스를 백그라운드로 만들면 터널이 일시 중지되어 터널을 사용하는 연결이 실패한다는 점을 명심하세요.

그런 다음 다른 터미널에서 이렇게 curl을 실행할 수 있어요:

curl -v http://localhost:8123/debug/pprof/ -H "Host: localhost:2019"

터널 양쪽에서 포트 2019를 사용하면 -H "Host: ..."의 필요를 피할 수 있어요(단, 여러분 컴퓨터에서 포트 2019가 이미 사용 중이면 안 됩니다, 즉 로컬에 Caddy가 실행 중이면 안 됩니다).

터널이 활성화된 동안 admin API를 마음껏 접근할 수 있어요. 터널을 닫으려면 ssh 명령에 Ctrl+C를 입력하세요.

장기 실행 터널

위 명령으로 터널을 실행하려면 터미널을 계속 열어두어야 해요. 터널을 백그라운드로 실행하려면 이렇게 시작할 수 있어요:

ssh -f -N -M -S /tmp/caddy-tunnel.sock [email protected] -L 8123:localhost:2019

이렇게 하면 백그라운드로 시작하고 /tmp/caddy-tunnel.sock에 컨트롤 소켓을 만들어요. 그런 다음 컨트롤 소켓으로 터널을 닫을 수 있어요:

ssh -S /tmp/caddy-tunnel.sock -O exit e

원격 admin API

admin API가 인증된 클라이언트의 원격 연결을 수락하도록 구성할 수도 있어요.

(TODO: 이에 대한 글 작성.)

고루틴 프로파일

고루틴 덤프는 어떤 고루틴이 존재하고 그들의 호출 스택이 무엇인지 아는 데 유용해요. 즉, 현재 실행 중이거나 블로킹/대기 중인 코드에 대한 아이디어를 제공해요.

"goroutines"를 클릭하거나 /debug/pprof/goroutine?debug=1로 이동하면 고루틴 목록과 그 호출 스택이 보여요. 예:

goroutine profile: total 88
23 @ 0x43e50e 0x436d37 0x46bda5 0x4e1327 0x4e261a 0x4e2608 0x545a65 0x5590c5 0x6b2e9b 0x50ddb8 0x6b307e 0x6b0650 0x6b6918 0x6b6921 0x4b8570 0xb11a05 0xb119d4 0xb12145 0xb1d087 0x4719c1
#	0x46bda4	internal/poll.runtime_pollWait+0x84			runtime/netpoll.go:343
#	0x4e1326	internal/poll.(*pollDesc).wait+0x26			internal/poll/fd_poll_runtime.go:84
#	0x4e2619	internal/poll.(*pollDesc).waitRead+0x279		internal/poll/fd_poll_runtime.go:89
#	0x4e2607	internal/poll.(*FD).Read+0x267				internal/poll/fd_unix.go:164
#	0x545a64	net.(*netFD).Read+0x24					net/fd_posix.go:55
#	0x5590c4	net.(*conn).Read+0x44					net/net.go:179
#	0x6b2e9a	crypto/tls.(*atLeastReader).Read+0x3a			crypto/tls/conn.go:805
#	0x50ddb7	bytes.(*Buffer).ReadFrom+0x97				bytes/buffer.go:211
#	0x6b307d	crypto/tls.(*Conn).readFromUntil+0xdd			crypto/tls/conn.go:827
#	0x6b064f	crypto/tls.(*Conn).readRecordOrCCS+0x24f		crypto/tls/conn.go:625
#	0x6b6917	crypto/tls.(*Conn).readRecord+0x157			crypto/tls/conn.go:587
#	0x6b6920	crypto/tls.(*Conn).Read+0x160				crypto/tls/conn.go:1369
#	0x4b856f	io.ReadAtLeast+0x8f					io/io.go:335
#	0xb11a04	io.ReadFull+0x64					io/io.go:354
#	0xb119d3	golang.org/x/net/http2.readFrameHeader+0x33		golang.org/x/[email protected]/http2/frame.go:237
#	0xb12144	golang.org/x/net/http2.(*Framer).ReadFrame+0x84		golang.org/x/[email protected]/http2/frame.go:498
#	0xb1d086	golang.org/x/net/http2.(*serverConn).readFrames+0x86	golang.org/x/[email protected]/http2/server.go:818

1 @ 0x43e50e 0x44e286 0xafeeb3 0xb0af86 0x5c29fc 0x5c3225 0xb0365b 0xb03650 0x15cb6af 0x43e09b 0x4719c1
#	0xafeeb2	github.com/caddyserver/caddy/v2/cmd.cmdRun+0xcd2					github.com/caddyserver/caddy/[email protected]/cmd/commandfuncs.go:277
#	0xb0af85	github.com/caddyserver/caddy/v2/cmd.init.1.func2.WrapCommandFuncForCobra.func1+0x25	github.com/caddyserver/caddy/[email protected]/cmd/cobra.go:126
#	0x5c29fb	github.com/spf13/cobra.(*Command).execute+0x87b						github.com/spf13/[email protected]/command.go:940
#	0x5c3224	github.com/spf13/cobra.(*Command).ExecuteC+0x3a4					github.com/spf13/[email protected]/command.go:1068
#	0xb0365a	github.com/spf13/cobra.(*Command).Execute+0x5a						github.com/spf13/[email protected]/command.go:992
#	0xb0364f	github.com/caddyserver/caddy/v2/cmd.Main+0x4f						github.com/caddyserver/caddy/[email protected]/cmd/main.go:65
#	0x15cb6ae	main.main+0xe							caddy/main.go:11
#	0x43e09a	runtime.main+0x2ba							runtime/proc.go:267

1 @ 0x43e50e 0x44e9c5 0x8ec085 0x4719c1
#	0x8ec084	github.com/caddyserver/certmagic.(*Cache).maintainAssets+0x304	github.com/caddyserver/[email protected]/maintain.go:67

...

첫 줄 goroutine profile: total 88은 무엇을 보고 있는지, 고루틴이 몇 개인지 알려줘요.

고루틴 목록이 이어져요. 이들은 빈도 내림차순으로 호출 스택별로 그룹화돼요.

고루틴 줄은 <count> @ <addresses...> 구문이에요.

줄은 관련 호출 스택을 가진 고루틴의 수로 시작해요. @ 기호는 고루틴을 시작한 호출 명령 주소, 즉 함수 포인터의 시작을 나타내요. 각 포인터는 함수 호출, 즉 호출 프레임이에요.

많은 고루틴이 같은 첫 호출 주소를 공유하는 것을 볼 수 있을 거예요. 이것이 프로그램의 main, 즉 진입점이에요. 일부 고루틴은 프로그램에 다양한 init() 함수가 있고 Go 런타임도 고루틴을 생성할 수 있기 때문에 거기서 시작하지 않을 수 있어요.

이후 줄은 #로 시작하며 사실상 독자를 위한 주석이에요. 고루틴의 현재 스택 트레이스를 담고 있어요. 위쪽은 스택의 위, 즉 현재 실행 중인 코드 줄을 나타내요. 아래쪽은 스택의 아래, 즉 고루틴이 처음 실행을 시작한 코드를 나타내요.

스택 트레이스는 이런 형식이에요:

<address> <package/func>+<offset> <filename>:<line>

주소는 함수 포인터이고, 그 다음 Go 패키지와 함수 이름(메서드라면 관련 타입 이름), 그리고 함수 내 명령 오프셋이 나와요. 그 다음 아마 가장 유용한 정보인 파일과 줄 번호가 끝에 있어요.

전체 고루틴 스택 덤프

쿼리 문자열 파라미터를 ?debug=2로 바꾸면 전체 덤프를 얻어요. 여기에는 모든 고루틴의 상세한 스택 트레이스가 포함되며 동일한 고루틴은 접지되지 않아요. 이 출력은 바쁜 서버에서는 매우 클 수 있지만 흥미로운 정보예요!

위 첫 호출 스택에 해당하는 것을 살펴볼게요(잘림):

goroutine 61961905 [IO wait, 1 minutes]:
internal/poll.runtime_pollWait(0x7f9a9a059eb0, 0x72)
	runtime/netpoll.go:343 +0x85
...
golang.org/x/net/http2.(*serverConn).readFrames(0xc001756f00)
	golang.org/x/[email protected]/http2/server.go:818 +0x87
created by golang.org/x/net/http2.(*serverConn).serve in goroutine 61961902
	golang.org/x/[email protected]/http2/server.go:930 +0x56a

장황함에도 불구하고 이 덤프가 고유하게 제공하는 가장 유용한 정보는 모든 고루틴의 첫 줄과 마지막 줄이에요.

첫 줄은 고루틴의 번호(61961905), 상태("IO wait"), 지속 시간("1 minutes")을 담고 있어요:

고루틴 번호: 네, 고루틴에도 번호가 있어요! 하지만 우리 코드에는 노출되지 않아요. 그러나 이 번호는 스택 트레이스에서 특히 유용한데, 어떤 고루틴이 이것을 생성했는지 볼 수 있기 때문이에요(끝부분 참고: "created by ... in goroutine 61961902"). 아래 보여주는 도구로 이걸 시각적 그래프로 그릴 수 있어요.

상태: 이것은 고루틴이 현재 무엇을 하고 있는지 알려줘요. 볼 수 있는 몇 가지 가능한 상태:

running: 코드를 실행 중 - 좋아요!
IO wait: 네트워크를 기다리는 중. 비차단 네트워크 폴러에 주차되어 있으므로 OS 스레드를 소비하지 않아요.
sleep: 우리 모두 더 필요해요.
select: select에 블로킹; 케이스가 사용 가능해지기를 기다리는 중.
select (no cases): 빈 select select {}에 특별히 블로킹. Caddy는 종료가 다른 고루틴에서 시작되기 때문에 main에서 계속 실행되도록 하나를 사용해요.
chan receive: 채널 수신(<-ch)에 블로킹.
semacquire: 세마포어(저수준 동기화 프리미티브) 획득을 기다리는 중.
syscall: 시스템 호출 실행 중. OS 스레드를 소비해요.

지속 시간: 고루틴이 존재한 기간. 고루틴 누수 같은 버그를 찾는 데 유용해요. 예를 들어 모든 네트워크 연결이 몇 분 후에 닫힐 것으로 기대한다면, 많은 netconn 고루틴이 몇 시간 동안 살아 있는 것이 무엇을 의미할까요?

고루틴 덤프 해석하기

코드를 보지 않고 위 고루틴에 대해 무엇을 알 수 있을까요?

그것은 약 1분 전에 생성되었고, 네트워크 소켓을 통해 데이터를 기다리고 있으며, 고루틴 번호가 꽤 크다는 것(61961905)을 알 수 있어요.

첫 덤프(debug=1)에서 그 호출 스택이 상대적으로 자주 실행된다는 것을 알고, 큰 고루틴 번호와 짧은 지속 시간을 합치면 수천만 개의 비교적 짧은 수명의 고루틴이 있었다는 것을 암시해요. pollWait라는 함수에 있으며 호출 기록에는 TLS를 사용하는 암호화된 네트워크 연결에서 HTTP/2 프레임을 읽는 것이 포함돼요.

따라서 이 고루틴이 HTTP/2 요청을 서빙하고 있다고 추론할 수 있어요! 클라이언트의 데이터를 기다리는 중이에요. 게다가 이 고루틴을 생성한 고루틴이 프로세스의 처음 고루틴 중 하나가 아니라는 것을 알 수 있어요. 왜냐하면 그것도 높은 번호를 갖기 때문이에요. 덤프에서 그 고루틴을 찾으면 기존 요청 중에 새 HTTP/2 스트림을 처리하기 위해 생성되었음을 알 수 있어요. 반대로 다른 높은 번호의 고루틴은 낮은 번호의 고루틴(예: 32)이 생성한 것일 수 있으며, 소켓의 Accept() 호출에서 갓 나온 완전히 새로운 연결을 나타내요.

모든 프로그램은 다르지만, Caddy를 디버깅할 때 이런 패턴이 대체로 성립해요.

메모리 프로파일

메모리(또는 heap) 프로파일은 시스템의 주요 메모리 소비자인 heap 할당을 추적해요. 할당은 메모리 할당에 시스템 호출이 필요하고 느릴 수 있기 때문에 성능 문제의 일반적인 용의자이기도 해요.

Heap 프로파일은 맨 위 줄의 시작 부분을 제외하고 거의 모든 면에서 고루틴 프로파일과 비슷하게 보여요. 예:

0: 0 [1: 4096] @ 0xb1fc05 0xb1fc4d 0x48d8d1 0xb1fce6 0xb184c7 0xb1bc8e 0xb41653 0xb4105c 0xb4151d 0xb23b14 0x4719c1
#	0xb1fc04	bufio.NewWriterSize+0x24					bufio/bufio.go:599
#	0xb1fc4c	golang.org/x/net/http2.glob..func8+0x6c				golang.org/x/[email protected]/http2/http2.go:263
#	0x48d8d0	sync.(*Pool).Get+0xb0						sync/pool.go:151
#	0xb1fce5	golang.org/x/net/http2.(*bufferedWriter).Write+0x45		golang.org/x/[email protected]/http2/http2.go:276
#	0xb184c6	golang.org/x/net/http2.(*Framer).endWrite+0xc6			golang.org/x/[email protected]/http2/frame.go:371
#	0xb1bc8d	golang.org/x/net/http2.(*Framer).WriteHeaders+0x48d		golang.org/x/[email protected]/http2/frame.go:1131
#	0xb41652	golang.org/x/net/http2.(*writeResHeaders).writeHeaderBlock+0xd2	golang.org/x/[email protected]/http2/write.go:239
#	0xb4105b	golang.org/x/net/http2.splitHeaderBlock+0xbb			golang.org/x/[email protected]/http2/write.go:169
#	0xb4151c	golang.org/x/net/http2.(*writeResHeaders).writeFrame+0x1dc	golang.org/x/[email protected]/http2/write.go:234
#	0xb23b13	golang.org/x/net/http2.(*serverConn).writeFrameAsync+0x73	golang.org/x/[email protected]/http2/server.go:851

첫 줄 형식은 다음과 같아요:

<live objects> <live memory> [<allocations>: <allocation memory>] @ <addresses...>

위 예제에서 bufio.NewWriterSize()가 만든 단일 할당이 있지만 현재 이 호출 스택에서 살아있는 객체는 없어요.

흥미롭게도 그 호출 스택에서 http2 패키지가 풀링된 4 KB를 사용해 클라이언트에 HTTP/2 프레임을 썼다는 것을 추론할 수 있어요. 핫 경로가 할당 재사용으로 최적화된 경우 Go 메모리 프로파일에서 풀링된 객체를 자주 볼 수 있어요. 이렇게 하면 새 할당이 줄어들고, heap 프로파일은 풀이 제대로 사용되고 있는지 알려줘요!

CPU 프로파일

CPU 프로파일은 Go 프로그램이 프로세서에서 예약된 시간의 대부분을 어디에 쓰는지 이해하는 데 도움을 줘요.

하지만 이에 대한 일반 텍스트 형식이 없으므로 다음 섹션에서는 go tool pprof 명령으로 읽는 방법을 사용할게요.

CPU 프로파일을 다운로드하려면 /debug/pprof/profile?seconds=N에 요청을 만들면 돼요. 여기서 N은 프로파일을 수집할 초 수예요. CPU 프로파일 수집 중에는 프로그램 성능이 약간 영향을 받을 수 있어요. (다른 프로파일은 성능에 거의 영향이 없어요.)

완료되면 적절히 profile이라는 이름의 바이너리 파일이 다운로드돼요. 그런 다음 그것을 조사해야 해요.

`go tool pprof`

Go에 내장된 프로파일 분석기를 사용해 CPU 프로파일을 읽는 방법을 예로 들어볼게요. 하지만 어떤 종류의 프로파일에도 사용할 수 있어요.

이 명령을 실행하면(다르다면 "profile"을 실제 파일 경로로 바꿔주세요) 대화형 프롬프트가 열려요:

go tool pprof profile
File: caddy_master
Type: cpu
Time: Aug 29, 2022 at 8:47pm (MDT)
Duration: 30.02s, Total samples = 70.11s (233.55%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)

이 명령으로 CPU 프로파일뿐만 아니라 어떤 종류의 프로파일도 검사할 수 있어요. 다른 프로파일에도 원리는 같고 개념은 그대로 이어져요.

이건 탐색할 수 있는 것이에요. help를 입력하면 명령 목록이, o는 현재 옵션을 보여줘요. help <command>를 입력하면 특정 명령에 대한 정보를 얻을 수 있어요.

명령이 많지만 일반적인 몇 가지:

top: CPU를 가장 많이 쓴 것을 보여줘요. top 20처럼 숫자를 붙이면 더 많이 볼 수 있고, 정규식을 사용해 특정 항목에 "집중"하거나 무시할 수 있어요.
web: 웹 브라우저에서 호출 그래프를 열어요. CPU 사용량을 시각적으로 보는 훌륭한 방법이에요.
svg: 호출 그래프의 SVG 이미지를 생성해요. web와 같지만 웹 브라우저를 열지 않고 SVG를 로컬에 저장해요.
tree: 호출 스택의 표 형식 보기.

top부터 시작해볼게요. 이런 출력이 보여요:

(pprof) top
Showing nodes accounting for 38.36s, 54.71% of 70.11s total
Dropped 785 nodes (cum <= 0.35s)
Showing top 10 nodes out of 196
      flat  flat%   sum%        cum   cum%
    10.97s 15.65% 15.65%     10.97s 15.65%  runtime/internal/syscall.Syscall6
     6.59s  9.40% 25.05%     36.65s 52.27%  runtime.gcDrain
     5.03s  7.17% 32.22%      5.34s  7.62%  runtime.(*lfstack).pop (inline)
     3.69s  5.26% 37.48%     11.02s 15.72%  runtime.scanobject
     2.42s  3.45% 40.94%      2.42s  3.45%  runtime.(*lfstack).push
     2.26s  3.22% 44.16%      2.30s  3.28%  runtime.pageIndexOf (inline)
     2.11s  3.01% 47.17%      2.56s  3.65%  runtime.findObject
     2.03s  2.90% 50.06%      2.03s  2.90%  runtime.markBits.isMarked (inline)
     1.69s  2.41% 52.47%      1.69s  2.41%  runtime.memclrNoHeapPointers
     1.57s  2.24% 54.71%      1.57s  2.24%  runtime.epollwait

CPU의 상위 10개 소비자는 모두 Go 런타임에 있었어요 - 특히 가비지 컬렉션이 많았죠(syscall이 메모리를 해제하고 할당하는 데 사용된다는 점을 기억하세요). 이는 할당을 줄이면 성능이 개선될 수 있다는 힌트이며, heap 프로파일이 가치 있을 거예요.

좋아요, 그런데 우리 코드의 CPU 사용률을 보고 싶다면? "runtime"을 포함하는 패턴을 이렇게 무시할 수 있어요:

(pprof) top -runtime
Active filters:
   ignore=runtime
Showing nodes accounting for 0.92s, 1.31% of 70.11s total
Dropped 160 nodes (cum <= 0.35s)
Showing top 10 nodes out of 243
      flat  flat%   sum%        cum   cum%
     0.17s  0.24%  0.24%      0.28s   0.4%  sync.(*Pool).getSlow
     0.11s  0.16%   0.4%      0.11s  0.16%  github.com/prometheus/client_golang/prometheus.(*histogram).observe (inline)
     0.10s  0.14%  0.54%      0.23s  0.33%  github.com/prometheus/client_golang/prometheus.(*MetricVec).hashLabels
     0.10s  0.14%  0.68%      0.12s  0.17%  net/textproto.CanonicalMIMEHeaderKey
     0.10s  0.14%  0.83%      0.10s  0.14%  sync.(*poolChain).popTail
     0.08s  0.11%  0.94%      0.26s  0.37%  github.com/prometheus/client_golang/prometheus.(*histogram).Observe
     0.07s   0.1%  1.04%      0.07s   0.1%  internal/poll.(*fdMutex).rwlock
     0.07s   0.1%  1.14%      0.10s  0.14%  path/filepath.Clean
     0.06s 0.086%  1.23%      0.06s 0.086%  context.value
     0.06s 0.086%  1.31%      0.06s 0.086%  go.uber.org/zap/buffer.(*Buffer).AppendByte

Prometheus 메트릭이 또 다른 주요 소비자라는 것은 분명하지만, 누적으로 위 GC보다 몇 자릿수 적다는 것을 알 수 있어요. 그 큰 차이는 GC 줄이기에 집중해야 한다는 것을 시사해요.

CPU 프로파일은 간헐적 샘플링에서 측정값을 얻으며 샘플은 기본 10ms인 샘플링 속도보다 더 자주 캡처되지 않는다는 점을 기억하는 것이 중요해요. 그래서 10ms 미만의 누적 시간을 볼 수 없어요(아마 더 적지만 반올림됨). 더 특정한 타이밍을 원하면 샘플링을 사용하지 않는 실행 트레이스(execution trace)를 할 수 있어요. (TODO: 트레이싱에 관한 섹션 추가.)

q로 이 프로파일을 종료하고 heap 프로파일에 같은 명령을 사용해볼게요:

(pprof) top
Showing nodes accounting for 22259.07kB, 81.30% of 27380.04kB total
Showing top 10 nodes out of 102
      flat  flat%   sum%        cum   cum%
   12300kB 44.92% 44.92%    12300kB 44.92%  runtime.allocm
 2570.01kB  9.39% 54.31%  2570.01kB  9.39%  bufio.NewReaderSize
 2048.81kB  7.48% 61.79%  2048.81kB  7.48%  runtime.malg
 1542.01kB  5.63% 67.42%  1542.01kB  5.63%  bufio.NewWriterSize
 ...

적중이에요. 메모리의 거의 절반이 bufio 패키지 사용으로 인한 읽기/쓰기 버퍼에만 할당돼요. 따라서 버퍼링을 줄이도록 코드를 최적화하면 매우 유익할 것이라고 추론할 수 있어요. (Caddy의 관련 패치가 정확히 그렇게 해요).

시각화

대신 svg나 web 명령을 실행하면 프로파일의 시각화를 얻어요:

이것은 CPU 프로파일이지만 다른 프로파일 유형에도 비슷한 그래프가 있어요.

이 그래프를 읽는 법을 배우려면 pprof 문서를 읽어보세요.

프로파일 diff

코드를 변경한 후 차이 분석("diff")으로 이전과 이후를 비교할 수 있어요. heap의 diff는 다음과 같아요:

go tool pprof -diff_base=before.prof after.prof
File: caddy
Type: inuse_space
Time: Aug 29, 2022 at 1:21am (MDT)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for -26.97MB, 49.32% of 54.68MB total
Dropped 10 nodes (cum <= 0.27MB)
Showing top 10 nodes out of 137
      flat  flat%   sum%        cum   cum%
  -27.04MB 49.45% 49.45%   -27.04MB 49.45%  bufio.NewWriterSize
      -2MB  3.66% 53.11%       -2MB  3.66%  runtime.allocm
    1.06MB  1.93% 51.18%     1.06MB  1.93%  github.com/yuin/goldmark/util.init
    1.03MB  1.89% 49.29%     1.03MB  1.89%  github.com/caddyserver/caddy/v2/modules/caddyhttp/reverseproxy.glob..func2
       1MB  1.84% 47.46%        1MB  1.84%  bufio.NewReaderSize
      -1MB  1.83% 49.29%       -1MB  1.83%  runtime.malg
       1MB  1.83% 47.46%        1MB  1.83%  github.com/caddyserver/caddy/v2/modules/caddyhttp/reverseproxy.cloneRequest
      -1MB  1.83% 49.29%       -1MB  1.83%  net/http.(*Server).newConn
   -0.55MB  1.00% 50.29%    -0.55MB  1.00%  html.populateMaps
    0.53MB  0.97% 49.32%     0.53MB  0.97%  github.com/alecthomas/chroma.TypeRemappingLexer

보시다시피 메모리 할당을 약 절반으로 줄였어요!

diff도 시각화할 수 있어요:

이렇게 하면 변경 사항이 프로그램의 특정 부분 성능에 어떤 영향을 미쳤는지 아주 명확해져요.

더 읽을거리

프로그램 프로파일링은 마스터할 것이 많고 우리는 겉핥기만 했어요.

"profiling"에서 "pro"를 진짜로 만들려면 이런 자료를 고려해보세요:

더 알아보기 (Learn more)

Caddy 공식 문서