いちばん遅いスパンを直したのに応答は変わらなかった

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

목표

파드에 들어 있는 3,454개 스팬을 표준 라이브러리만으로 분석해 자기 시간과 임계 경로를 직접 계산하고, '가장 오래 걸린 스팬' 과 '고쳐야 할 스팬' 이 다르다는 것을 숫자로 확인한 뒤 무엇을 고칠지 예상 절감과 함께 제출합니다.

왜 중요한가

폭포수 화면에서 제일 긴 막대는 '그 구간에 시간이 얼마나 걸렸나' 를 말해 줄 뿐, '그 구간을 줄이면 전체가 줄어드나' 에는 답하지 않는다. 병렬로 도는 형제 중 먼저 끝나는 쪽은 아무리 길어도 응답 시간에 기여하지 않는다. 두 질문을 가르는 것이 임계 경로 계산이고, 그 계산은 스팬의 시작 시각·지속 시간·부모 식별자 세 가지만 있으면 된다. 여기에 자기 시간을 겹쳐 보면 고칠 자리가 좁혀지고, 같은 이름의 형제를 묶어 보면 개별 순위에는 들지 않던 N+1 이 드러난다. 고치기 전에 예상 절감을 숫자로 적어 두는 습관이 마지막 한 조각이다 — 그래야 배포 뒤에 판단이 맞았는지 남는다.

단계

/root/obs-trace-critical/trace.py 를 만드세요. python3 trace.py shape 를 실행하면 /opt/lab/critpath/spans.jsonl 를 읽어 여섯 줄을 spans=, traces=, roots=, rootless_traces=, orphan_spans=, clean_traces= 순서로 출력해야 합니다. 루트 스팬은 parent_id 가 null 인 스팬, 고아 스팬은 parent_id 가 이 파일 안에 없는 스팬, clean_traces 는 루트가 정확히 하나이고 고아가 하나도 없는 트레이스 수입니다. 같은 여섯 줄을 /root/obs-trace-critical/01-shape.txt 에도 저장하세요.
trace.py tree <trace_id> 를 더하세요. 그 트레이스의 스팬을 루트부터 깊이 우선으로 훑으며 한 줄에 하나씩 <깊이><탭><span_id><탭><name><탭><지속시간> 을 출력합니다. 깊이는 루트가 0 이고, 형제는 start_ms 오름차순입니다. 지속 시간은 소수 셋째 자리까지 적습니다. 루트가 없는 트레이스를 주면 0 이 아닌 값으로 끝나야 합니다.
trace.py self <trace_id> 를 더하세요. 스팬마다 자기 시간(총 시간 − 자식들이 차지한 시간)을 구해 <span_id><탭><name><탭><자기시간> 을 자기 시간 내림차순으로 모두 출력합니다. 자식 구간이 서로 겹칠 때는 합집합 길이를 빼야 합니다 — 단순히 더해서 빼면 병렬 호출이 있는 스팬에서 음수가 나옵니다. 008cde18a6503944 로 확인해 보세요.
trace.py crit <trace_id> 를 더하세요. 루트의 지속 시간을 실제로 결정한 스팬들만 골라 <span_id><탭><name><탭><임계 경로 기여 밀리초> 를 기여 내림차순으로 출력합니다. 루트의 끝에서 거꾸로 훑으며 지금 시각보다 늦게 끝나는 자식은 건너뛰고, 가장 늦게 끝나는 자식으로 내려갑니다. 출력된 기여의 합은 루트의 지속 시간과 같아야 합니다 — 그것이 검산입니다.
기준 트레이스 008cde18a6503944 에서 루트를 뺀 스팬을 세 가지로 줄 세워 /root/obs-trace-critical/05-compare.tsv 에 저장하세요. 머리글 없이 세 줄이고, 각 줄은 탭으로 나눈 네 칸 <순위><탭><총시간 1·2·3위 이름><탭><자기시간 1·2·3위 이름><탭><임계경로 기여 1·2·3위 이름> 입니다(순위는 1·2·3). 그리고 /root/obs-trace-critical/05-note.txt 에 두 줄을 적으세요 — longest_span= 뒤에 총 시간 1위 스팬의 이름, longest_on_critical_path= 뒤에 그 스팬이 임계 경로 위에 있으면 yes, 아니면 no.
trace.py nplus <trace_id> 를 더하세요. 같은 부모 아래에 같은 이름이 5개 이상 줄지어 있는 무리를 찾아 <부모 span_id><탭><name><탭><개수><탭><합계 밀리초><탭><절감 밀리초> 를 절감 내림차순으로 출력합니다. 절감은 '한 번의 호출로 묶었을 때' 로 보고 합계 − 그중 가장 긴 하나 로 계산합니다. 그리고 /root/obs-trace-critical/06-nplus.txt 에 기준 트레이스 008cde18a6503944 의 1위 무리를 name=, count=, total_ms=, saving_ms=, new_root_ms= 다섯 줄로 적으세요. new_root_ms 는 그 절감이 그대로 먹혔을 때의 루트 지속 시간입니다.
trace.py pct 를 더하세요. 깨끗한 트레이스(루트 하나·고아 없음)의 루트 지속 시간을 오름차순으로 줄 세우고 p50 과 p99 를 가장 가까운 순위(nearest-rank) 로 고릅니다 — 개수가 n 일 때 색인은 ceil(q × n) − 1 입니다. 출력은 두 줄이고 각각 <p50|p99><탭><trace_id><탭><루트 지속 시간> 입니다. 그다음 두 트레이스의 임계 경로를 견주어 /root/obs-trace-critical/07-p50p99.txt 에 여섯 줄을 적으세요 — p50_trace=, p50_ms=, p99_trace=, p99_ms=, only_in_p99=, only_in_p50=. 마지막 두 줄은 한쪽 임계 경로에만 나오는 스팬 이름을 쉼표로 이어 적습니다(이름 오름차순, 공백 없이).
기준 트레이스 008cde18a6503944 를 놓고 후보 세 가지를 견주어 /root/obs-trace-critical/08-plan.tsv 에 저장하세요. 머리글 없이 세 줄이고 각 줄은 탭으로 나눈 네 칸 <id><탭><대상><탭><예상 절감 밀리초><탭><yes|no> 입니다. id 는 a·b·c 이고 대상은 차례로 inventory.db.scan 을 0 으로 만들기, pricing.rules.eval 을 0 으로 만들기, db.query.item 을 한 번으로 묶기입니다. 예상 절감은 앞 두 개가 그 스팬의 임계 경로 기여, 마지막이 6단계의 절감이며, 네 번째 칸은 그 대상이 임계 경로 위에 있으면 yes 입니다. 그다음 /root/obs-trace-critical/08-decision.txt 에 네 줄 fix=(a·b·c 중 하나), expected_ms=, new_root_ms=, reason=(60자 이상) 을 적으세요. 절감이 0 인 후보는 고를 수 없습니다.

