They Say 20 Milliseconds, We Measure 300

한국어 원문으로 표시합니다.

목표

같은 호출을 클라이언트와 서버 양쪽에서 재어 차이를 쪼개고, 커넥션 풀 대기를 스팬 경계 안으로 넣고, 끊긴 호출과 취소된 호출을 구분해 남기고, 대상 식별 속성을 저카디널리티로 설계해 그 규칙을 두 번째 클라이언트에 그대로 적용합니다.

왜 중요한가

하류 팀의 p99 와 우리 p99 가 다른 것은 누가 틀려서가 아니라 서로 다른 구간을 재기 때문이다. 서버는 핸들러가 열려 있던 시간을 재고, 그 앞뒤에는 대기열·직렬화·전송이 있다. 더 나쁜 것은 커넥션 풀 대기다 — 연결을 얻은 뒤에 스팬을 시작하면 그 기다림은 어느 스팬에도 들어 있지 않아, 자식을 다 더해도 루트가 설명되지 않는 트레이스가 만들어진다. 타임아웃은 짝을 어긋나게 한다. 클라이언트가 포기해도 서버는 끝까지 일하므로 같은 트레이스에 짧은 CLIENT 스팬과 긴 SERVER 스팬이 함께 남고, 그 모양이 곧 자원이 새고 있다는 신호다. 반대로 사용자가 떠나서 생긴 취소를 오류로 올리면 오류율이 사용자의 행동을 따라 출렁인다. 마지막으로 나가는 호출의 대상을 주소 그대로 적으면 아이디와 파드 이름이 속성 값에 섞여 집계가 불가능해진다.

단계

