障害は「時刻」で追う — タイムスタンプを武器にする4つの読み方

手がかりは14時07分だけ。

ユーザーからの報告はそれだけです。エラーメッセージも、リクエストIDも、再現手順もありません。
手元にあるのは数億行のログと、たった1つの時刻。ここから何分で現場に立てますか？

障害調査で最初に手に入る情報は、たいてい「いつ」です。しかも時刻は、ログのほぼ全行が持っている数少ない共通の属性でもあります。時刻は検索語ではなく、座標として使える — この記事はそこから始めます。

以下、時刻を武器にする4つの読み方を順に並べます。1分間へ飛ぶ・サーバ間のズレを吸収する・間隔の疎密を見る・1人ぶんを時系列に並べる。どれも grep と awk で一応は進みますが、4つとも同じ3つの操作で止まります。

先に結論: UwView Pro なら、258.68GB・45億行のファイルでも開いた瞬間からスクロールでき、2回目以降は行番号付きで開いてその時刻の行へ直接飛べます（実測は環境により異なります。詳細は記事末尾）

1. 「14時07分」しか分からないとき、数億行からその1分へ飛ぶ

状況

冒頭の14時07分を具体的にします。ログは1日ぶんで数億行、ファイルサイズは数十GB。時刻は行頭にあり、当然ながら昇順に並んでいます。

見たいのは 14:07 の前後だけです。全体の0.001%にも満たない範囲。それだけを見るために、いま何をしていますか。

なぜ起きるか

ログは時刻で完全にソートされているのに、テキストファイルには「時刻から位置へ」の索引がないからです。

ソート済みのデータに対する検索は、本来なら二分探索が使えます。数億行でも30回ほどの比較で目的の行に着くはずです。ところがテキストファイルには行の境界がどこにあるかの情報がなく、N行目の先頭バイトがどこかは、先頭から数えないと分からない。この一点だけで、二分探索という最良の道具が使えなくなります。

さらに厄介なのは、探したい時刻の文字列が、そのままの形でログに書かれているとは限らないことです。14:07:33 は書かれていても 14:07 ちょうどの行はないかもしれない。秒が飛んでいる（その秒に何も起きていない）のはログでは普通のことです。「その時刻の行」ではなく「その時刻を跨ぐ位置」を探したい、というのが実際の要求です。

汎用ツールでの対処と限界

素朴には grep です。

grep -n '14:07:' app.log | head        # その分のヒットを行番号つきで
sed -n '/14:07:00/,/14:09:00/p' app.log   # 時刻範囲で切り出す
awk '$0 >= "2026-09-01 14:05" && $0 <= "2026-09-01 14:10"' app.log

3本目は、行頭が YYYY-MM-DD HH:MM:SS で始まる形式なら文字列比較がそのまま時刻比較になるという定石です。パースが要らず、フォーマットが揃っている限り確実に効きます。

もう少し賢くやるなら、ソート済みであることを利用します。

# 行数を数えて、当たりを付けた位置を覗く（二分探索を手でやる）
wc -l app.log
sed -n '148000000p;148000001p' app.log

これは実際に効きます。数回繰り返せば目的の分に着きます。

限界は3つ。ひとつめ、上のどれも、原本を頭から読み直すことです。grep も sed -n '範囲p' も awk も、目的の行がファイルの何%の位置にあろうと、そこまでの全バイトを走査します。数十GBなら1回あたり数十秒。「時刻が分かっている」という最大の手がかりを、まったく使えていません。

ふたつめ、wc -l による手動二分探索は、その wc -l 自体が全読みだということです。しかも sed -n 'Np' も先頭から数え直すので、1回覗くたびに全読みが1回増えます。原理的には最良の方法なのに、実行コストで負けます。

みっつめ、着いたあとに動けないことです。sed で切り出した範囲を眺めていて「もう1分前も見たい」と思ったら、範囲を書き直してもう一度全読み。障害調査で見る範囲が一発で決まることは、まずありません。