참고

작업 디렉터리는 /root/obs-trace-critical 입니다. 없으면 먼저 만드세요.
재료는 /opt/lab/critpath/spans.jsonl 입니다(JSON Lines, 3,454줄). 만든 스크립트는 같은 디렉터리의 gen_spans.py 입니다. 스팬 한 줄에는 trace_id·span_id·parent_id·service·name·start_ms·duration_ms 가 들어 있고, start_ms 는 그 트레이스의 루트가 시작한 시점으로부터의 밀리초입니다.
기준 트레이스는 008cde18a6503944 이고, 느린 트레이스의 예로 d1272fdd4d4bfe50 를 함께 보면 차이가 잘 보입니다.
파이썬은 3.12 표준 라이브러리만 씁니다. pip install 은 되지 않습니다.
흔한 실수: 자식 시간을 그냥 더해서 자기 시간을 구하는 것. 병렬 자식이 있으면 음수가 나옵니다.
흔한 실수: 루트가 없거나 고아가 섞인 트레이스까지 통계에 넣는 것. 합계가 조용히 틀어집니다.
Traces (OpenTelemetry) · Observability primer · Instrumentation concepts · Latency (SRE Book: 네 가지 골든 시그널)

자료의 모양부터 센다 — 루트 없는 트레이스와 고아 스팬

/root/obs-trace-critical/trace.py 를 만드세요. python3 trace.py shape 를 실행하면 /opt/lab/critpath/spans.jsonl 를 읽어 여섯 줄을 spans=, traces=, roots=, rootless_traces=, orphan_spans=, clean_traces= 순서로 출력해야 합니다. 루트 스팬은 parent_id 가 null 인 스팬, 고아 스팬은 parent_id 가 이 파일 안에 없는 스팬, clean_traces 는 루트가 정확히 하나이고 고아가 하나도 없는 트레이스 수입니다. 같은 여섯 줄을 /root/obs-trace-critical/01-shape.txt 에도 저장하세요.