/root/tp-client/pair.py 를 만드세요. 덤프 경로는 TRACELAB_OUT 에서 읽고 없으면 /root/tp-client/pair.jsonl 입니다. 클라이언트 서비스 이름은 shop-api, 하류는 Backend("pricing", <덤프와 같은 디렉터리>/server.jsonl) 입니다. CLIENT 스팬 POST /price 안에서 헤더를 주입하고 be.call("POST /price", 120, carrier) 를 부른 뒤, 덤프와 같은 디렉터리의 pair.tsv 에 <클라이언트 밀리초>, <서버 밀리초>, <차이> 를 탭으로 나눠 한 줄 적으세요. 소수 셋째 자리까지입니다.
/root/tp-client/gap.py 를 만들어 같은 호출을 스무 번 하세요(일감은 30밀리초). 덤프 기본 경로는 /root/tp-client/gap.jsonl, 서버 덤프는 같은 디렉터리의 gap-server.jsonl 입니다. 호출마다 CLIENT 스팬 POST /price 에 속성 세 개를 붙입니다 — gap.ms(클라이언트 시간 빼기 서버 시간), gap.queue_ms(응답이 알려 준 대기열 시간), gap.rest_ms(둘의 차). 덤프와 같은 디렉터리의 gap.tsv 에 <번호>와 <gap.ms> 를 스무 줄, gap-summary.txt 에 median_gap_ms=(스무 값의 중앙값)와 reason=(차이가 무엇으로 이루어지는지 100자 이상) 을 적으세요.
/root/tp-client/pooled.py 를 만들어 같은 일을 두 번 하세요. 덤프 기본 경로는 /root/tp-client/pooled.jsonl, 서버 덤프는 같은 디렉터리의 pooled-server.jsonl 입니다. 두 번 모두 크기 1 짜리 ConnPool 을 새로 만들고 스레드 세 개가 동시에 be.call("GET /stock", 80, carrier) 를 부릅니다. 첫 번째 묶음은 풀에서 자리를 얻은 뒤 CLIENT 스팬 narrow 를 열고, 두 번째 묶음은 CLIENT 스팬 wide 를 먼저 연 뒤 자리를 얻으면서 속성 pool.wait_ms 와 이벤트 pool.acquired 를 남깁니다. 덤프와 같은 디렉터리의 pool.tsv 에 narrow·wide 두 줄로 각 묶음에서 가장 오래 열려 있던 스팬의 밀리초를 적으세요.
/root/tp-client/timeout.py 를 만드세요. 덤프 기본 경로는 /root/tp-client/timeout.jsonl, 서버 덤프는 같은 디렉터리의 timeout-server.jsonl 입니다. CLIENT 스팬 GET /stock 안에서 be.call("GET /stock", 400, carrier, timeout_ms=120) 을 부르고, 올라온 타임아웃을 잡아 스팬 상태를 ERROR 로 두고 속성 error.type 을 timeout, rpc.timeout_ms 를 120 으로 적으세요. be.close() 로 서버 일감이 끝나기를 기다린 뒤 flush() 하고, 두 덤프를 다시 읽어 같은 trace_id 를 가진 짝을 찾아 덤프와 같은 디렉터리의 orphan.tsv 에 <trace_id>, <클라이언트 밀리초>, <서버 밀리초>, <판정> 을 탭으로 나눠 한 줄 적습니다. 판정은 서버 쪽이 더 길면 client-gave-up, 아니면 server-finished-first 입니다.
/root/tp-client/cancel.py 를 만들어 두 가지를 남기세요. 덤프 기본 경로는 /root/tp-client/cancel.jsonl, 서버 덤프는 같은 디렉터리의 cancel-server.jsonl 입니다. (1) CLIENT 스팬 GET /recs 에서 be.submit("GET /recs", 300, carrier) 로 호출을 보낸 뒤 60밀리초만 기다리다 그만둡니다 — 상태는 건드리지 말고 속성 rpc.cancelled 를 참으로, 이벤트 rpc.cancelled 를 남깁니다. (2) CLIENT 스팬 GET /promo 에서 be.call("GET /promo", 20, carrier, fail=True) 를 부르고 올라온 예외를 record_exception 으로 기록한 뒤 상태를 ERROR 로 둡니다. 덤프와 같은 디렉터리의 05-cancel.txt 에 cancelled_status=, failed_status=, reason=(왜 둘을 다르게 남기는지 100자 이상) 세 줄을 적으세요.
/root/tp-client/target.py 를 만들어 /opt/app/tracelab/tp_client/plan.json 의 cardinality 호출 여덟 건을 보내세요. 덤프 기본 경로는 /root/tp-client/target.jsonl, 서버 덤프는 같은 디렉터리의 target-server.jsonl 입니다. CLIENT 스팬 이름은 <target>/<op> 이고 속성 네 개를 붙입니다 — rpc.service(target), rpc.method(op), server.address(target), url.template(path 에서 주문 아이디만 plan.json 의 placeholder 로 바꾼 것). 주소의 host 와 주문 아이디는 속성 값에 넣지 않습니다. 덤프와 같은 디렉터리의 cardinality.tsv 에 네 속성의 이름과 서로 다른 값의 개수를 속성 이름 사전순으로 탭으로 나눠 네 줄 적으세요.
/root/tp-client/repeat.py 를 만들어 /opt/app/tracelab/tp_client/plan.json 의 checkout 호출 일곱 건을 SERVER 스팬 POST /checkout 하나 아래에서 보내세요. 덤프 기본 경로는 /root/tp-client/repeat.jsonl, 서버 덤프는 같은 디렉터리의 repeat-server.jsonl 입니다. 루트 스팬에 속성 rpc.client.calls 로 나간 호출 수를 적고, CLIENT 스팬마다 6단계와 같은 네 속성을 붙입니다. 덤프와 같은 디렉터리의 repeat.tsv 에 <server.address>, <rpc.method>, <호출 수>, <걸린 시간 합(정수 밀리초)> 을 호출 수가 많은 것부터 탭으로 나눠 적으세요. 호출 수가 같으면 주소 사전순입니다.
먼저 /root/tp-client/client-policy.json 에 지금까지의 판단을 적으세요 — span_kind, boundary(풀 대기가 스팬 안인지 밖인지), required_attributes(6단계의 네 속성), forbidden_value_sources(속성 값으로 쓰면 안 되는 재료의 필드 이름들), timeout_status, cancel_status. 그다음 /root/tp-client/second.py 를 만들어 그 파일을 읽고 /opt/app/tracelab/tp_client/plan.json 의 search 호출 네 건을 두 번째 클라이언트로 보냅니다. 덤프 기본 경로는 /root/tp-client/second.jsonl, 서버 덤프는 같은 디렉터리의 second-server.jsonl 이고, 크기 1 짜리 ConnPool 을 써서 기다린 시간을 스팬 안의 pool.wait_ms 로 남깁니다. 덤프와 같은 디렉터리의 second.tsv 에 <rpc.method>, <호출 수>, <서로 다른 server.address 수> 를 연산 이름 사전순으로 세 칸씩 적으세요.

