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

目標

Podに入っている3,454個のスパンを標準ライブラリだけで分析して、自己時間とクリティカルパスを自分で計算し、「最も時間がかかったスパン」と「直すべきスパン」が違うことを数字で確認したうえで、何を直すかを予想削減量とともに提出します。

なぜ重要なのか

ウォーターフォール画面で最も長いバーは、「その区間にどれだけ時間がかかったか」を教えてくれるだけで、「その区間を縮めれば全体が縮むか」には答えてくれません。並列に動く兄弟のうち、先に終わるほうは、どれだけ長くても応答時間に寄与しません。2つの問いを分けるのがクリティカルパスの計算で、その計算には、スパンの開始時刻・継続時間・親の識別子の3つだけがあればよいのです。ここに自己時間を重ねて見ると、直す場所が絞られ、同じ名前の兄弟をまとめて見ると、個別の順位には入らなかったN+1が現れます。直す前に、予想削減量を数字で書いておく習慣が、最後の1ピースです。そうすれば、デプロイ後に判断が合っていたかが残ります。

ステップ

/root/obs-trace-critical/trace.pyを作成してください。python3 trace.py shapeを実行すると、/opt/lab/critpath/spans.jsonlを読んで、6行をspans=、traces=、roots=、rootless_traces=、orphan_spans=、clean_traces=の順に出力しなければなりません。ルートスパンはparent_idがnullのスパン、孤立スパンはparent_idがこのファイルの中にないスパン、clean_tracesは、ルートがちょうど1つで孤立スパンが1つもないトレースの数です。同じ6行を、/root/obs-trace-critical/01-shape.txtにも保存してください。
trace.py tree <trace_id>を加えてください。そのトレースのスパンを、ルートから深さ優先でたどりながら、1行に1つずつ<깊이><탭><span_id><탭><name><탭><지속시간>を出力します(プレースホルダーは深さ、タブ、span_id、name、継続時間です)。深さはルートが0で、兄弟はstart_msの昇順です。継続時間は小数第3位まで書きます。ルートがないトレースを渡したら、0以外の値で終了しなければなりません。
trace.py self <trace_id>を加えてください。スパンごとに自己時間(総時間 − 子が占めた時間)を求めて、<span_id><탭><name><탭><자기시간>を自己時間の降順ですべて出力します(プレースホルダーはタブと自己時間です)。子の区間が互いに重なるときは、和集合の長さを引く必要があります。単純に足して引くと、並列呼び出しのあるスパンで負の数が出ます。008cde18a6503944で確認してみてください。
trace.py crit <trace_id>を加えてください。ルートの継続時間を実際に決めたスパンだけを選んで、<span_id><탭><name><탭><임계 경로 기여 밀리초>を、寄与の降順で出力します(プレースホルダーはタブとクリティカルパスへの寄与のミリ秒です)。ルートの終わりから逆向きにたどりながら、今の時刻より遅く終わる子は飛ばして、最も遅く終わる子へ下ります。出力された寄与の合計は、ルートの継続時間と等しくなければなりません。それが検算です。
基準のトレース008cde18a6503944からルートを除いたスパンを、3通りで順位付けして、/root/obs-trace-critical/05-compare.tsvに保存してください。ヘッダーなしで3行、各行はタブで区切った4列<순위><탭><총시간 1·2·3위 이름><탭><자기시간 1·2·3위 이름><탭><임계경로 기여 1·2·3위 이름>です(順位は1・2・3。プレースホルダーは、順位、タブ、総時間の1・2・3位の名前、自己時間の1・2・3位の名前、クリティカルパス寄与の1・2・3位の名前です)。そして/root/obs-trace-critical/05-note.txtに2行を書いてください。longest_span=の後ろに総時間1位のスパンの名前、longest_on_critical_path=の後ろに、そのスパンがクリティカルパス上にあればyes、なければnoです。
trace.py nplus <trace_id>を加えてください。同じ親の下に同じ名前が5つ以上並んでいる集団を探して、<부모 span_id><탭><name><탭><개수><탭><합계 밀리초><탭><절감 밀리초>を、削減量の降順で出力します(プレースホルダーは、親のspan_id、タブ、name、個数、合計ミリ秒、削減ミリ秒です)。削減量は「1回の呼び出しにまとめたとき」として見て、합계 − 그중 가장 긴 하나で計算します(プレースホルダーは、合計と、そのうち最も長い1つです)。そして/root/obs-trace-critical/06-nplus.txtに、基準のトレース008cde18a6503944の1位の集団を、name=、count=、total_ms=、saving_ms=、new_root_ms=の5行で書いてください。new_root_msは、その削減がそのまま効いたときのルートの継続時間です。
trace.py pctを加えてください。きれいなトレース(ルート1つ・孤立なし)のルートの継続時間を昇順に並べて、p50とp99を最近傍順位(nearest-rank)で選びます。個数がnのとき、インデックスはceil(q × n) − 1です。出力は2行で、それぞれ<p50|p99><탭><trace_id><탭><루트 지속 시간>です(プレースホルダーは、タブ、trace_id、ルートの継続時間です)。そのあと、2つのトレースのクリティカルパスを見比べて、/root/obs-trace-critical/07-p50p99.txtに6行を書いてください。p50_trace=、p50_ms=、p99_trace=、p99_ms=、only_in_p99=、only_in_p50=です。最後の2行は、片方のクリティカルパスにだけ現れるスパンの名前を、カンマでつないで書きます(名前の昇順、空白なし)。
基準のトレース008cde18a6503944を前に、3つの候補を見比べて、/root/obs-trace-critical/08-plan.tsvに保存してください。ヘッダーなしで3行、各行はタブで区切った4列<id><탭><대상><탭><예상 절감 밀리초><탭><yes|no>です(プレースホルダーは、id、タブ、対象、予想削減ミリ秒、yesまたはnoです)。idはa・b・cで、対象は順に、inventory.db.scanを0にする、pricing.rules.evalを0にする、db.query.itemを1回にまとめる、です。予想削減量は、前の2つがそのスパンのクリティカルパスへの寄与、最後がステップ6の削減量で、4列目は、その対象がクリティカルパス上にあればyesです。そのあと/root/obs-trace-critical/08-decision.txtに、4行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です。スパン1行には、trace_id・span_id・parent_id・service・name・start_ms・duration_msが入っていて、start_msは、そのトレースのルートが開始した時点からのミリ秒です。
基準のトレースは008cde18a6503944で、遅いトレースの例としてd1272fdd4d4bfe50を一緒に見ると、違いがよくわかります。
Pythonは3.12の標準ライブラリだけを使います。pip installはできません。
よくある間違い: 子の時間を単純に足して、自己時間を求めてしまうこと。並列の子がいると、負の数が出ます。
よくある間違い: ルートがなかったり孤立スパンが混ざったりしたトレースまで、統計に入れてしまうこと。合計が静かに狂います。
Traces (OpenTelemetry)・Observability primer・Instrumentation concepts・Latency (SRE Book: 4つのゴールデンシグナル)