2. サーバ間で時計がずれている — 突き合わせの前にやること

状況

Webサーバのログでは 14:07:12 にリクエストが来ています。APIサーバのログでは、対応するはずの処理が 14:07:09 に始まっています。呼ばれる前に始まっている。

これはタイムトラベルではなく、ほぼ確実に時計のズレです。ではズレは何秒で、どちらが進んでいるのでしょうか。

なぜ起きるか

時刻はサーバごとに独立して刻まれていて、揃っている保証がないからです。

NTPで同期していても、秒未満のズレは常にあります。同期が外れていれば秒単位、仮想マシンやコンテナのホストが高負荷だったならもっと大きくズレます。しかもズレは一定ではありません。NTPが階段状に補正すれば、その瞬間の前後で関係が変わります。

日本の現場でよくあるのはもうひとつ、タイムゾーンの混在です。アプリのログはJST、コンテナのログはUTC、ミドルウェアのログは +0900 付き。9時間の差は明らかなので気づきますが、片方だけがUTCの状態で「9時間ずれてるから足しておこう」と機械的に補正すると、DSTのない日本では気づかない別の間違いを埋め込みます（たとえばログローテーションの境界が1日ずれる）。

そして本質はここです。突き合わせで知りたいのは絶対時刻ではなく、どちらが先に起きたかという順序です。ズレが3秒あるとき、「3秒以内の出来事の前後関係」は原理的に決められません。決められるのは、ズレの大きさより十分に離れた出来事の順序だけです。

汎用ツールでの対処と限界

まずズレの量を測ります。両方のログに現れる「同じ1つの出来事」を探すのが定石です。

# 両側に必ず出る相関キー（リクエストID）で、同じ処理の時刻を比べる
grep 'req-8f21ac' web.log api.log
# デプロイ・起動メッセージなど、確実に同時刻の出来事で較正する
grep -h 'application started' web.log api.log

ズレが分かったら、片方を寄せてマージします。

# APIログの時刻に +3 秒して、Webログと1本の時系列にする
awk '{ ... 時刻を秒に直して +3 して書き戻す ... }' api.log > api.shifted.log
sort -m -k1,2 web.log api.shifted.log | less

これは正しい手順です。そしてこの手順そのものが、3つの問題を連れてきます。

ひとつめ、補正した瞬間に原本ではなくなることです。api.shifted.log の第4,120,338行は、api.log の何行目でしょうか。行の追加や欠落がなければ同じはずですが、それを保証するのは自分の注意力だけです。障害報告書に「APIサーバのログ 4,120,338行目」と書くとき、その番号は加工物の行番号です。フォレンジックの原則から言えば、第4回で触れた「原本に触らない」がここで崩れます。

ふたつめ、ズレの推定値を変えるたびに全部やり直しになることです。「3秒だと思ったが、較正に使った出来事が悪かった。2.4秒かもしれない」——数十GBを読んで書き直し、またマージ。しかもマージ済みファイルは原本の倍のディスクを食います。

みっつめ、マージは「1本にする」操作だということです。1本になると、どの行がどちらのサーバ由来か分からなくなります。本当にやりたかったのは2つを左右に並べて、同じ時間帯を同時に追うことでした。この形は第6回のDHCPログ突き合わせでも同じで、突き合わせの本質は並置であって合成ではないようです。

補足として、正直に書いておきます。ズレが数秒あるログの順序を、後から完全に復元する方法はありません。可能なのは「ズレの幅を見積もり、その幅より小さい差の順序は主張しない」という運用だけです。障害報告書に「同時刻（±3秒の時計差の範囲内）」と書ける勇気のほうが、無理に並べた1本の時系列より正確です。

3. 兆候は行の中身ではなく「間隔」に出る

状況

サービスが数日おきに重くなります。エラーは出ていません。ログの中身は正常そのもので、grep ERROR は何も返しません。

メモリリークやコネクションリークの初期は、エラーではなく遅さとして現れます。そして遅さは、ログの行と行の間隔に出ます。

