スパンが1つでは何も分からず、30個では誰も見ない

目標

計装が1行もない注文処理コードにスパンを自分で入れながら、境界をどこに引くかを数字で決める方法を身につけます。計装の空白を測り、繰り返しを属性に畳み、その判断をルールファイルに書いて、2つ目のハンドラーにそのまま適用します。

なぜ重要なのか

スパンを1つだけ置くと、トレースは「211ミリ秒かかった」以外に何も語りません。ループごとにスパンを作ると、今度は同じ形の棒が30個つながって、誰も最後まで見ません。2つの失敗は、同じ問いを飛ばした結果です。あとでこのトレースで何を尋ねるのか、という問いです。その問いに答えとなる場所を探す道具が、計装の空白です。親の区間のうち、どの子にも覆われていない時間がそのまま「まだわからない時間」であり、その場所が次にスパンを引く場所です。逆に、繰り返しはスパンではなく回数・合計時間・最大値に畳んで初めて、トレースが読めるサイズに収まります。最後に、この判断を人の好みに任せるとレビューのたびにまた争うことになるため、リクエストあたりのスパン上限と許容する空白をファイルに書いて、機械に読ませます。

ステップ

/root/tp-boundary/01_root.pyを作成してください。/opt/app/tracelab/dump.pyのproviderでサービス名shop-apiのプロバイダーを作り、ダンプのパスは環境変数TRACELAB_OUTから先に読み、なければ/root/tp-boundary/01-root.jsonlを使います。POST /checkoutという名前のSERVERスパン1つの中で、tracelab.tp_boundary.shopのvalidate→load_cart→price_of(全商品)→charge→write_receiptを順に呼び、最後にflush()を呼びます。そのあと/opt/otel-lab/bin/pythonで実行してダンプを作り、/root/tp-boundary/01-root.txtにspans=とroot_ms=の2行を書いてください(ダンプから読んだ値をそのまま)。
/root/tp-boundary/02_split.pyを作成してください。ステップ1と同じですが、データベースの往復であるload_cartをcart.loadスパンで、外へ出ていくchargeをpayment.chargeスパンで包みます(自動計装が代わりに作ってくれる場所がこの2つです)。ダンプのデフォルトのパスは/root/tp-boundary/02-split.jsonlです。実行したあと、/root/tp-boundary/02-gap.txtにroot_ms=・covered_ms=・gap_ms=・gap_ratio=の4行を書いてください。covered_msはルートの子の区間を和集合として足した長さで、gap_ratioは(ルート−覆われた時間)÷ルートを小数第4位まで書きます。
/root/tp-boundary/03_close.pyを作成してください。ステップ2で残った空白をなくすために、validateはorder.validate、商品の価格を調べる繰り返し全体はprice.lookup、write_receiptはreceipt.writeスパンで包みます。スパン名は、この5つ(order.validate・cart.load・price.lookup・payment.charge・receipt.write)とルートのPOST /checkoutに正確に合わせてください。ダンプのデフォルトのパスは/root/tp-boundary/03-close.jsonlです。実行したあと、/root/tp-boundary/03-gap.txtにステップ2と同じ4行を書き、gap_ratioが0.05未満になるようにしてください。
/root/tp-boundary/04_peritem.pyを作成してください。ステップ3と同じですが、price.lookupの中で商品を1つ調べるたびにprice.itemスパンを1つずつ作ります。ダンプのデフォルトのパスは/root/tp-boundary/04-peritem.jsonlです。実行したあと、/root/tp-boundary/04-count.txtにspans_per_request=・item_spans=・spans_per_1000_requests=の3行を書いてください。最後の行は、リクエストあたりのスパン数に1000を掛けた整数です。
/root/tp-boundary/05_fold.pyを作成してください。price.itemスパンをなくし、代わりにprice.lookupスパンに3つの属性price.lookup.count(調査回数)・price.lookup.total_ms(合計ミリ秒)・price.lookup.max_ms(最も時間がかかった1件のミリ秒)を付けます。そして、最も時間がかかった商品をprice.lookup.slowestというイベントとして残し、イベントの属性にskuを入れてください。ダンプのデフォルトのパスは/root/tp-boundary/05-fold.jsonlで、全体のスパン数は8個を超えてはいけません。
/root/tp-boundary/06_kind.pyを作成してください。ステップ5と同じですが、すべてのスパンにSpanKindを明示します。入ってきたリクエストはSERVER、プロセスの外へ出ていく呼び出し(cart.load・payment.charge・receipt.write)はCLIENT、プロセス内で分けた区間(order.validate・price.lookup)はINTERNALです。ダンプのデフォルトのパスは/root/tp-boundary/06-kind.jsonlです。実行したあと、/root/tp-boundary/06-kinds.tsvに、スパンごとに1行ずつ<스팬이름><탭><kind>(プレースホルダーはスパン名とタブです)を開始時刻の順に書いてください(ヘッダーなしで6行)。
/root/tp-boundary/budget.txtに3行を書いてください: max_spans_per_request=8、max_gap_ratio=0.10、root_kind=SERVER。そして/root/tp-boundary/check_budget.pyを作成してください。python3 check_budget.py <규칙파일> <덤프>(プレースホルダーはルールファイルとダンプです)で呼び出すと、ルールを破ったものごとにVIOLATION <규칙키> <지금 값>(プレースホルダーはルールのキーと現在の値です)を1行ずつ出力して終了コード1、すべて守っていればOKで始まる1行と終了コード0を返します。最後に/root/tp-boundary/07-verdict.tsvに3行を書いてください。各行は<덤프파일이름><탭><pass|fail><탭><깨진 규칙키 또는 ->(プレースホルダーはダンプのファイル名、タブ、破られたルールのキーまたはハイフンです)で、02-split.jsonl・04-peritem.jsonl・06-kind.jsonlをこの順に検査した結果です。
/root/tp-boundary/08_search.pyを作成して、GET /searchハンドラーを最初から計装してください。shop.parse_query→shop.search_index→結果ごとにshop.hydrate→shop.renderの順に呼び、スパンはルートのGET /search(SERVER)の下に、query.parse(INTERNAL)・index.search(CLIENT)・result.hydrate(INTERNAL)・response.render(INTERNAL)の4つです。繰り返しは畳んで、result.hydrateにresult.hydrate.count・result.hydrate.total_ms・result.hydrate.max_msを属性として付けます。ダンプのデフォルトのパスは/root/tp-boundary/08-search.jsonlで、ステップ7の検査プログラムをこのダンプに対して実行したとき、OKが出る必要があります。