データの形から数える: ルートのないトレースと孤立スパン

/root/obs-trace-critical/trace.pyを作成してください。python3 trace.py shapeを実行すると、/opt/lab/critpath/spans.jsonlを読んで、6行をspans=、traces=、roots=、rootless_traces=、orphan_spans=、clean_traces=の順に出力しなければなりません。ルートスパンはparent_idがnullのスパン、孤立スパンはparent_idがこのファイルの中にないスパン、clean_tracesは、ルートがちょうど1つで孤立スパンが1つもないトレースの数です。同じ6行を、/root/obs-trace-critical/01-shape.txtにも保存してください。

ファイルはJSON Linesです。1行にJSONが1つです。span_idをキーとする辞書を先に作れば、孤立の判定がparent_id not in spansの1行になります。あとのステップが同じファイルにサブコマンドを足していくので、sys.argv[1]でサブコマンドを選ぶ骨組みを先に作っておいてください。

親子を再びつないで、深さを付ける

trace.py tree <trace_id>を加えてください。そのトレースのスパンを、ルートから深さ優先でたどりながら、1行に1つずつ<깊이><탭><span_id><탭><name><탭><지속시간>を出力します(プレースホルダーは深さ、タブ、span_id、name、継続時間です)。深さはルートが0で、兄弟はstart_msの昇順です。継続時間は小数第3位まで書きます。ルートがないトレースを渡したら、0以外の値で終了しなければなりません。

親の識別子をキーに子のリストを集めておくと(kids[parent_id] = [자식들]、プレースホルダーは子たちです)、たどりやすくなります。再帰の代わりにスタックを使うなら、兄弟の順序を逆にして入れないと、出力の順序が合いません。試してみるトレースは008cde18a6503944です。

自己時間: 重なる子は和集合で引く

trace.py self <trace_id>を加えてください。スパンごとに自己時間(総時間 − 子が占めた時間)を求めて、<span_id><탭><name><탭><자기시간>を自己時間の降順ですべて出力します(プレースホルダーはタブと自己時間です)。子の区間が互いに重なるときは、和集合の長さを引く必要があります。単純に足して引くと、並列呼び出しのあるスパンで負の数が出ます。008cde18a6503944で確認してみてください。

区間を開始時刻で並べ替えておき、先頭からつないでいけば、和集合の長さを一度に求められます。子の区間は親の区間の外にはみ出すことがあるので、親の範囲で切って数えるほうが安全です。このトレースのルートで、子の時間を単純に足すと、ルートの継続時間より大きくなります。

クリティカルパス: 並列の子のうち、遅く終わったほうだけを含める

trace.py crit <trace_id>を加えてください。ルートの継続時間を実際に決めたスパンだけを選んで、<span_id><탭><name><탭><임계 경로 기여 밀리초>を、寄与の降順で出力します(プレースホルダーはタブとクリティカルパスへの寄与のミリ秒です)。ルートの終わりから逆向きにたどりながら、今の時刻より遅く終わる子は飛ばして、最も遅く終わる子へ下ります。出力された寄与の合計は、ルートの継続時間と等しくなければなりません。それが検算です。