なぜ起きるか

異常が「書かれている内容」ではなく「書かれた時刻の分布」に現れるからです。

たとえば1分ごとのヘルスチェックログを考えます。正常なら60秒間隔で並びます。GCが伸び始めると61秒、63秒、67秒……と間隔が伸びていき、あるところで急に60秒に戻ります（再起動）。この形は、1行だけ見ても絶対に分かりません。ログの中身はどの行も health check ok です。

同じことは逆向きにも起きます。リトライの嵐が始まると、間隔が異常に詰まります。1秒に数百行が同じ文言で並ぶ。これも1行では正常です。

つまり見たいのは、行の集合ではなく行の並び方の変化です。しかもこの変化は「どこかで始まる」ものなので、どこから見ればいいのかが事前には分かりません。全体をざっと眺めて、変わった場所へ寄っていくという見方が要ります。

汎用ツールでの対処と限界

差分を計算するのは awk の得意分野です。

# 直前の行との時刻差を出して、大きいものだけ見る
awk '{ "date -d\""$1" "$2"\" +%s" | getline t; if (p) d=t-p; p=t; if (d>90) print d, $0 }' app.log

# 分あたりの件数を数えて、密度の変化を見る
awk '{print substr($2,1,5)}' app.log | uniq -c | head -100

2本目の「分ごとの件数」は実務でよく効きます。密度がそのまま数字で出るので、リトライの嵐は一目です。

限界は3つ。ひとつめ、この2本は、どちらも数億行を1行ずつ処理することです。1本目は行ごとに date を呼ぶので論外に遅く（実務ではフォーマットを決め打ちして自前で秒に直します）、2本目でも数十GBなら数分かかります。しきい値の90を試しに120にしてみたい、と思うたびに数分です。

ふたつめ、数字の列になった瞬間に文脈が消えることです。「14:07台だけ件数が3倍」と分かっても、その3倍の中身が何かは分かりません。原本に戻って 14:07 を探し直すことになり、それは第1章の全読みです。

みっつめ、そして本質的な問題として、「疎密を見る」は本来グラフか目でやる作業だということです。しきい値を決めて超えたものを出す、というやり方は、しきい値が正しいときにしか機能しません。障害調査で最初にやりたいのは「どこが変か知らないので、全体の形を見る」ことです。数値化は形を見たあとの仕事であって、その逆ではありません。

4. 数千万件から、特定ユーザーの全リクエストを時系列に並べる

状況

「このアカウントで9月1日に何をしたか、全部出してください」。問い合わせ対応でも、不正調査でも、監査でも出る要求です。

APIのレスポンスログは1日で数千万件。1人ぶんは数十件から数千件。求められているのはその人の行動の物語であって、ヒット行の羅列ではありません。

なぜ起きるか

1人ぶんの行動が、時系列の中に薄く広く散らばっているからです。

数千万件の中の数百件は、割合にして0.001%です。そして重要なのは、その数百件が連続していないことです。他人のリクエストに挟まれて、ファイル全体に散っています。

さらに、1人が複数の識別子を持ちます。ユーザーID、セッションID、APIキー、デバイスID、送信元IP。ログの種類ごとに書かれている識別子が違い、「同じ人」であることを繋ぐのは人間の仕事です。セッションIDはログイン直後の行にしか出ないので、そこを見つけてから改めて探し直す、という段取りになります。

そして最後に、時系列に並べたあと、まだ絞りたくなることです。全リクエストを出したら数千件あった。エラーになったものだけ見たい。そのうちPOSTだけ見たい。この絞り込みは、出してみるまで何が必要か分かりません。

汎用ツールでの対処と限界

順当に進めるとこうなります。

grep 'user_id=U8842' api.log > u8842.log            # 1人ぶんを抜く
grep -o 'session=[a-f0-9]*' u8842.log | sort -u     # その人のセッションIDを回収
grep -E 'user_id=U8842|session=(a1b2|c3d4)' api.log | sort -k1,2 | less   # 識別子を足して抜き直す
grep 'status=5' u8842.log | grep 'POST'             # 出したあとの絞り込み