参考

作業ディレクトリは/root/tp-boundaryです。なければ先に作ってください。
計装プログラムは必ず/opt/otel-lab/bin/pythonで実行します。システムのpython3にはOpenTelemetryがありません。ダンプを読んで数える小さなスクリプトは、システムのpython3で十分です。
共通の配線は/opt/app/tracelab/dump.py(provider・flush)、材料は/opt/app/tracelab/tp_boundary/shop.py(計装のない注文処理コード)と/opt/app/tracelab/tp_boundary/gapstat.py(ダンプの読み込み・和集合の計算・tree出力)です。
よくある間違い: ダンプファイルを削除せずにプログラムを再実行してしまいます。ダンプは追記なのでスパンがたまり、トレースが2つになります。
よくある間違い: 空白を「遅い区間」として読んでしまいます。空白はまだスパンがない区間であり、自己時間・クリティカルパスとは別の問いです。
このPodにはコレクターもトレース画面もありません。判定はダンプの構造だけで行い、ミリ秒の絶対値ではなく割合で見ます。
OpenTelemetry: Traces・Tracing API仕様・OpenTelemetry Python計装・ライブラリ計装のガイドライン・W3C Trace Context

スパン1つだけのトレースから始める

/root/tp-boundary/01_root.pyを作成してください。/opt/app/tracelab/dump.pyのproviderでサービス名shop-apiのプロバイダーを作り、ダンプのパスは環境変数TRACELAB_OUTから先に読み、なければ/root/tp-boundary/01-root.jsonlを使います。POST /checkoutという名前のSERVERスパン1つの中で、tracelab.tp_boundary.shopのvalidate→load_cart→price_of(全商品)→charge→write_receiptを順に呼び、最後にflush()を呼びます。そのあと/opt/otel-lab/bin/pythonで実行してダンプを作り、/root/tp-boundary/01-root.txtにspans=とroot_ms=の2行を書いてください(ダンプから読んだ値をそのまま)。

