플레임 그래프를 숫자로 읽는다

목표

pricing 의 CPU 프로파일을 받아 플레임 그래프의 원자료인 접은 스택(folded stacks)으로 펴고, 상자의 너비가 무엇을 뜻하는지(전체 시간과 자기 시간), 넓은 상자가 왜 범인이 아닐 수 있는지를 숫자로 확인합니다.

왜 중요한가

플레임 그래프는 한 장에 수천 개의 스택을 겹쳐 그립니다. 처음 보는 사람은 가장 위에 있는 뾰족한 상자나 가장 넓은 맨 아래 상자를 범인으로 읽기 쉽습니다. 그런데 맨 아래는 모든 요청이 지나가는 길이라 넓을 수밖에 없고, 위쪽의 뾰족한 상자는 자기 시간이 길어도 전체에서는 작을 수 있습니다. 읽어야 할 것은 넓은데 그 위가 비어 있는 고원, 그리고 넓은 상자 바로 아래에서 그 너비를 만든 내 코드의 함수입니다.

가로축은 시간이 아닙니다. 형제 상자는 이름순으로 놓입니다. 그래서 「왼쪽에서 먼저 일어났다」 같은 읽기는 틀립니다. 이 실습은 그림 대신 그 그림을 만드는 숫자를 직접 세어, 그림을 볼 때 무엇을 봐야 하는지 손에 익힙니다.

단계

pricing 에 기본 부하를 주는 동안 10초짜리 CPU 프로파일을 받아 /root/prof/profiles/m3-cpu.pb.gz 에 저장하세요.
prof-fold 로 접은 스택을 /root/prof/profiles/m3-cpu.folded 에 만드세요.
자기 시간(self)이 가장 긴 함수와 그 비율을 /root/prof/answers/flame-self.json 에 적으세요.
main.couponPattern 의 전체(total) 비율과 자기(self) 비율을 /root/prof/answers/flame-coupon.json 에 적으세요.
main.reserveStock 이 든 스택만 남긴 접은 파일을 /root/prof/profiles/m3-reserve.folded 에 만드세요.
runtime.mallocgc 가 든 표본 수, 그 가운데 main.couponPattern 아래에서 난 수와 비율을 /root/prof/answers/flame-malloc.json 에 적으세요.
읽은 내용을 /root/prof/answers/flame-notes.md 에 ## 고원·## 자기 시간·## 범인 세 절로 쓰세요. 범인 절에는 함수 이름과 그 total 비율을 적습니다.

참고

작업 자리는 /root/prof 입니다. prof-workspace 가 소스(src)를 복사하고 두 프로그램(bin/pricing·bin/loadgen)을 빌드합니다. 여러 번 불러도 이미 있는 것은 덮지 않습니다.
서비스는 prof-svc up pricing·prof-svc up api 로 띄우고 prof-svc status 로 봅니다. up 은 떠 있던 것을 내리고 다시 띄우므로, 앞에 적은 환경 변수가 그때 반영됩니다.
부하는 loadgen 입니다. -c(동시성)·-d(시간)·-coupon(쿠폰 비율)·-big(큰 주문 비율)·-seed 를 받고, -out 파일에 조건과 결과를 함께 적습니다.
이 파드는 네트워크가 막혀 있습니다. 필요한 것은 전부 이미지에 들어 있습니다.
접은 스택의 한 줄은 뿌리;…;잎 값 입니다. 그 줄에 함수가 나오면 total 에, 맨 끝(잎)이면 self 에 셉니다. 한 줄에 같은 함수가 두 번 나와도(재귀) total 에는 한 번만 셉니다.
prof-flame <파일> --min 2 가 터미널에 나무 모양 플레임 그래프를 그립니다. go tool pprof -top·-top -cum 은 같은 숫자를 표로 보여 줍니다.
흔한 실수: 부하 없이 받은 프로파일입니다. 표본이 몇 개뿐이라 아무것도 읽히지 않습니다.

부하 아래에서 CPU 프로파일을 받는다

pricing 이 떠 있는 상태에서 loadgen -c 4 -d 12s 를 백그라운드로 돌리고, 그동안 http://127.0.0.1:6060/debug/pprof/profile?seconds=10 을 받아 /root/prof/profiles/m3-cpu.pb.gz 에 저장하세요.

CPU 프로파일은 받는 동안 10ms 마다 「지금 어디를 실행 중인가」를 적습니다. 아무 일도 없을 때 받으면 표본이 거의 없습니다. 부하가 도는 동안 받으세요.

접은 스택으로 편다

prof-fold /root/prof/profiles/m3-cpu.pb.gz > /root/prof/profiles/m3-cpu.folded 로 접은 스택을 만드세요. 합계가 프로파일의 표본 수와 같아야 합니다.

플레임 그래프 도구(flamegraph.pl, speedscope)가 읽는 형식입니다. 한 줄이 스택 하나이고 끝의 숫자가 그 스택에서 나온 표본 수입니다.

자기 시간이 가장 긴 함수

접은 스택에서 잎(줄 맨 끝 프레임)으로 가장 많이 나온 함수를 top_self, 그 비율(%)을 top_self_pct 로 /root/prof/answers/flame-self.json 에 적으세요.

잎은 표본을 찍은 순간 CPU 가 실제로 실행하던 함수입니다. 플레임 그래프에서는 위가 비어 있는 상자 끝입니다. go tool pprof -top 의 flat 열과 같은 값입니다.

total 과 self

main.couponPattern 이 든 표본의 비율을 total_pct, 잎으로 나온 비율을 self_pct 로 /root/prof/answers/flame-coupon.json 에 적으세요(0..100).

total 은 그 상자의 너비, self 는 그 상자 위가 비어 있는 부분의 너비입니다. 두 값이 크게 다르면 시간은 그 함수가 부른 것들에서 쓰인 것입니다.

한 함수가 든 스택만 남긴다

main.reserveStock 이 든 줄만 남긴 접은 파일을 /root/prof/profiles/m3-reserve.folded 에 만드세요. 합계가 원래 파일에서 그 줄들의 합과 같아야 합니다.

접은 스택은 줄 단위 텍스트라 grep 으로 거를 수 있습니다. 플레임 그래프 도구의 「이 함수로 좁히기」가 하는 일도 이것입니다(pprof 의 -focus).

넓지만 범인이 아닌 상자

runtime.mallocgc 가 든 표본 수(mallocgc_total), 그 가운데 main.couponPattern 도 든 표본 수(under_coupon), 그 비율(share, 0..1)을 /root/prof/answers/flame-malloc.json 에 적으세요.

할당기와 GC 는 여러 곳에서 불려 넓게 보입니다. 그 비용을 누가 만들었는지는 그 아래(뿌리 쪽)의 호출자를 보면 압니다.

읽은 것을 적는다

/root/prof/answers/flame-notes.md 에 ## 고원·## 자기 시간·## 범인 세 절을 쓰세요. 범인 절에는 main.couponPattern 과 그 total 비율(예: 78.9%)을 적습니다.

고원은 넓은데 위가 비어 있는 상자, 자기 시간은 잎, 범인은 그 너비를 만든 내 코드의 함수입니다. 앞 단계의 숫자를 문장으로 옮기면 됩니다.