참고

작업 디렉터리는 /root/tp-client 입니다. 없으면 먼저 만드세요.
계측 프로그램은 반드시 /opt/otel-lab/bin/python 로 돌립니다. 시스템 python3 에는 OpenTelemetry 가 없습니다.
덤프 경로는 언제나 환경변수 TRACELAB_OUT 을 먼저 읽고, 없을 때만 과제에 적힌 기본 경로를 씁니다. 서버 덤프와 표 파일도 덤프와 같은 디렉터리에 쓰세요 — 채점기가 같은 프로그램을 자기 임시 디렉터리에서 한 번 더 돌려 대조합니다.
덤프는 이어 쓰기라서 프로그램 시작에 open(OUT, "w").close() 로 비웁니다.
재료는 /opt/app/tracelab/tp_client/ 에 있습니다 — backend.py(하류 서비스 흉내), pool.py(커넥션 풀), plan.json(나가는 호출 목록). 앞의 두 파일은 읽되 고치지 않습니다.
흔한 실수: be.close() 없이 flush() 를 부르는 것. 워커 스레드가 아직 돌고 있으면 서버 스팬이 덤프에 남지 않습니다.
흔한 실수: 헤더를 CLIENT 스팬 밖에서 주입하는 것. 그러면 서버 스팬이 그 스팬의 자식이 되지 않습니다.
Semantic Conventions — RPC 스팬 · Trace API — 스팬 상태 · OpenTelemetry — 스팬 종류 · OpenTelemetry Python — Instrumentation · Semantic Conventions — 일반 속성

같은 호출을 양쪽에서 잰다

/root/tp-client/pair.py 를 만드세요. 덤프 경로는 TRACELAB_OUT 에서 읽고 없으면 /root/tp-client/pair.jsonl 입니다. 클라이언트 서비스 이름은 shop-api, 하류는 Backend("pricing", <덤프와 같은 디렉터리>/server.jsonl) 입니다. CLIENT 스팬 POST /price 안에서 헤더를 주입하고 be.call("POST /price", 120, carrier) 를 부른 뒤, 덤프와 같은 디렉터리의 pair.tsv 에 <클라이언트 밀리초>, <서버 밀리초>, <차이> 를 탭으로 나눠 한 줄 적으세요. 소수 셋째 자리까지입니다.

Backend.call 이 돌려주는 dict 의 server_ms 가 서버 스팬이 열려 있던 시간입니다. 클라이언트 시간은 호출 앞뒤를 time.perf_counter() 로 재면 됩니다. 헤더를 스팬 안에서 주입해야 서버 스팬이 이 스팬의 자식이 됩니다. 끝에 be.close() 를 부른 뒤 flush() 하세요.

그 차이가 무엇으로 이루어져 있는가

/root/tp-client/gap.py 를 만들어 같은 호출을 스무 번 하세요(일감은 30밀리초). 덤프 기본 경로는 /root/tp-client/gap.jsonl, 서버 덤프는 같은 디렉터리의 gap-server.jsonl 입니다. 호출마다 CLIENT 스팬 POST /price 에 속성 세 개를 붙입니다 — gap.ms(클라이언트 시간 빼기 서버 시간), gap.queue_ms(응답이 알려 준 대기열 시간), gap.rest_ms(둘의 차). 덤프와 같은 디렉터리의 gap.tsv 에 <번호>와 <gap.ms> 를 스무 줄, gap-summary.txt 에 median_gap_ms=(스무 값의 중앙값)와 reason=(차이가 무엇으로 이루어지는지 100자 이상) 을 적으세요.

Backend.call 의 응답 dict 에는 server_ms 말고 queue_ms 도 있습니다 — 요청이 도착해 핸들러가 잡히기까지의 시간이고, 서버 스팬 밖입니다. 진짜 서비스라면 이 값이 응답 헤더로 돌아옵니다. 중앙값은 스무 값을 정렬해 가운데 두 개를 평균 내면 됩니다.

