3分を見るために一日分を読まない

一言でいうと

時間順に積み上がったログでは、読まずに探せます。時刻の表記が統一されていれば、文字列の比較がそのまま時間の比較なので、ファイルをバイト単位で二分探索して区間の開始位置を先に特定し、その後ろだけを読めば済みます。

なぜ必要なのか

障害の振り返りで最もよく出る依頼は、「事故が起きた3分だけを見せてください」です。ところが、手が先にすることは、たいていgrep '03:5[89]' app.logで、その1行がファイル全体を先頭から最後まで読みます。ファイルが1日分で数GBなら、この1回でディスク帯域とメモリを使い切り、分析しようとしたPodのほうが先に止まります。ラボのPodでさえ、メモリ2Giに一時ディスク6Giです。

さらに悪いのは、この方式が間違った答えも返すことです。区間がローテーションの境界にまたがっていると、app.logだけを見た結果は半分です。事故の前半はすでにapp.log.1に移っていて、それより前はapp.log.2.gzの中に圧縮されています。1つのファイルだけを見て「その時刻には何も起きていなかった」と書く振り返りは、ここから生まれます。

どう動くのか

前提は1つです。ファイルが時間順で、時刻の表記が統一されていること。RFC 3339の5.1節が、この性質を明記しています。日付と時刻の構成要素が、精度の低いものから高いものの順に並び、タイムゾーンがすべて同じ文字列で書かれ(たとえば全部Z)、小数の桁数がすべて同じなら、その文字列をCのstrcmpでソートしても時間順になると書かれています。そのため、2026-04-12T03:58:30.000Zの2つを比べることは、時刻2つを比べることと同じです。この前提が成り立っているかは、sort(1)の-c(ソート済みかどうかだけを検査し、ソートはしません)で、先に確認できます。

前提が成り立てば、二分探索が可能になります。ファイルサイズを半分に折って、そのバイトにseekし、行の真ん中に落ちているはずなので、1行を読み捨てて行の境界に立ち、その行の時刻を区間の開始と比較します。小さければ後ろ半分、大きいか等しければ前半分へと、範囲を絞ります。20MBのファイルなら、20数回で終わります。

ここで2つを正確にする必要があります。1つ目、区間は半開区間[시작, 끝)(プレースホルダーは開始と終了です)で取ります。そうすれば、続く区間を並べて取り出しても、境界の行が2度数えられません。2つ目、同じ時刻の行が複数あるとき、二分探索が見つけるべきものは、その時刻の最初の行です。毎秒数十行が積み上がるサービスで、同じミリ秒に複数の行があるのは、例外ではなく普通で、どれか1行を見つけてその後ろだけを読むと、前の数行が黙って抜けます。「条件を満たすどれかの行」ではなく「条件を最初に満たす行」を見つけるように書く必要があります。

ローテーションされたファイルは、先に時間順に並べます。番号を付ける基本方式では、数字が大きいほど過去で、拡張子のないファイルが今書いているものです。logrotate(8)のdateextを有効にすると、名前が日付になりますが(デフォルトのdateformatは-%Y%m%d、hourlyは-%Y%m%d%H)、そのときは名前が小さいほど過去なので、方向が逆になります。同じmanページが、日付形式は必ず辞書順にソートできなければならないと明記していますが、その理由がおもしろいです。logrotate自身が、どのファイルが古いのかを見つけるために、ローテーションされたファイル名をソートするからです。名前のソートが時間のソートになるようにすることは、ファイルの中でもファイル名でも、同じコツです。

圧縮ファイルだけは、事情が違います。gzipストリームは、前の内容に頼って展開されるので、任意の地点へ飛べません。Pythonのgzipモジュールが返すファイルオブジェクトは、seekを受け付けはしますが、後ろへ戻ると、圧縮ストリームを最初から読み直します(自分で測ると、元のバイトを読み込み直しているのが見えます)。そのため、圧縮ファイルに二分探索をかけると、同じ場所を何度も展開し直すことになります。答えは単純です。先頭から1回だけ走査し、区間の終わりを過ぎた瞬間に止まります。区間がファイルの前のほうにあるほど、この節約が大きくなります。

1行が完結したレコードであるJSON Lines形式なら、これらすべてがそのまま通用します。行単位で切ったバイト区間が、それ自体で有効なドキュメントだからです。1つの巨大なJSON配列は、途中を切り出せません。

現場での姿

前提が崩れると、二分探索は黙って間違えます。複数のプロセスが1つのファイルに書くと、行の順序がわずかにずれ、収集器が遅れて届いた行を後ろに追記することもあります。そのようなファイルでは、二分探索はエラーを出さず、ただ数行を取りこぼします。そのため、新しいファイルを初めて扱うときは、ソート済みかどうかを先に確認し、ずれていれば二分探索をあきらめるか、ずれの幅の分だけ区間を広げて取ります。

「速かった」は証明ではありません。速い方法を導入するときに、必ず一緒にすることは、遅い方法との突き合わせです。全体を走査して同じ区間を取り出し、行数とハッシュを比べて同じかを見ます。この突き合わせは、一度だけ行えばよく、その一度がなければ、境界で行が抜けても誰も気づきません。

次のラボですること

ローテーションまで済んだ6時間分のログを作り、ファイルごとに含まれる区間を測って、古いものから並べます。事故の区間と重ならないファイルは、そもそも開かず、残ったファイルでは、二分探索で開始バイトと終了バイトを特定して、その間だけを読みます。圧縮ファイルには同じ手法を使えないので、先頭から走査して、早めに止まります。最後に、まるごと走査する遅い方法と突き合わせて、結果が同じであることを証明し、方法と根拠を報告書として残します。