파일은 JSON Lines 입니다 — 한 줄에 JSON 하나. span_id 를 열쇠로 하는 딕셔너리를 먼저 만들면 고아 판정이 parent_id not in spans 한 줄이 됩니다. 뒤 단계들이 같은 파일에 하위 명령을 더해 가므로, sys.argv[1] 로 하위 명령을 고르는 뼈대부터 잡아 두세요.

부모-자식을 다시 잇고 깊이를 붙인다

trace.py tree <trace_id> 를 더하세요. 그 트레이스의 스팬을 루트부터 깊이 우선으로 훑으며 한 줄에 하나씩 <깊이><탭><span_id><탭><name><탭><지속시간> 을 출력합니다. 깊이는 루트가 0 이고, 형제는 start_ms 오름차순입니다. 지속 시간은 소수 셋째 자리까지 적습니다. 루트가 없는 트레이스를 주면 0 이 아닌 값으로 끝나야 합니다.

부모 식별자를 열쇠로 자식 목록을 모아 두면(kids[parent_id] = [자식들]) 훑기가 쉬워집니다. 재귀 대신 스택을 쓰면 형제 순서를 뒤집어 넣어야 출력 순서가 맞습니다. 시험해 볼 트레이스는 008cde18a6503944 입니다.

자기 시간 — 겹치는 자식은 합집합으로 뺀다

trace.py self <trace_id> 를 더하세요. 스팬마다 자기 시간(총 시간 − 자식들이 차지한 시간)을 구해 <span_id><탭><name><탭><자기시간> 을 자기 시간 내림차순으로 모두 출력합니다. 자식 구간이 서로 겹칠 때는 합집합 길이를 빼야 합니다 — 단순히 더해서 빼면 병렬 호출이 있는 스팬에서 음수가 나옵니다. 008cde18a6503944 로 확인해 보세요.

구간을 시작 시각으로 정렬해 놓고 앞에서부터 이어 붙이면 합집합 길이를 한 번에 구할 수 있습니다. 자식 구간은 부모 구간 밖으로 삐져나갈 수 있으니 부모 범위로 잘라서 세는 편이 안전합니다. 이 트레이스의 루트에서 자식 시간을 그냥 더하면 루트 지속 시간보다 커집니다.

임계 경로 — 병렬 자식 중 늦게 끝난 쪽만 든다

trace.py crit <trace_id> 를 더하세요. 루트의 지속 시간을 실제로 결정한 스팬들만 골라 <span_id><탭><name><탭><임계 경로 기여 밀리초> 를 기여 내림차순으로 출력합니다. 루트의 끝에서 거꾸로 훑으며 지금 시각보다 늦게 끝나는 자식은 건너뛰고, 가장 늦게 끝나는 자식으로 내려갑니다. 출력된 기여의 합은 루트의 지속 시간과 같아야 합니다 — 그것이 검산입니다.

부모의 구간 중 자식이 덮지 않은 자리는 부모 자신의 기여입니다. 자식으로 내려간 뒤에는 '지금 시각' 을 그 자식의 시작 시각으로 당겨 놓고 다음 형제를 봅니다. 먼저 끝난 병렬 형제는 이 과정에서 자연스럽게 빠집니다 — 그 형제가 끝난 시각이 이미 지나간 시각보다 뒤라서 건너뛰어집니다.

세 목록이 다르다 — 어느 쪽을 고쳐야 응답이 줄어드나

기준 트레이스 008cde18a6503944 에서 루트를 뺀 스팬을 세 가지로 줄 세워 /root/obs-trace-critical/05-compare.tsv 에 저장하세요. 머리글 없이 세 줄이고, 각 줄은 탭으로 나눈 네 칸 <순위><탭><총시간 1·2·3위 이름><탭><자기시간 1·2·3위 이름><탭><임계경로 기여 1·2·3위 이름> 입니다(순위는 1·2·3). 그리고 /root/obs-trace-critical/05-note.txt 에 두 줄을 적으세요 — longest_span= 뒤에 총 시간 1위 스팬의 이름, longest_on_critical_path= 뒤에 그 스팬이 임계 경로 위에 있으면 yes, 아니면 no.