システムのpython3にはOpenTelemetryがありません。計装プログラムは必ずotelの入ったPythonで実行してください。ダンプは追記(append)なので、同じファイルに2回実行するとスパンがたまります。再実行する前に削除してください。ダンプを人の目で見るには、python3 /opt/app/tracelab/tp_boundary/gapstat.py tree <덤프>(プレースホルダーはダンプのパスです)が便利です。

自動計装が提供する2つのスパンだけを入れて空白を測る

/root/tp-boundary/02_split.pyを作成してください。ステップ1と同じですが、データベースの往復であるload_cartをcart.loadスパンで、外へ出ていくchargeをpayment.chargeスパンで包みます(自動計装が代わりに作ってくれる場所がこの2つです)。ダンプのデフォルトのパスは/root/tp-boundary/02-split.jsonlです。実行したあと、/root/tp-boundary/02-gap.txtにroot_ms=・covered_ms=・gap_ms=・gap_ratio=の4行を書いてください。covered_msはルートの子の区間を和集合として足した長さで、gap_ratioは(ルート−覆われた時間)÷ルートを小数第4位まで書きます。

/opt/app/tracelab/tp_boundary/gapstat.pyにload・root_span・children・union_ns・msがあります。和集合にする理由は、子同士が重なりうるからです。重なった区間を2回数えると、覆われた時間が親より長くなってしまいます。このステップで空白が半分近く出るのが正常です。

空白が大きい区間を分けて5%未満に下げる

/root/tp-boundary/03_close.pyを作成してください。ステップ2で残った空白をなくすために、validateはorder.validate、商品の価格を調べる繰り返し全体はprice.lookup、write_receiptはreceipt.writeスパンで包みます。スパン名は、この5つ(order.validate・cart.load・price.lookup・payment.charge・receipt.write)とルートのPOST /checkoutに正確に合わせてください。ダンプのデフォルトのパスは/root/tp-boundary/03-close.jsonlです。実行したあと、/root/tp-boundary/03-gap.txtにステップ2と同じ4行を書き、gap_ratioが0.05未満になるようにしてください。

繰り返し24回を1つのスパンで包むのが核心です。このステップでは、まだ繰り返しごとにスパンを作りません。空白が0になることはありません。スパンを開始して終了すること自体が数マイクロ秒を使うためです。割合で見れば無視できる大きさです。

繰り返しごとにスパンを作ると何個になるか数える

/root/tp-boundary/04_peritem.pyを作成してください。ステップ3と同じですが、price.lookupの中で商品を1つ調べるたびにprice.itemスパンを1つずつ作ります。ダンプのデフォルトのパスは/root/tp-boundary/04-peritem.jsonlです。実行したあと、/root/tp-boundary/04-count.txtにspans_per_request=・item_spans=・spans_per_1000_requests=の3行を書いてください。最後の行は、リクエストあたりのスパン数に1000を掛けた整数です。

3行とも、ダンプから直接数えて埋めます。カートのサイズは/opt/app/tracelab/tp_boundary/shop.pyのCART_SIZEで決まっています。商品が24個でこの程度なら、商品が200個の注文では何個になるか、頭の中で掛け算してみてください。それが次のステップの理由です。

繰り返しをスパンの代わりに属性とイベントで畳む

/root/tp-boundary/05_fold.pyを作成してください。price.itemスパンをなくし、代わりにprice.lookupスパンに3つの属性price.lookup.count(調査回数)・price.lookup.total_ms(合計ミリ秒)・price.lookup.max_ms(最も時間がかかった1件のミリ秒)を付けます。そして、最も時間がかかった商品をprice.lookup.slowestというイベントとして残し、イベントの属性にskuを入れてください。ダンプのデフォルトのパスは/root/tp-boundary/05-fold.jsonlで、全体のスパン数は8個を超えてはいけません。

