平常値を知らなければ急増も分からない

一言でいうと

ログから数字を1つ取り出したとき、それが悪い値かどうかは、平常値を知っていて初めて判定できます。

なぜ必要なのか

「エラーが103件あります」は、情報ではありません。平常が5件なら深刻で、平常が120件ならむしろ良くなっています。今のレスポンス時間が200ミリ秒だという事実だけでは、良いか悪いかわかりません。平常が40ミリ秒なら深刻で、220ミリ秒なら何でもありません。

そのため、ログ分析の最初のステップは、原因探しではなくベースライン作りです。そして、不慣れな顧客企業ではベースラインがドキュメントとして存在しないので、同じログの中で作る必要があります。事故の時刻を除いた残りの区間が、そのまま平常値です。

どう動くのか

アクセスログを初めて開いたときの順序は、次のとおりです。

1. 全体の規模を測る。何行あるか、どの区間を覆っているか。6時間分のログで昨日の午後の出来事を探しているなら、そのログには最初から答えがありません。

2. ステータスコードの分布を見る。200が何件、4xxが何件、5xxが何件。ここで、4xxと5xxを必ず分けて見ます。4xxはクライアントが誤って送ったもの、5xxはサーバーが壊れたものなので、2つの数字が一緒に動くのか、別々に動くのかが、そのまま原因の方向です。デプロイ後に4xxだけが増えたなら、APIの契約が変わったのであり、5xxだけが増えたなら、内部が壊れたのです。

3. 時間軸で切る。5xxを分単位で数えてみます。均等に広がっていれば慢性的な問題で、1点に集中していれば事故です。この区別が、対応をまったく変えます。集中しているなら、その時刻に何があったかを尋ねるだけで、調査が終わることもあります。

4. パスごとに切る。エラーが特定のエンドポイントに集中しているのか、全体に広がっているのか。集中していればその機能の問題で、広がっていれば共通の依存先(データベース、認証、ネットワーク)の問題です。

5. ベースラインを引く。事故の区間を除いた残りのエラー数を数えます。この数字があって初めて、「平常は33件だったものが、1分で70件になった」という文を書けて、その文が報告書の1行目になります。

現場での姿

ここで、実務の感覚を1つ加えます。平均にだまされないでください。

レスポンス時間の平均が1380ミリ秒だからといって、ユーザーが平均的に1.4秒待ったわけではありません。340件のうち240件が260ミリ秒以下で、70件が3秒を超える状況でも、平均はその値になります。平均は、存在しないユーザーを描き出します。

そして、この歪みは一方向にしか働きません。平均は、テールが悪くなることをほとんど検知できません。遅いリクエスト100件が3秒から6秒へ2倍悪くなっても、全体の平均は30ミリ秒ほど上がるだけで、その程度ではどのアラートのしきい値も超えません。

そのため、顧客が「たまに数秒止まる」と言っているのに、ダッシュボードの平均は正常だという状況は、矛盾ではありません。どちらも真で、互いに違うものを見ているだけです。

ログが答えを持っていないとき

調査を進めていると、ログ自体が信頼できない場合に出会います。これを知らずに掘り続けると、ない答えを何時間も探すことになるので、先に確認すべきことがあります。

欠落。ログがバッファーに溜まってから送信される構造だと、プロセスが強制終了されるとき、最後の数秒がまるごと消えます。ところが、障害の決定的な瞬間が、まさにその数秒です。「死ぬ直前のログがない」ということは、手がかりがないという意味ではなく、異常終了だったという強い手がかりです。正常終了だったなら、終了処理のログが残っていたはずだからです。

切り詰め。収集器が1行の長さを制限することがよくあります。長いスタックトレースやJSONの本文が途中で切れ、そのあとに続く行が別の項目として扱われます。パースする側からは形式が壊れた行に見えて、黙って捨てられます。エラー件数を数えたのに実際より少なく出る原因の1つが、これです。

時刻。複数の機器のログを合わせるとき、時計がずれていると、因果がひっくり返って見えます。結果が原因より先に記録されたように見えたら、奇妙な仮説を立てるのではなく、時計を疑うべきです。そして、タイムゾーンが混ざると、9時間分の錯覚が生まれます。ログの時刻はUTCで残し、表示するときだけ変換することが、この問題をなくす唯一の方法です。

サンプリング。トラフィックが多いサービスは、ログをすべて残さず、一部だけを記録することもあります。このとき、「そのユーザーのリクエストがログにない」ということは、リクエストがなかったという意味ではありません。サンプリング比率を知らないまま件数を数えても、その数字には何の意味もありません。

まとめると、ログを開く前に、4つを先に確認します。どの区間を覆っているか、どこまで無事か、時計は合っているか、全部か一部か。この確認にかかる数分が、ない答えを探す数時間を防いでくれます。そして、確認した結果、ログが答えを持っていないなら、それを報告書にそのまま書くほうが、推測を書くよりはるかに価値があります。次回何をさらに残すべきかが、その一文から出てくるからです。

次のラボですること

1269行のWebアクセスログから、エラーの総量と事故の時刻と原因のパスを見つけ出し、最後に平常値を別に計算して、急増の幅を数字にします。