この流れ自体は正しく、実際これで仕事は終わります。

限界は3つ。ひとつめ、識別子を1つ足すたびに原本へ戻ることです。3本目で session= を足した時点で、また数十GBの全読みです。そして識別子は、たいてい調査の途中で増えます。

ふたつめ、中間ファイルが行番号を持っていないことです。u8842.log の第310行が原本の何行目かは書かれていません。「この失敗の直前に、他の誰かが何をしていたか」を見たくなった瞬間 — これは競合やロック待ちの調査では必ず出ます — 中間ファイルは無力です。そこには本人の行しかないからです。原本の該当行に戻る必要があるのに、戻り方が失われています。

みっつめ、4本目の絞り込みが積み重なることです。grep | grep | grep と足していくと、何件から何件に減ったのかが分かりません。第6回で書いた「段ごとの件数が残らない」問題が、ここでも同じ形で出ます。

4つに共通していたもの

4つとも、詰まっているのは解析の手法ではありません。3列目を見ると、要求されている操作は3つに収まります。

• 時刻を手がかりに、原本の中の位置へ直接飛ぶ — 時刻はほぼ全行が持つ唯一のソート済みキーです。それを座標として使えれば、数億行でも「見る範囲」は数百行で済みます。
• 複数の原本を、混ぜずに同じ時間帯へ合わせる — 突き合わせの本質は並置です。1本にマージした時点で、どちらの原本の話なのかが失われます。
• 行の中身ではなく、行の並び方を見る — 間隔・密度・順序。異常はしばしば、書かれた内容ではなく書かれ方に出ます。

3つとも、小さいファイルなら誰でも当たり前にやっていることです。エディタで日時を検索して飛び、ウィンドウを2つ並べ、スクロールして「このへんだけ行が詰まってるな」と気づく。それが数十GBになった途端、飛ぶために全読みを要求され、並べるために加工を要求され、眺めるために数分待たされる。

そしてこれは、連載で繰り返し出てきた形です。第1回の「開くのに全読みを要求する」、第2回の「一覧と現場の往復」、第5回の「正規化した瞬間に戻れなくなる」。操作が難しいのではなく、大きさのせいで割に合わなくなる — 時刻という最も強い手がかりを持っていてさえ、そうです。

冒頭の「14時07分だけ」に戻ります。手がかりが1つしかないのは、実は悪い状況ではありません。時刻はログの中で最も信頼できる索引だからです。問題は、その索引を索引として使わせてくれない道具のほうにあります。

使っている道具

私が開発している UwView（無料）は、この「大きいと時刻を手がかりにできなくなる」前提を外すために作ったビューアです。数十GBのログでも開いた瞬間から全体を表示・スクロール・検索でき、索引はバックグラウンドで作られて、完成すると行番号が付きます。ファイルの真ん中あたりへ一気にスクロールして、そこに書かれている時刻を見て当たりを付ける——第1章で wc -l と sed -n 'Np' を往復していた手動二分探索が、スクロールバーの操作で済みます。

第3章の「間隔の疎密」も、まず眺めるところから始められます。時刻の分の桁を色分けハイライトしてスクロールすれば、密度の変化は色の縞の粗さとして目に入ります（色分けハイライトの使い方）。ハイライトは行を消さずに色を付けるだけなので、正常な行も視界に残ります。複数ファイルを同時に開けるので、第2章の「並置」もマージなしで成立します。そして原本には書き込みません。

そのうえで、上に並べた3つの操作を強化するのが UwView Pro です。