커넥션 풀에서 기다린 시간을 스팬 안으로 넣는다

/root/tp-client/pooled.py 를 만들어 같은 일을 두 번 하세요. 덤프 기본 경로는 /root/tp-client/pooled.jsonl, 서버 덤프는 같은 디렉터리의 pooled-server.jsonl 입니다. 두 번 모두 크기 1 짜리 ConnPool 을 새로 만들고 스레드 세 개가 동시에 be.call("GET /stock", 80, carrier) 를 부릅니다. 첫 번째 묶음은 풀에서 자리를 얻은 뒤 CLIENT 스팬 narrow 를 열고, 두 번째 묶음은 CLIENT 스팬 wide 를 먼저 연 뒤 자리를 얻으면서 속성 pool.wait_ms 와 이벤트 pool.acquired 를 남깁니다. 덤프와 같은 디렉터리의 pool.tsv 에 narrow·wide 두 줄로 각 묶음에서 가장 오래 열려 있던 스팬의 밀리초를 적으세요.

ConnPool.lease() 는 기다린 밀리초를 yield 합니다 — with pool.lease() as waited:. 두 묶음의 차이는 코드 두 줄의 순서뿐인데 트레이스에서는 전혀 다르게 보입니다. 풀을 두 묶음이 나눠 쓰면 결과가 섞이니 묶음마다 새로 만드세요. 스레드는 threading.Thread 로 만들고 전부 join() 합니다.

끊긴 호출의 짝을 덤프에서 찾는다

/root/tp-client/timeout.py 를 만드세요. 덤프 기본 경로는 /root/tp-client/timeout.jsonl, 서버 덤프는 같은 디렉터리의 timeout-server.jsonl 입니다. CLIENT 스팬 GET /stock 안에서 be.call("GET /stock", 400, carrier, timeout_ms=120) 을 부르고, 올라온 타임아웃을 잡아 스팬 상태를 ERROR 로 두고 속성 error.type 을 timeout, rpc.timeout_ms 를 120 으로 적으세요. be.close() 로 서버 일감이 끝나기를 기다린 뒤 flush() 하고, 두 덤프를 다시 읽어 같은 trace_id 를 가진 짝을 찾아 덤프와 같은 디렉터리의 orphan.tsv 에 <trace_id>, <클라이언트 밀리초>, <서버 밀리초>, <판정> 을 탭으로 나눠 한 줄 적습니다. 판정은 서버 쪽이 더 길면 client-gave-up, 아니면 server-finished-first 입니다.

Backend.call 의 타임아웃은 concurrent.futures.TimeoutError 로 올라옵니다. be.close() 를 부르지 않고 flush() 하면 서버 스팬이 덤프에 남지 않아 짝을 찾을 수 없습니다. 덤프는 JSON 한 줄씩이라 json.loads 로 그대로 읽힙니다. 두 스팬의 길이 차이가 이 단계의 요점입니다.

취소된 호출을 오류와 다르게 남긴다

/root/tp-client/cancel.py 를 만들어 두 가지를 남기세요. 덤프 기본 경로는 /root/tp-client/cancel.jsonl, 서버 덤프는 같은 디렉터리의 cancel-server.jsonl 입니다. (1) CLIENT 스팬 GET /recs 에서 be.submit("GET /recs", 300, carrier) 로 호출을 보낸 뒤 60밀리초만 기다리다 그만둡니다 — 상태는 건드리지 말고 속성 rpc.cancelled 를 참으로, 이벤트 rpc.cancelled 를 남깁니다. (2) CLIENT 스팬 GET /promo 에서 be.call("GET /promo", 20, carrier, fail=True) 를 부르고 올라온 예외를 record_exception 으로 기록한 뒤 상태를 ERROR 로 둡니다. 덤프와 같은 디렉터리의 05-cancel.txt 에 cancelled_status=, failed_status=, reason=(왜 둘을 다르게 남기는지 100자 이상) 세 줄을 적으세요.

상태를 건드리지 않은 스팬은 덤프에 UNSET 으로 남습니다. 두 상태 값은 덤프를 열어 확인한 뒤 파일에 적으세요 — 지어내면 덤프와 어긋납니다. 예외는 from tracelab.tp_client.backend import BackendError 로 잡습니다.