1件の所要時間はtime.perf_counter()で自分で測ります。平均だけを残すと、24回のうち1回が10倍遅かったという事実が消えてしまいます。そのため最大値を別に残し、それが何だったかは、時点のある記録であるイベントとして書きます。イベントはspan.add_event(이름, {속성})(プレースホルダーはイベント名と属性です)です。

SpanKindで境界を表示する

/root/tp-boundary/06_kind.pyを作成してください。ステップ5と同じですが、すべてのスパンにSpanKindを明示します。入ってきたリクエストはSERVER、プロセスの外へ出ていく呼び出し(cart.load・payment.charge・receipt.write)はCLIENT、プロセス内で分けた区間(order.validate・price.lookup)はINTERNALです。ダンプのデフォルトのパスは/root/tp-boundary/06-kind.jsonlです。実行したあと、/root/tp-boundary/06-kinds.tsvに、スパンごとに1行ずつ<스팬이름><탭><kind>(プレースホルダーはスパン名とタブです)を開始時刻の順に書いてください(ヘッダーなしで6行)。

CLIENTは「自分たちが他者を待った時間」、INTERNALは「自分たちが働いた時間」を、あとで分ける基準になります。データベースの往復もプロセスの外へ出ていく呼び出しなのでCLIENTです。tsvはダンプからそのまま抽出して作れば、手で書いて間違えることがありません。

境界のルールをファイルに書き、検査プログラムを作る

/root/tp-boundary/budget.txtに3行を書いてください: max_spans_per_request=8、max_gap_ratio=0.10、root_kind=SERVER。そして/root/tp-boundary/check_budget.pyを作成してください。python3 check_budget.py <규칙파일> <덤프>(プレースホルダーはルールファイルとダンプです)で呼び出すと、ルールを破ったものごとにVIOLATION <규칙키> <지금 값>(プレースホルダーはルールのキーと現在の値です)を1行ずつ出力して終了コード1、すべて守っていればOKで始まる1行と終了コード0を返します。最後に/root/tp-boundary/07-verdict.tsvに3行を書いてください。各行は<덤프파일이름><탭><pass|fail><탭><깨진 규칙키 또는 ->(プレースホルダーはダンプのファイル名、タブ、破られたルールのキーまたはハイフンです)で、02-split.jsonl・04-peritem.jsonl・06-kind.jsonlをこの順に検査した結果です。

空白の計算は/opt/app/tracelab/tp_boundary/gapstat.pyの関数をそのまま使えば済みます。ルールファイルを別に置く理由は、上限をコードに埋め込んでおくと、レビューのたびに人の好みでまた争うことになるからです。3つのダンプのうち2つは、互いに異なるルールを破ります。どちらが何を破るかを先に予想してから、実行してみてください。

同じルールで2つ目のハンドラーを計装する

/root/tp-boundary/08_search.pyを作成して、GET /searchハンドラーを最初から計装してください。shop.parse_query→shop.search_index→結果ごとにshop.hydrate→shop.renderの順に呼び、スパンはルートのGET /search(SERVER)の下に、query.parse(INTERNAL)・index.search(CLIENT)・result.hydrate(INTERNAL)・response.render(INTERNAL)の4つです。繰り返しは畳んで、result.hydrateにresult.hydrate.count・result.hydrate.total_ms・result.hydrate.max_msを属性として付けます。ダンプのデフォルトのパスは/root/tp-boundary/08-search.jsonlで、ステップ7の検査プログラムをこのダンプに対して実行したとき、OKが出る必要があります。

前の7つのステップで学んだ手順をそのままたどります。プロセス境界ごとにスパンを置き、空白が大きい区間を分け、繰り返しは畳みます。検索結果の個数はshop.pyのSEARCH_HITSで決まっています。検査プログラムがVIOLATIONを出したら、ルールではなく計装のほうを直してください。