세 목록은 앞 단계의 세 하위 명령이 그대로 만들어 줍니다. 총 시간 순위는 tree 출력의 마지막 칸으로, 자기 시간은 self, 임계 경로 기여는 crit 으로 얻습니다. 루트는 항상 총 시간 1위라 빼고 셉니다. 세 목록의 1위가 서로 다르다면 제대로 계산한 것입니다.

N+1 — 하나는 작지만 열여섯 개는 크다

trace.py nplus <trace_id> 를 더하세요. 같은 부모 아래에 같은 이름이 5개 이상 줄지어 있는 무리를 찾아 <부모 span_id><탭><name><탭><개수><탭><합계 밀리초><탭><절감 밀리초> 를 절감 내림차순으로 출력합니다. 절감은 '한 번의 호출로 묶었을 때' 로 보고 합계 − 그중 가장 긴 하나 로 계산합니다. 그리고 /root/obs-trace-critical/06-nplus.txt 에 기준 트레이스 008cde18a6503944 의 1위 무리를 name=, count=, total_ms=, saving_ms=, new_root_ms= 다섯 줄로 적으세요. new_root_ms 는 그 절감이 그대로 먹혔을 때의 루트 지속 시간입니다.

형제 목록을 이름으로 묶으면(group[name].append(child)) 무리를 바로 셀 수 있습니다. 절감이 루트에 그대로 먹히는지는 그 무리가 임계 경로 위에 있는지에 달려 있습니다 — 앞 단계의 crit 출력에서 그 이름들이 보이는지 확인해 보세요.

p50 과 p99 의 임계 경로는 다르다

trace.py pct 를 더하세요. 깨끗한 트레이스(루트 하나·고아 없음)의 루트 지속 시간을 오름차순으로 줄 세우고 p50 과 p99 를 가장 가까운 순위(nearest-rank) 로 고릅니다 — 개수가 n 일 때 색인은 ceil(q × n) − 1 입니다. 출력은 두 줄이고 각각 <p50|p99><탭><trace_id><탭><루트 지속 시간> 입니다. 그다음 두 트레이스의 임계 경로를 견주어 /root/obs-trace-critical/07-p50p99.txt 에 여섯 줄을 적으세요 — p50_trace=, p50_ms=, p99_trace=, p99_ms=, only_in_p99=, only_in_p50=. 마지막 두 줄은 한쪽 임계 경로에만 나오는 스팬 이름을 쉼표로 이어 적습니다(이름 오름차순, 공백 없이).

임계 경로의 이름 집합은 crit 출력의 둘째 칸을 모으면 됩니다. 두 집합의 차집합을 양쪽으로 구하세요. 느린 트레이스에서는 병렬 형제 중 늦게 끝나는 쪽이 뒤바뀝니다 — 그래서 경로에 드는 이름이 통째로 갈립니다.

무엇을 고칠 것인가 — 예상 절감을 숫자로 적는다

기준 트레이스 008cde18a6503944 를 놓고 후보 세 가지를 견주어 /root/obs-trace-critical/08-plan.tsv 에 저장하세요. 머리글 없이 세 줄이고 각 줄은 탭으로 나눈 네 칸 <id><탭><대상><탭><예상 절감 밀리초><탭><yes|no> 입니다. id 는 a·b·c 이고 대상은 차례로 inventory.db.scan 을 0 으로 만들기, pricing.rules.eval 을 0 으로 만들기, db.query.item 을 한 번으로 묶기입니다. 예상 절감은 앞 두 개가 그 스팬의 임계 경로 기여, 마지막이 6단계의 절감이며, 네 번째 칸은 그 대상이 임계 경로 위에 있으면 yes 입니다. 그다음 /root/obs-trace-critical/08-decision.txt 에 네 줄 fix=(a·b·c 중 하나), expected_ms=, new_root_ms=, reason=(60자 이상) 을 적으세요. 절감이 0 인 후보는 고를 수 없습니다.

임계 경로에 없는 스팬의 기여는 0 입니다 — crit 출력에 그 이름이 아예 나오지 않습니다. new_root_ms 는 루트 지속 시간에서 고른 후보의 절감을 뺀 값입니다. reason= 에는 왜 다른 둘이 아니라 그것인지를 앞 단계의 숫자를 들어 적으세요 — 배포 뒤에 이 예상이 맞았는지 확인할 수 있어야 합니다.