We fixed the slowest span and the response time did not move

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

목표

파드에 들어 있는 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= 에는 왜 다른 둘이 아니라 그것인지를 앞 단계의 숫자를 들어 적으세요 — 배포 뒤에 이 예상이 맞았는지 확인할 수 있어야 합니다.