TT Lab
はじめる
学ぶ 学習パス コース

分散トレーシングが切れる場所

サーバーは20ミリ秒と言うが我々が測ると300ミリ秒

TT Labで続きを見る

目標

同じ呼び出しをクライアントとサーバーの両側で測って差を分解し、コネクションプールの待機をスパンの境界の中に入れ、切断された呼び出しとキャンセルされた呼び出しを区別して残し、宛先を識別する属性を低カーディナリティで設計して、そのルールを2つ目のクライアントにそのまま適用します。

なぜ重要なのか

下流チームのp99と自分たちのp99が違うのは、誰かが間違っているからではなく、異なる区間を測っているからです。サーバーはハンドラーが開いていた時間を測り、その前後には待ち行列・シリアライズ・送信があります。さらに悪いのがコネクションプールの待機です。接続を得たあとでスパンを開始すると、その待機はどのスパンにも入らず、子をすべて足してもルートが説明できないトレースができます。タイムアウトはペアをずらします。クライアントが諦めてもサーバーは最後まで働くので、同じトレースに短いCLIENTスパンと長いSERVERスパンが一緒に残り、その形がそのままリソースが漏れているというサインです。逆に、ユーザーが離脱して生じたキャンセルをエラーに上げると、エラー率がユーザーの行動に応じて上下します。最後に、外へ出ていく呼び出しの宛先をアドレスのまま書くと、IDやPod名が属性の値に混ざり、集計が不可能になります。

ステップ

  1. /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に<클라이언트 밀리초>、<서버 밀리초>、<차이>(プレースホルダーは順に、クライアントのミリ秒、サーバーのミリ秒、差です)をタブで区切って1行書いてください。小数第3位までです。
  2. /root/tp-client/gap.pyを作成して、同じ呼び出しを20回行ってください(作業量は30ミリ秒)。デフォルトのダンプのパスは/root/tp-client/gap.jsonl、サーバーのダンプは同じディレクトリのgap-server.jsonlです。呼び出しごとにCLIENTスパンPOST /priceに3つの属性を付けます。gap.ms(クライアントの時間からサーバーの時間を引いたもの)、gap.queue_ms(レスポンスが知らせてきた待ち行列時間)、gap.rest_ms(2つの差)です。ダンプと同じディレクトリのgap.tsvに<번호>と<gap.ms>(1つ目のプレースホルダーは番号です)を20行、gap-summary.txtにmedian_gap_ms=(20個の値の中央値)とreason=(差が何でできているかを100文字以上)を書いてください。
  3. /root/tp-client/pooled.pyを作成して、同じことを2回行ってください。デフォルトのダンプのパスは/root/tp-client/pooled.jsonl、サーバーのダンプは同じディレクトリのpooled-server.jsonlです。2回とも、サイズ1のConnPoolを新しく作り、スレッド3つが同時にbe.call("GET /stock", 80, carrier)を呼びます。1つ目のセットは、プールで枠を得たあとにCLIENTスパンnarrowを開き、2つ目のセットは、CLIENTスパンwideを先に開いたあとで枠を得ながら、属性pool.wait_msとイベントpool.acquiredを残します。ダンプと同じディレクトリのpool.tsvに、narrow・wideの2行で、各セットで最も長く開いていたスパンのミリ秒を書いてください。
  4. /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()し、2つのダンプを読み直して、同じtrace_idを持つペアを探し、ダンプと同じディレクトリのorphan.tsvに<trace_id>、<클라이언트 밀리초>、<서버 밀리초>、<판정>(プレースホルダーは順に、trace ID、クライアントのミリ秒、サーバーのミリ秒、判定です)をタブで区切って1行書きます。判定は、サーバー側のほうが長ければclient-gave-up、そうでなければserver-finished-firstです。
  5. /root/tp-client/cancel.pyを作成して、2つのことを残してください。デフォルトのダンプのパスは/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=(なぜ2つを別々に残すのかを100文字以上)の3行を書いてください。
  6. /root/tp-client/target.pyを作成して、/opt/app/tracelab/tp_client/plan.jsonのcardinalityの呼び出し8件を送ってください。デフォルトのダンプのパスは/root/tp-client/target.jsonl、サーバーのダンプは同じディレクトリのtarget-server.jsonlです。CLIENTスパン名は<target>/<op>で、属性を4つ付けます。rpc.service(target)、rpc.method(op)、server.address(target)、url.template(pathから注文IDだけをplan.jsonのplaceholderに置き換えたもの)です。アドレスのhostと注文IDは、属性の値に入れません。ダンプと同じディレクトリのcardinality.tsvに、4つの属性の名前と異なる値の個数を、属性名の辞書順にタブで区切って4行書いてください。
  7. /root/tp-client/repeat.pyを作成して、/opt/app/tracelab/tp_client/plan.jsonのcheckoutの呼び出し7件を、SERVERスパンPOST /checkout1つの下で送ってください。デフォルトのダンプのパスは/root/tp-client/repeat.jsonl、サーバーのダンプは同じディレクトリのrepeat-server.jsonlです。ルートスパンに属性rpc.client.callsとして、出ていった呼び出し数を書き、CLIENTスパンごとにステップ6と同じ4つの属性を付けます。ダンプと同じディレクトリのrepeat.tsvに、<server.address>、<rpc.method>、<호출 수>、<걸린 시간 합(정수 밀리초)>(プレースホルダーは順に、アドレス、メソッド、呼び出し数、かかった時間の合計(整数ミリ秒)です)を、呼び出し数が多いものから、タブで区切って書いてください。呼び出し数が同じなら、アドレスの辞書順です。
  8. まず/root/tp-client/client-policy.jsonに、これまでの判断を書いてください。span_kind、boundary(プール待機がスパンの中か外か)、required_attributes(ステップ6の4つの属性)、forbidden_value_sources(属性の値として使ってはいけない材料のフィールド名)、timeout_status、cancel_statusです。そのあと/root/tp-client/second.pyを作成して、そのファイルを読み、/opt/app/tracelab/tp_client/plan.jsonのsearchの呼び出し4件を2つ目のクライアントとして送ります。デフォルトのダンプのパスは/root/tp-client/second.jsonl、サーバーのダンプは同じディレクトリのsecond-server.jsonlで、サイズ1のConnPoolを使って、待った時間をスパンの中のpool.wait_msとして残します。ダンプと同じディレクトリのsecond.tsvに、<rpc.method>、<호출 수>、<서로 다른 server.address 수>(プレースホルダーは順に、メソッド、呼び出し数、異なるserver.addressの数です)を、操作名の辞書順に3つの欄ずつ書いてください。

