ログを全部残すと何も見つからない

一言でいうと

ログは、行単位で値が決まるのではありません。リクエスト単位で残るか消えるかが調査できるかどうかを決め、レベルとサンプリング率は、その上に載せるコストのノブです。

なぜ必要なのか

SRE Bookのトラブルシューティングの章が述べる調査の最初の段階は、症状を残したリクエストを見つけ出すことですが、障害調査中にこんなことが起きます。失敗したリクエストのrequest_idはわかりました。ログストレージにそのIDを入れると、2行が出てきます。「request started」と「request failed」です。その間に何があったかは出てきません。先月のコスト会議のあとで、DEBUGを切ったからです。

反対の状況も、同じくらい悪いものです。DEBUGを再び有効にしたチームは、1か月後にストレージ料金が4倍になり、検索が遅くなって調査に使えなくなりました。次に手軽な選択が、「10%だけ残そう」でした。ところがサンプルを行単位で選んだところ、同じリクエストの半分だけが残って、どのリクエストも最後まで読めなくなりました。コストは減りましたが、調査できる可能性は0になりました。

3回とも、同じ間違いをしています。ログの単位を行と見ていることです。人が調査するときに読む単位は行ではなく、1つのリクエストが残した行のまとまりです。

どう動くのか

そのため、サンプルはリクエスト単位で選びます。request_idをハッシュしてNで割った余りが0のリクエストだけを残すと、1つのリクエストの行は、まるごと残るかまるごと消えるかのどちらかです。これを一貫したヘッドサンプリング(consistent head sampling)と呼びます。ハッシュはPython標準ライブラリのhashlibだけで十分です。ハッシュの役割は1つです。同じIDに対して、いつどこで計算しても同じ答えを返すことです。そのため、複数のサービスが同じルールを使えば、1つのリクエストの流れがサービスの境界を越えてもつながります。

ここにルールをもう1つ載せます。エラーで終わったリクエストは、サンプリング率に関係なくすべて残します。調査する価値のあるリクエストはたいてい失敗したリクエストで、そうしたリクエストは全体の数パーセントにすぎないので、保持してもコストはほとんど増えません。サンプリング率10%とエラーの保持を併用すると、行数は9.6%から14.3%へとわずかに増える代わりに、失敗したリクエストの保持率が0%から100%に上がります。コストに対する効果がこれより大きいノブは、めったにありません。

残る2つのノブは、繰り返しを扱うものです。リトライループにはまったコードは、同じ行を1秒に何百回も出力します。連続する同じ行を1つに折りたたんでrepeated=<k>を付ければ、情報を失わずに量だけ減らせます。それでも残るなら、1秒あたりの上限をかけます。ただし上限はDEBUGにだけかけなければなりません。上限に引っかかってERRORが消えると、コストは減っても調査は不可能になります。

ノブ	減らすもの	失うもの
レベルを下げる	量の大部分	失敗したリクエストの流れ全体
リクエスト単位のサンプリング	量に比例	サンプルに選ばれなかったリクエストのすべて
エラーの保持	増える(わずか)	なし
繰り返しの折りたたみ	リトライループの量	なし(回数は残します)
1秒あたりの上限	急増した区間	上限を超えた行

ポリシー文書には、これらのノブと一緒に、レベルごとの保持期間を書きます。DEBUGを90日保管する理由はほとんどなく、ERRORを3日しか保管しなければ、四半期の振り返りで何も見つかりません。レベルを1つの保持期間にまとめると、どちらかになります。DEBUGに合わせてERRORを失うか、ERRORに合わせてDEBUGの料金を何倍にも払うかです。

これらのノブがすべて動くには、前提が1つあります。行にrequest_idがなければなりません。OpenTelemetryのログデータモデルが、trace_idとspan_idをログレコードの第一級フィールドとして置いている理由がこれです。IDのないログは、リクエスト単位でまとめることも、リクエスト単位でサンプルを選ぶこともできず、結局、行単位で切るしかありません。コスト削減の半分は、計装の段階ですでに決まっています。

現場での姿

あるチームは、サンプリング率を1%に下げて「コストを99%削減した」と報告しました。3か月後の決済失敗の調査で、関連するリクエストがログに1つもありませんでした。エラーを保持するルールがなかったからです。ルールを入れるとコストは1.3%に上がり、失敗したリクエストはすべて残りました。1.3%と1%の差で買えたものが、「調査できること」でした。

別のチームでは、1秒あたりの上限をレベルの区別なしにかけました。普段は何の問題もなかったのに、本物の障害が起きて1秒に数千行があふれ出したその瞬間に上限に引っかかり、ERROR行が切り落とされました。最も必要な時刻のログだけがありませんでした。上限は普段ではなく、最悪の瞬間に働くということを忘れた設計でした。

3つ目の事例は、折りたたみについてです。リトライループにはまったバッチジョブが1日に4億行を出力し、その行は1文字も違いませんでした。連続する行の折りたたみを1つ入れると、その4億行が2万行に減り、repeated=の数字のおかげで、「何回リトライしたか」という質問にはそれでも答えられました。捨てることと要約することは、別のことです。

次のラボですること

Podにあらかじめ入っている固定のログファイルで、レベルごとのコスト表を作り、DEBUGを切ったときに、事故の起きたリクエストの9行のうち何行が残るかを自分で数えます。そのあと、request_idのハッシュでリクエスト単位のサンプルを選ぶフィルターを作り、エラーで終わったリクエストを保持するルールを加えて、サンプリング率と調査可能性のトレードオフを表にします。繰り返しを折りたたみ、1秒あたりの上限をかけるフィルターをもう1つ作ったあと、2つのフィルターをつなげたパイプラインで、88%を削減しながらも、その9行がすべて残ることを確認し、最後にレベル・サンプリング率・保持期間・予想コストをまとめたポリシーファイルを書きます。