ログと分散トレースによる性能分析
一要求のログとspanを対応させ、重なった処理時間を二重に加算せず、記録から分かる範囲を説明します。
説明
メトリクスは件数や時間の傾向を集計し、ログは個々の出来事を記録します。トレースでは、一要求の中の処理をspanとして記録し、親子関係と開始・終了時刻をたどります。集計で異常を見つけ、同じ要求の記録へ絞る流れを学びます。
固定の要求記録3件を使います。応答は120ms・600ms・200msで、最後の要求は500です。集計、trace_idによる抽出、処理の重なり、下流へ渡すHTTPヘッダーを順に調べます。時刻は各要求の開始を0とした相対値です。
一要求のログとspanを対応させ、重なった処理時間を二重に加算せず、記録から分かる範囲を説明します。
1件数と応答時間の分布
集計対象は要求全体を表すroot spanです。子spanまで件数へ含めると、一要求を何回も数えてしまいます。
python3 observe.py metrics要求単位で件数と時間を集計する要求は3、エラーは1、エラー率は33.33%です。生の3件を昇順に並べ、ceil(0.95×3)番目を取る方法ではp95は600msです。bucketは上限以下の累積件数なので、200以下の2件は500以下の2件にも含まれます。
2識別子を外したログの限界
比較のため、trace_idとspan_idを表示せずに出来事を並べます。
python3 observe.py logs --omit-trace要求と処理の識別子を表示から除く同じ名前のrequest.startやdb.completeが繰り返されます。時刻は要求ごとの相対値なので、この表示だけでは別要求の時刻を比較できません。要求をまたいで記録を結び付ける識別子が必要です。
3遅い要求のログだけを取り出す
trace_idが2の32文字反復である要求を選びます。--trace 2は、その固定IDを指定する短縮引数です。
python3 observe.py logs --trace 2600msかかった要求に絞る同じtrace_idの開始、DB完了、応答完了が残ります。DBは500ms、要求全体は600msです。span_idが異なるため、要求全体の記録とDB処理の記録も対応させられます。
4親子関係と開始・終了時刻
同じ要求のspanを表示します。parentは親spanのIDです。
python3 observe.py spans処理ごとの時間と親IDを表示する --trace 2rootの下にDBとprofileがあります。DBは50〜550ms、profileは100〜300msで、両者は重なっています。名前だけでなく、開始・終了と親IDを使って処理の関係を確認します。
5下流へ引き継ぐヘッダー
root spanから下流へ要求を渡す場合のtraceparentを組み立て、各フィールドを表示します。
python3 observe.py header引継ぎ用traceparentと各フィールドを表示する --trace 200は版、次の32桁はtrace-id、その次の16桁は送信側spanを表すparent-id、最後の01はsampledフラグです。下流のspanは同じtrace-idを引き継ぎ、送信側を親として記録します。sampledは、全記録が必ず収集される保証ではありません。
6重なりを含む時間を計算
子spanの単純合計と、重複区間を一度だけ数える時間を計算します。
python3 observe.py overlap子spanの区間を統合して時間を計算する --trace 2単純合計は500+200=700msですが、profileはDBの区間に収まるため、子spanが覆う時間は500msです。rootの残り100msは子spanに記録されていない時間であり、CPU処理だけの時間とは断定できません。
7失敗した要求の記録へ絞る
500を返したtrace_idが3の要求を調べます。
python3 observe.py logs --trace 3失敗した要求の出来事を読む
python3 observe.py spans --trace 3失敗した処理と要求全体を対応させるDBの記録にDB_TIMEOUTがあり、そのspanは20〜180ms、要求全体は200msで500です。DB待機の失敗が記録されていますが、待機が長くなった原因はSQL・ロック・負荷などの追加記録が必要です。
8速い要求の時間配置も確認
120msで完了した要求のspanを表示します。
python3 observe.py spans --trace 1120msの要求の処理区間を読む
python3 observe.py overlap --trace 1重なりのない場合の時間を計算するDBは60ms、profileは30msで重ならず、子spanの合計と統合時間は90msです。全体との差は30ms。同じ種類の処理でも配置と時間は変わるため、集計値だけで一要求の原因を決めつけないようにします。
まとめ
メトリクスで傾向を確認し、trace_idで一要求のログとspanへ絞ります。
spanの時間には重なりがあるため、単純合計が要求全体より長くなることがあります。
記録された失敗箇所と、その原因を説明する証拠は分けて確認します。
操作履歴と解説を振り返れます。
シェル / Python 3
python3 observe.py metricsrequests=3 errors=1 error_rate=33.33% p95_raw_ms=600 duration_bucket_le_100=0 duration_bucket_le_200=2 duration_bucket_le_500=2 duration_bucket_le_inf=3
python3 observe.py logs --omit-trace{"at_ms": 0, "event": "request.start", "route": "/orders"}
{"at_ms": 70, "duration_ms": 60, "event": "db.complete"}
{"at_ms": 120, "event": "request.end", "status": 200}
{"at_ms": 0, "event": "request.start", "route": "/orders"}
{"at_ms": 550, "duration_ms": 500, "event": "db.complete"}
{"at_ms": 600, "event": "request.end", "status": 200}
{"at_ms": 0, "event": "request.start", "route": "/orders"}
{"at_ms": 180, "duration_ms": 160, "event": "DB_TIMEOUT"}
{"at_ms": 200, "event": "request.end", "status": 500}python3 observe.py logs --trace 2{"at_ms": 0, "event": "request.start", "route": "/orders", "span_id": "0000000000000001", "trace_id": "22222222222222222222222222222222"}
{"at_ms": 550, "duration_ms": 500, "event": "db.complete", "span_id": "0000000000000002", "trace_id": "22222222222222222222222222222222"}
{"at_ms": 600, "event": "request.end", "span_id": "0000000000000001", "status": 200, "trace_id": "22222222222222222222222222222222"}python3 observe.py spans --trace 2span=0000000000000001 parent=None name=GET /orders start=0 end=600 duration=600 status=200 span=0000000000000002 parent=0000000000000001 name=db.query start=50 end=550 duration=500 status=ok span=0000000000000003 parent=0000000000000001 name=profile.fetch start=100 end=300 duration=200 status=ok
python3 observe.py header --trace 2traceparent=00-22222222222222222222222222222222-0000000000000001-01 version=00 trace_id=22222222222222222222222222222222 parent_id=0000000000000001 sampled=1
python3 observe.py overlap --trace 2root_ms=600 sum_children_ms=700 union_children_ms=500 outside_child_spans_ms=100
python3 observe.py logs --trace 3
python3 observe.py spans --trace 3{"at_ms": 0, "event": "request.start", "route": "/orders", "span_id": "0000000000000001", "trace_id": "33333333333333333333333333333333"}
{"at_ms": 180, "duration_ms": 160, "event": "DB_TIMEOUT", "span_id": "0000000000000002", "trace_id": "33333333333333333333333333333333"}
{"at_ms": 200, "event": "request.end", "span_id": "0000000000000001", "status": 500, "trace_id": "33333333333333333333333333333333"}
span=0000000000000001 parent=None name=GET /orders start=0 end=200 duration=200 status=500
span=0000000000000002 parent=0000000000000001 name=db.query start=20 end=180 duration=160 status=errorpython3 observe.py spans --trace 1
python3 observe.py overlap --trace 1span=0000000000000001 parent=None name=GET /orders start=0 end=120 duration=120 status=200 span=0000000000000002 parent=0000000000000001 name=db.query start=10 end=70 duration=60 status=ok span=0000000000000003 parent=0000000000000001 name=profile.fetch start=75 end=105 duration=30 status=ok root_ms=120 sum_children_ms=90 union_children_ms=90 outside_child_spans_ms=30
演習完了