参考

同じ呼び出しを両側で測る

/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に<클라이언트 밀리초>、<서버 밀리초>、<차이>(プレースホルダーは順に、クライアントのミリ秒、サーバーのミリ秒、差です)をタブで区切って1行書いてください。小数第3位までです。

Backend.callが返すdictのserver_msが、サーバースパンが開いていた時間です。クライアントの時間は、呼び出しの前後をtime.perf_counter()で測れば済みます。ヘッダーをスパンの中で注入して初めて、サーバースパンがこのスパンの子になります。最後にbe.close()を呼んでからflush()してください。

その差は何でできているか

/root/tp-client/gap.pyを作成して、同じ呼び出しを20回行ってください(作業量は30ミリ秒)。デフォルトのダンプのパスは/root/tp-client/gap.jsonl、サーバーのダンプは同じディレクトリのgap-server.jsonlです。呼び出しごとにCLIENTスパンPOST /priceに3つの属性を付けます。gap.ms(クライアントの時間からサーバーの時間を引いたもの)、gap.queue_ms(レスポンスが知らせてきた待ち行列時間)、gap.rest_ms(2つの差)です。ダンプと同じディレクトリのgap.tsvに<번호>と<gap.ms>(1つ目のプレースホルダーは番号です)を20行、gap-summary.txtにmedian_gap_ms=(20個の値の中央値)とreason=(差が何でできているかを100文字以上)を書いてください。

Backend.callのレスポンスdictには、server_msのほかにqueue_msもあります。リクエストが到着してからハンドラーが確保されるまでの時間で、サーバースパンの外です。本物のサービスなら、この値はレスポンスヘッダーで戻ってきます。中央値は、20個の値を並べ替えて、真ん中の2つを平均すれば求められます。

コネクションプールで待った時間をスパンの中に入れる

/root/tp-client/pooled.pyを作成して、同じことを2回行ってください。デフォルトのダンプのパスは/root/tp-client/pooled.jsonl、サーバーのダンプは同じディレクトリのpooled-server.jsonlです。2回とも、サイズ1のConnPoolを新しく作り、スレッド3つが同時にbe.call("GET /stock", 80, carrier)を呼びます。1つ目のセットは、プールで枠を得たあとにCLIENTスパンnarrowを開き、2つ目のセットは、CLIENTスパンwideを先に開いたあとで枠を得ながら、属性pool.wait_msとイベントpool.acquiredを残します。ダンプと同じディレクトリのpool.tsvに、narrow・wideの2行で、各セットで最も長く開いていたスパンのミリ秒を書いてください。

ConnPool.lease()は、待ったミリ秒をyieldします。with pool.lease() as waited:です。2つのセットの違いは、コード2行の順序だけですが、トレースではまったく違って見えます。プールを2つのセットで共有すると結果が混ざるので、セットごとに新しく作ってください。スレッドは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()し、2つのダンプを読み直して、同じtrace_idを持つペアを探し、ダンプと同じディレクトリのorphan.tsvに<trace_id>、<클라이언트 밀리초>、<서버 밀리초>、<판정>(プレースホルダーは順に、trace ID、クライアントのミリ秒、サーバーのミリ秒、判定です)をタブで区切って1行書きます。判定は、サーバー側のほうが長ければclient-gave-up、そうでなければserver-finished-firstです。