대상 식별 속성을 저카디널리티로 정한다

/root/tp-client/target.py 를 만들어 /opt/app/tracelab/tp_client/plan.json 의 cardinality 호출 여덟 건을 보내세요. 덤프 기본 경로는 /root/tp-client/target.jsonl, 서버 덤프는 같은 디렉터리의 target-server.jsonl 입니다. CLIENT 스팬 이름은 <target>/<op> 이고 속성 네 개를 붙입니다 — rpc.service(target), rpc.method(op), server.address(target), url.template(path 에서 주문 아이디만 plan.json 의 placeholder 로 바꾼 것). 주소의 host 와 주문 아이디는 속성 값에 넣지 않습니다. 덤프와 같은 디렉터리의 cardinality.tsv 에 네 속성의 이름과 서로 다른 값의 개수를 속성 이름 사전순으로 탭으로 나눠 네 줄 적으세요.

plan.json 의 limits 가 각 속성이 가질 수 있는 값의 가짓수를 알려 줍니다. host 에는 파드 접미사가, path 에는 주문 아이디가 들어 있어 그대로 넣으면 호출마다 값이 달라집니다. 대상이 둘이므로 Backend 도 대상마다 하나씩 만들어 재사용하세요.

같은 대상을 여러 번 부른 것을 클라이언트 쪽에서 드러낸다

/root/tp-client/repeat.py 를 만들어 /opt/app/tracelab/tp_client/plan.json 의 checkout 호출 일곱 건을 SERVER 스팬 POST /checkout 하나 아래에서 보내세요. 덤프 기본 경로는 /root/tp-client/repeat.jsonl, 서버 덤프는 같은 디렉터리의 repeat-server.jsonl 입니다. 루트 스팬에 속성 rpc.client.calls 로 나간 호출 수를 적고, CLIENT 스팬마다 6단계와 같은 네 속성을 붙입니다. 덤프와 같은 디렉터리의 repeat.tsv 에 <server.address>, <rpc.method>, <호출 수>, <걸린 시간 합(정수 밀리초)> 을 호출 수가 많은 것부터 탭으로 나눠 적으세요. 호출 수가 같으면 주소 사전순입니다.

묶는 열쇠는 대상과 연산 두 가지입니다 — 그래서 저카디널리티 속성이 필요했습니다. 루트 스팬 하나에 호출 수를 적어 두면 자식을 펴 보지 않고도 부챗살이 넓은 요청을 걸러낼 수 있습니다. 시간 합은 각 CLIENT 호출을 감싼 구간을 더해 반올림한 정수입니다.

규칙을 파일로 적고 두 번째 클라이언트에 적용한다

먼저 /root/tp-client/client-policy.json 에 지금까지의 판단을 적으세요 — span_kind, boundary(풀 대기가 스팬 안인지 밖인지), required_attributes(6단계의 네 속성), forbidden_value_sources(속성 값으로 쓰면 안 되는 재료의 필드 이름들), timeout_status, cancel_status. 그다음 /root/tp-client/second.py 를 만들어 그 파일을 읽고 /opt/app/tracelab/tp_client/plan.json 의 search 호출 네 건을 두 번째 클라이언트로 보냅니다. 덤프 기본 경로는 /root/tp-client/second.jsonl, 서버 덤프는 같은 디렉터리의 second-server.jsonl 이고, 크기 1 짜리 ConnPool 을 써서 기다린 시간을 스팬 안의 pool.wait_ms 로 남깁니다. 덤프와 같은 디렉터리의 second.tsv 에 <rpc.method>, <호출 수>, <서로 다른 server.address 수> 를 연산 이름 사전순으로 세 칸씩 적으세요.

속성 이름을 프로그램에 다시 적지 말고 규칙 파일의 required_attributes 를 돌면서 붙이세요 — 그것이 '규칙을 적용한다' 는 말의 뜻입니다. forbidden_value_sources 에는 plan.json 에서 그대로 쓰면 안 되는 필드 이름을 적습니다. 상태 두 개는 4·5단계에서 덤프로 확인한 값입니다.