• 索引と圧縮を保存する: 一度開いたログは、2回目以降は行番号付きで瞬時に開けます。障害調査は同じログを何度も開き直す作業なので、ここが効きます。行番号があれば「4,120,338行目へ」の移動が原本を読み直さずに済み、第1章の「着いたあと動けない」が消えます。
• 多段階検索（ドリルダウン）: 検索結果をさらに別の語で絞り込みます。第4章の user_id → status=5 → POST が、タブに 語（件数） を並べながら進みます。何件から何件に減ったかが段ごとに見えるので、効いた条件がその場で分かります。2段目以降は前段の範囲だけが対象なので待ちがありません。→ 多段階検索の記事
• シーケンシャル検索: w1 → w2 → w3 がこの順で現れる箇所だけを拾います。第2章の「どちらが先に起きたか」を、時刻の大小ではなくファイル内の出現順で確かめる用途に使えます。ただし各段は前段の位置を開始点に本文を検索するため、所要時間は全文検索とほぼ同じです（ドリルダウンの「2段目以降は即時」とはここが違います）。→ シーケンシャル検索の記事

そして、ストレージを専有している巨大ログを圧縮して保管し、さらに高速に検索したいなら Pro の圧縮キャッシュ検索と約1/9保管が効きます。開き直しも検索も一段速くなります（全OS対応・買い切り／月額プランあり）。なお無料版で使えるのは1段検索・±1文脈・結果の保存までで、多段階検索・シーケンシャル検索・可変の±N・索引の保存は Pro の機能です。

正直に書いておくと、UwView は時刻を解釈しません。行頭の文字列が日時であることを知らないので、「14:07から14:09まで」という時刻範囲の指定はできず、サーバ間のズレを自動で補正することもしません。できるのは、時刻の文字列を検索し、その位置へ飛び、色を付け、2本を並べて見ることまでです。時刻を構造として扱いたいなら、それはログ基盤やSIEMの仕事です。UwView が担うのは、その前段——取り込む前の生ログを、そのままの形で人間が見るところです。

リンク

• 第1回: 巨大ファイルに沈む4つの定番ツールと、その先: https://uvp.y42u.net/blog/uwview-ps01-huge-file-tool-limits/
• 第2回: ログの因果を遡る4つの技法: https://uvp.y42u.net/blog/uwview-ps02-log-causality-tracing/
• 第3回: 文字コード4つの罠と切り分け手順: https://uvp.y42u.net/blog/uwview-ps03-japanese-encoding-traps/
• 第4回: 消す・残す・圧縮するの判断基準: https://uvp.y42u.net/blog/uwview-ps04-log-retention-decision/
• 第5回: 開発ログとの正しい付き合い方4選: https://uvp.y42u.net/blog/uwview-ps05-debug-log-practices/
• 第6回: 認証ログ数千万行から痕跡を拾う4手順: https://uvp.y42u.net/blog/uwview-ps06-intrusion-triage-auth-logs/
• 多段階検索（ドリルダウン）— 9万件を2回の絞り込みで54件に: https://uvp.y42u.net/blog/uvp-drilldown-search/
• シーケンシャル検索 — 「この順で現れる場所」だけを探す: https://uvp.y42u.net/blog/uvp-sequence-search/
• nginxアクセスログの5xxを追う: https://uvp.y42u.net/blog/uwview-access-log-5xx-workflow/
• 色分けハイライトの使い方: https://uvp.y42u.net/blog/uwview-v11-color-highlighter/
• ソースコード（GitHub）: https://github.com/amru195704/UwView

開発者より: アプリ・Kindle本・オープンソースの一覧は GitHub: amru195704 にまとめています。

お願い
本記事の情報は参考目的で掲載しており、正確性・完全性を保証するものではありません。ログの形式・フィールド位置・時刻表記は、OS・ミドルウェア・設定により大きく異なります。コマンド例は環境（GNU/BSD、シェル、awk の実装、date コマンドのオプション、ログのフィールド構成等）により調整が必要です。時刻の同期状態やタイムゾーン設定はシステムごとに異なるため、突き合わせの前にご自身の環境で確認してください。ユーザーID・セッションIDはすべて架空の例示です。誤記・不正確な情報がございましたら、コメント欄よりご指摘いただければ、確認のうえ修正いたします。