Backend.callのタイムアウトは、concurrent.futures.TimeoutErrorとして上がってきます。be.close()を呼ばずにflush()すると、サーバースパンがダンプに残らず、ペアを探せません。ダンプはJSON1行ずつなので、json.loadsでそのまま読めます。2つのスパンの長さの差が、このステップの要点です。

キャンセルされた呼び出しを、エラーとは別に残す

/root/tp-client/cancel.pyを作成して、2つのことを残してください。デフォルトのダンプのパスは/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=(なぜ2つを別々に残すのかを100文字以上)の3行を書いてください。

ステータスに触れなかったスパンは、ダンプにUNSETとして残ります。2つのステータスの値は、ダンプを開いて確認してからファイルに書いてください。作り話を書くと、ダンプと食い違います。例外はfrom tracelab.tp_client.backend import BackendErrorで捕捉します。

宛先を識別する属性を低カーディナリティで決める

/root/tp-client/target.pyを作成して、/opt/app/tracelab/tp_client/plan.jsonのcardinalityの呼び出し8件を送ってください。デフォルトのダンプのパスは/root/tp-client/target.jsonl、サーバーのダンプは同じディレクトリのtarget-server.jsonlです。CLIENTスパン名は<target>/<op>で、属性を4つ付けます。rpc.service(target)、rpc.method(op)、server.address(target)、url.template(pathから注文IDだけをplan.jsonのplaceholderに置き換えたもの)です。アドレスのhostと注文IDは、属性の値に入れません。ダンプと同じディレクトリのcardinality.tsvに、4つの属性の名前と異なる値の個数を、属性名の辞書順にタブで区切って4行書いてください。

plan.jsonのlimitsが、各属性が持てる値の種類数を教えてくれます。hostにはPodのサフィックスが、pathには注文IDが入っているため、そのまま入れると呼び出しごとに値が変わります。宛先が2つなので、Backendも宛先ごとに1つずつ作って再利用してください。

同じ宛先を何度も呼んだことを、クライアント側で明らかにする

/root/tp-client/repeat.pyを作成して、/opt/app/tracelab/tp_client/plan.jsonのcheckoutの呼び出し7件を、SERVERスパンPOST /checkout1つの下で送ってください。デフォルトのダンプのパスは/root/tp-client/repeat.jsonl、サーバーのダンプは同じディレクトリのrepeat-server.jsonlです。ルートスパンに属性rpc.client.callsとして、出ていった呼び出し数を書き、CLIENTスパンごとにステップ6と同じ4つの属性を付けます。ダンプと同じディレクトリのrepeat.tsvに、<server.address>、<rpc.method>、<호출 수>、<걸린 시간 합(정수 밀리초)>(プレースホルダーは順に、アドレス、メソッド、呼び出し数、かかった時間の合計(整数ミリ秒)です)を、呼び出し数が多いものから、タブで区切って書いてください。呼び出し数が同じなら、アドレスの辞書順です。

まとめるキーは、宛先と操作の2つです。そのため、低カーディナリティの属性が必要でした。ルートスパン1つに呼び出し数を書いておけば、子を開いて見なくても、ファンアウトが大きいリクエストをふるい分けられます。時間の合計は、各CLIENT呼び出しを包んだ区間を足して、丸めた整数です。

ルールをファイルに書き、2つ目のクライアントに適用する

まず/root/tp-client/client-policy.jsonに、これまでの判断を書いてください。span_kind、boundary(プール待機がスパンの中か外か)、required_attributes(ステップ6の4つの属性)、forbidden_value_sources(属性の値として使ってはいけない材料のフィールド名)、timeout_status、cancel_statusです。そのあと/root/tp-client/second.pyを作成して、そのファイルを読み、/opt/app/tracelab/tp_client/plan.jsonのsearchの呼び出し4件を2つ目のクライアントとして送ります。デフォルトのダンプのパスは/root/tp-client/second.jsonl、サーバーのダンプは同じディレクトリのsecond-server.jsonlで、サイズ1のConnPoolを使って、待った時間をスパンの中のpool.wait_msとして残します。ダンプと同じディレクトリのsecond.tsvに、<rpc.method>、<호출 수>、<서로 다른 server.address 수>(プレースホルダーは順に、メソッド、呼び出し数、異なるserver.addressの数です)を、操作名の辞書順に3つの欄ずつ書いてください。

属性名をプログラムに書き直さず、ルールファイルのrequired_attributesを回しながら付けてください。それが「ルールを適用する」という言葉の意味です。forbidden_value_sourcesには、plan.jsonからそのまま使ってはいけないフィールド名を書きます。2つのステータスは、ステップ4・5でダンプから確認した値です。