느린 스팬 하나의 CPU 를 함수까지 연다

목표

트레이스에서 고른 느린 스팬 하나를 같은 시간의 CPU 프로파일에 이어, 그 요청 하나가 CPU 를 어디에 썼는지 함수 단위로 엽니다. 그리고 요청 하나를 보는 것과 같은 종류의 요청을 모아 보는 것이 각각 언제 쓸모 있는지 견줍니다.

왜 중요한가

트레이스는 「pricing.quote 구간이 36ms 걸렸다」까지 말하고, 프로파일은 「서비스 전체가 couponPattern 에 CPU 의 80% 를 썼다」를 말합니다. 둘을 잇는 고리가 없으면 「그 느린 요청도 정말 couponPattern 때문이었나」를 증명할 수 없습니다. 고리는 프로파일의 표본에 붙는 레이블입니다. pricing 은 요청을 처리하는 동안 pprof.Do 로 trace_id·span_id·coupon 레이블을 겁니다. 그러면 CPU 표본마다 「어느 요청의 일이었나」가 붙고, -tagfocus 로 한 스팬의 표본만 걸러 볼 수 있습니다. Pyroscope 의 span profiles 와 OpenTelemetry profiles 신호의 trace 링크가 같은 생각입니다.

한계도 숫자로 봅니다. 표본은 10ms 마다 하나라서 10ms 보다 짧은 스팬에는 표본이 없을 수 있습니다. 그래서 실무에서는 스팬 하나보다 「같은 이름·같은 속성의 스팬 묶음」으로 보는 일이 더 많습니다.

단계

1. 두 서비스를 띄우고 -c 4 -d 20s -seed 5 로 api 에 부하를 주는 동안 pricing 의 15초 CPU 프로파일을 /root/prof/profiles/m5-cpu.pb.gz 에, 부하 결과를 /root/prof/runs/m5.json 에 남기세요.
2. 프로파일의 레이블 키를 한 줄에 하나씩 /root/prof/answers/tag-keys.txt 에 적으세요.
3. 레이블이 붙은 표본 가운데 coupon=yes·coupon=no 의 비율을 /root/prof/answers/coupon-share.json 에 적으세요.
4. 이 프로파일에 표본이 붙은 쿠폰 스팬 가운데 가장 느린 쪽에서 하나를 골라 trace_id·span_id·표본 수를 /root/prof/answers/span.json 에 적으세요.
5. 그 스팬의 표본만 남긴 프로파일을 /root/prof/profiles/m5-span.pb.gz 에 저장하세요.
6. coupon=yes 와 coupon=no 표본에서 각각 가장 많이 나온 main 함수를 /root/prof/answers/split.json 에 적으세요.
7. 트레이스에서 프로파일까지 이어진 증거를 /root/prof/answers/incident.md 에 ## 트레이스·## 프로파일·## 결론 세 절로 쓰세요.

참고

• 작업 자리는 /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 파일에 조건과 결과를 함께 적습니다.
• 이 파드는 네트워크가 막혀 있습니다. 필요한 것은 전부 이미지에 들어 있습니다.
• go tool pprof -tags <파일> 이 레이블 키와 값별 비중을 보여 줍니다. -tagfocus=키=값 은 그 레이블의 표본만 남기고, -proto 를 붙이면 결과를 다시 프로파일 파일로 씁니다.
• loadgen 결과의 slowest 는 클라이언트가 잰 가장 느린 요청 다섯입니다. trace_id 로 /root/prof/pricing-spans.jsonl 에서 Go 쪽 span_id 를 찾습니다.
• 흔한 실수: 프로파일을 받던 15초 밖에서 처리된 요청을 고르는 것입니다. 그 스팬에는 표본이 없습니다.

레이블 달린 프로파일을 받는다

pricing·api 를 띄우고 loadgen -url http://127.0.0.1:8080/checkout -c 4 -d 20s -seed 5 -out /root/prof/runs/m5.json 을 돌리는 동안 ?seconds=15 로 pricing CPU 프로파일을 /root/prof/profiles/m5-cpu.pb.gz 에 받으세요.

부하가 프로파일 창을 다 덮어야 그 안의 요청에 표본이 붙습니다. 부하를 먼저 걸고 1~2초 뒤에 받기 시작하세요.

표본에 붙은 레이블

go tool pprof -tags 로 본 레이블 키를 한 줄에 하나씩 /root/prof/answers/tag-keys.txt 에 적으세요.

pricing 의 main.go 에서 pprof.Labels 를 찾아보세요. 거기 건 키가 그대로 프로파일에 나옵니다. 요청마다 다른 값(trace_id)을 레이블로 거는 것이 비용을 키운다는 점도 함께 보세요.

어느 종류의 요청이 CPU 를 썼나

coupon 레이블이 붙은 표본 가운데 coupon=yes 의 비율을 yes_pct, coupon=no 를 no_pct(0..100)로 /root/prof/answers/coupon-share.json 에 적으세요.

-tags 출력의 coupon 줄이 바로 이 값입니다. 요청 수로는 쿠폰 주문이 다섯에 하나뿐인데 CPU 는 어떤지 견줘 보세요.

느린 스팬 하나를 고른다

pricing-spans.jsonl 의 쿠폰 스팬 가운데 이 프로파일에 CPU 표본이 1개 이상 붙은 것들끼리 견줘 가장 느린 쪽(위 4분의 1)에서 하나를 골라 trace_id·span_id(Go 쪽)·samples(그 span_id 레이블을 단 표본 수)를 /root/prof/answers/span.json 에 적으세요.

trace_id 는 서비스 경계를 넘어 같지만 span_id 는 서비스마다 다릅니다. 프로파일의 레이블은 Go 쪽 span_id 이니 pricing-spans.jsonl 에서 찾아야 합니다. 표본이 0 이면 다음으로 느린 스팬을 보세요.

그 요청 하나의 프로파일

go tool pprof -proto -tagfocus=span_id=<그 span_id> 로 그 스팬의 표본만 남긴 프로파일을 /root/prof/profiles/m5-span.pb.gz 에 저장하세요.

-tagfocus 는 레이블로 표본을 거르는 필터입니다. -proto 를 붙이면 화면에 표를 그리는 대신 걸러진 프로파일을 파일로 씁니다. 결과를 -top 으로 열어 보세요.

하나가 아니라 묶음으로

coupon=yes 표본과 coupon=no 표본 각각에서, 표본마다 잎에서 처음 만나는 main 함수(main.quote 계열 제외)를 세어 가장 많은 것을 yes_top·no_top 으로 /root/prof/answers/split.json 에 적으세요.

요청 하나에는 표본이 몇 개뿐이라 우연이 섞입니다. 같은 속성의 요청을 모으면 표본이 수천 개가 되어 결론이 단단해집니다. -tagfocus=coupon=yes 와 coupon=no 로 각각 -top 을 봐도 됩니다.

증거를 한 문서로

/root/prof/answers/incident.md 에 ## 트레이스(trace_id·span_id·걸린 시간)·## 프로파일(표본 수·상위 함수)·## 결론(원인 함수 main.couponPattern 과 근거) 세 절을 쓰세요.

다른 사람이 이 문서만 보고 같은 스팬과 같은 프로파일을 다시 열 수 있어야 합니다. ID 를 빠뜨리면 증거가 아니라 주장이 됩니다.