親の区間のうち、子が覆っていない場所は、親自身の寄与です。子へ下りたあとは、「今の時刻」をその子の開始時刻まで引き戻して、次の兄弟を見ます。先に終わった並列の兄弟は、この過程で自然に外れます。その兄弟が終わった時刻が、すでに過ぎた時刻より後なので、飛ばされるのです。

3つのリストが違う: どちらを直せば応答が縮むか

基準のトレース008cde18a6503944からルートを除いたスパンを、3通りで順位付けして、/root/obs-trace-critical/05-compare.tsvに保存してください。ヘッダーなしで3行、各行はタブで区切った4列<순위><탭><총시간 1·2·3위 이름><탭><자기시간 1·2·3위 이름><탭><임계경로 기여 1·2·3위 이름>です(順位は1・2・3。プレースホルダーは、順位、タブ、総時間の1・2・3位の名前、自己時間の1・2・3位の名前、クリティカルパス寄与の1・2・3位の名前です)。そして/root/obs-trace-critical/05-note.txtに2行を書いてください。longest_span=の後ろに総時間1位のスパンの名前、longest_on_critical_path=の後ろに、そのスパンがクリティカルパス上にあればyes、なければnoです。

3つのリストは、前のステップの3つのサブコマンドがそのまま作ってくれます。総時間の順位はtreeの出力の最後の列で、自己時間はself、クリティカルパスへの寄与はcritで得られます。ルートは常に総時間1位なので、除いて数えます。3つのリストの1位が互いに違っていれば、正しく計算できています。

N+1: 1つは小さいが、16個は大きい

trace.py nplus <trace_id>を加えてください。同じ親の下に同じ名前が5つ以上並んでいる集団を探して、<부모 span_id><탭><name><탭><개수><탭><합계 밀리초><탭><절감 밀리초>を、削減量の降順で出力します(プレースホルダーは、親のspan_id、タブ、name、個数、合計ミリ秒、削減ミリ秒です)。削減量は「1回の呼び出しにまとめたとき」として見て、합계 − 그중 가장 긴 하나で計算します(プレースホルダーは、合計と、そのうち最も長い1つです)。そして/root/obs-trace-critical/06-nplus.txtに、基準のトレース008cde18a6503944の1位の集団を、name=、count=、total_ms=、saving_ms=、new_root_ms=の5行で書いてください。new_root_msは、その削減がそのまま効いたときのルートの継続時間です。

兄弟のリストを名前でまとめれば(group[name].append(child))、集団をすぐに数えられます。削減がルートにそのまま効くかは、その集団がクリティカルパス上にあるかにかかっています。前のステップのcritの出力に、それらの名前が見えるかを確認してみてください。

p50とp99のクリティカルパスは違う

trace.py pctを加えてください。きれいなトレース(ルート1つ・孤立なし)のルートの継続時間を昇順に並べて、p50とp99を最近傍順位(nearest-rank)で選びます。個数がnのとき、インデックスはceil(q × n) − 1です。出力は2行で、それぞれ<p50|p99><탭><trace_id><탭><루트 지속 시간>です(プレースホルダーは、タブ、trace_id、ルートの継続時間です)。そのあと、2つのトレースのクリティカルパスを見比べて、/root/obs-trace-critical/07-p50p99.txtに6行を書いてください。p50_trace=、p50_ms=、p99_trace=、p99_ms=、only_in_p99=、only_in_p50=です。最後の2行は、片方のクリティカルパスにだけ現れるスパンの名前を、カンマでつないで書きます(名前の昇順、空白なし)。

クリティカルパスの名前の集合は、critの出力の2列目を集めればよいのです。2つの集合の差集合を、両方向で求めてください。遅いトレースでは、並列の兄弟のうち遅く終わるほうが入れ替わります。そのため、経路に入る名前がまるごと分かれます。

何を直すか: 予想削減量を数字で書く

基準のトレース008cde18a6503944を前に、3つの候補を見比べて、/root/obs-trace-critical/08-plan.tsvに保存してください。ヘッダーなしで3行、各行はタブで区切った4列<id><탭><대상><탭><예상 절감 밀리초><탭><yes|no>です(プレースホルダーは、id、タブ、対象、予想削減ミリ秒、yesまたはnoです)。idはa・b・cで、対象は順に、inventory.db.scanを0にする、pricing.rules.evalを0にする、db.query.itemを1回にまとめる、です。予想削減量は、前の2つがそのスパンのクリティカルパスへの寄与、最後がステップ6の削減量で、4列目は、その対象がクリティカルパス上にあればyesです。そのあと/root/obs-trace-critical/08-decision.txtに、4行fix=(a・b・cのいずれか)、expected_ms=、new_root_ms=、reason=(60文字以上)を書いてください。削減量が0の候補は選べません。

クリティカルパスにないスパンの寄与は0です。critの出力に、その名前がそもそも出てきません。new_root_msは、ルートの継続時間から、選んだ候補の削減量を引いた値です。reason=には、なぜ他の2つではなくそれなのかを、前のステップの数字を挙げて書いてください。デプロイ後に、この予想が合っていたかを確認できる必要があります。