느린 요청 하나를 트레이스로 찾는다

목표

checkout 서비스에 부하를 주고, SDK 가 파일로 남긴 스팬에서 가장 느린 요청 하나를 골라 그 시간이 어느 구간에서 쓰였는지, 그리고 느린 요청들에 어떤 공통점이 있는지 찾습니다. 이 코스 전체가 쫓아갈 「범인」의 첫 단서입니다.

왜 중요한가

평균 응답 시간 그래프는 「느려졌다」는 사실만 알려 줍니다. 무엇이 느린지는 요청 하나를 열어 봐야 보이고, 그 일을 하는 것이 트레이스입니다. 트레이스는 요청이 지나간 구간마다 스팬을 남기므로, 가장 긴 자식 스팬이 곧 다음에 파고들 곳입니다. 그런데 트레이스는 어느 구간까지만 알려 주고, 그 구간 안에서 어느 함수가 시간을 썼는지는 알려 주지 않습니다. 그 질문은 뒤의 모듈에서 프로파일이 답합니다.

이 실습의 서비스는 둘입니다. 파이썬 앞단(api, OpenTelemetry SDK 로 계측)이 Go 가격 서비스(pricing)를 부릅니다. 두 서비스는 W3C traceparent 헤더로 같은 trace_id 를 나눠 가집니다.

단계

prof-workspace 로 작업 자리를 만드세요. /root/prof/bin/pricing·/root/prof/bin/loadgen 이 생겨야 합니다.
pricing 과 api 를 띄우고 http://127.0.0.1:8080/checkout?items=12&coupon=SUMMER007-2024 에 요청 하나를 보내 응답을 /root/prof/runs/first.json 에 저장하세요.
loadgen -url http://127.0.0.1:8080/checkout -c 4 -d 12s 로 부하를 주고 결과를 /root/prof/runs/m1-load.json 에 남기세요.
/root/prof/otel/spans.jsonl 에서 가장 오래 걸린 GET /checkout 스팬의 trace_id 를 16진수 32자리(0x 없이)로 /root/prof/answers/slow-trace.txt 에 적으세요.
그 트레이스에서 GET /checkout 의 자식 중 가장 오래 걸린 스팬의 이름과, 그것이 부모 시간에서 차지하는 비율(0..1)을 /root/prof/answers/slow-trace.json 에 적으세요.
같은 trace_id 를 Go 쪽 기록 /root/prof/pricing-spans.jsonl 에서 찾아, Go 스팬의 span_id·parent_span_id 와 파이썬 pricing.quote 스팬의 span_id 를 /root/prof/answers/slow-crossing.json 에 적으세요.
느린 순서로 20개 GET /checkout 스팬 가운데 checkout.coupon 이 참인 비율과, 전체 스팬에서의 비율을 /root/prof/answers/pattern.json 에 적으세요.

참고

작업 자리는 /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 파일에 조건과 결과를 함께 적습니다.
이 파드는 네트워크가 막혀 있습니다. 필요한 것은 전부 이미지에 들어 있습니다.
SDK 는 trace_id 를 0x 를 붙인 16진수로, Go 쪽은 붙이지 않고 적습니다. 같은 값인지 견줄 때는 앞의 0x 를 떼세요.
스팬은 1초마다 묶어 내보냅니다. 요청 직후 파일에 없으면 2초 기다리세요.
흔한 실수: loadgen 이 화면에 보여 주는 slowest 는 클라이언트가 잰 시간입니다. 이 실습은 서버 스팬의 길이로 고릅니다.

작업 자리를 만든다

prof-workspace 를 실행해 /root/prof/bin/pricing 과 /root/prof/bin/loadgen 을 만드세요.

도우미가 /opt/fixtures/prof 의 소스를 /root/prof/src 로 복사하고 go build 합니다. 빌드 캐시가 이미지에 데워져 있어 몇 초면 끝납니다.

요청 하나가 스팬이 되는 것을 본다

prof-svc up pricing·prof-svc up api 로 두 서비스를 띄우고, 쿠폰 주문 하나의 응답을 /root/prof/runs/first.json 에 저장하세요. 응답의 trace_id 가 otel/spans.jsonl 에 나타나야 합니다.

응답 JSON 에 trace_id 가 들어 있습니다. 같은 값을 grep 으로 spans.jsonl 에서 찾아보세요. SDK 는 1초마다 묶어 쓰므로 바로 없으면 잠시 기다립니다.

부하를 준다

loadgen -url http://127.0.0.1:8080/checkout -c 4 -d 12s -out /root/prof/runs/m1-load.json 으로 부하를 주세요. 실패한 요청이 없어야 합니다.

느린 요청은 드물게 나옵니다. 하나만 보내서는 찾을 수 없으니 여러 요청을 꾸준히 보내 표본을 만듭니다. 실패가 있으면 /root/prof/logs 의 로그를 보세요.

가장 느린 요청을 고른다

otel/spans.jsonl 의 GET /checkout 스팬 가운데 끝 시각에서 시작 시각을 뺀 길이가 가장 긴 것의 trace_id 를 /root/prof/answers/slow-trace.txt 에 적으세요(16진수 32자리, 0x 없이).

한 줄이 스팬 하나입니다. name 이 GET /checkout 인 줄만 골라 start_time·end_time 의 차이로 정렬합니다. 시각은 ISO 문자열이라 파이썬의 datetime.fromisoformat 으로 바꿀 수 있습니다.

어느 구간이 시간을 썼나

그 트레이스에서 GET /checkout 스팬의 자식 가운데 가장 오래 걸린 스팬의 이름(slowest_child)과 부모 시간에서의 비율(child_share, 0..1)을 trace_id 와 함께 /root/prof/answers/slow-trace.json 에 적으세요.

자식은 parent_id 가 부모의 context.span_id 와 같은 스팬입니다. 같은 trace_id 의 줄만 모아 나무를 세워 보세요.

서비스 경계를 건넌다

Go 쪽 기록 /root/prof/pricing-spans.jsonl 에서 같은 trace_id 의 줄을 찾아 pricing_span_id·parent_span_id 를, 파이썬 pricing.quote 스팬의 span_id 를 python_client_span_id 로 /root/prof/answers/slow-crossing.json 에 적으세요(전부 16진수, 0x 없이).

traceparent 헤더는 「버전-trace_id-부모 span_id-플래그」 입니다. 파이썬 클라이언트 스팬이 보낸 부모 span_id 가 Go 쪽 줄의 parent_span_id 로 들어갑니다. 두 값이 같으면 전파가 된 것입니다.

느린 요청의 공통점

가장 느린 GET /checkout 스팬 20개 가운데 속성 checkout.coupon 이 true 인 비율(top_coupon_share)과 전체 GET /checkout 스팬에서의 비율(all_coupon_share)을 top_n: 20 과 함께 /root/prof/answers/pattern.json 에 적으세요.

요청 하나만 보면 우연일 수 있습니다. 느린 쪽 묶음과 전체를 같은 속성으로 견줘야 「느린 요청은 대개 쿠폰 주문이다」 같은 말을 할 수 있습니다.