10GBを、朝に見つけました。
寝る前にループへ入れた printf 1行の出力です。中身のほとんどは「正常に回っていた」という同じ形の行。
その何行目に、壊れた瞬間があるのでしょうか？
デバッガで止まらないバグを追うとき、私たちは結局ログを吐きます。そして、吐きすぎます。運用のログと違い、開発中のログには保持期間もローテーションも設計もありません。困ったから足す、直ったら消す（つもり）、消し忘れる。
この記事では、開発の現場で起きる4つの場面を並べます。出力が肥大する・再現に時間がかかる・スレッドが混線する・正常時と壊れた後を見比べる。どれも手持ちの道具で一応は対処できます。そのうえで、その手がどこで止まるかまで踏み込みます。詰まる場所は4つとも同じ一点でした。
1. printfデバッグの出力が10GBになった — 消す前に読む
状況
冒頭の10GBを、もう少し具体的に見ます。入れたのは1行だけです。ループの中で状態を出力する printf（あるいは console.log、Log.d）。再現待ちのあいだ放置し、朝には8,400万行を超えていました。
行の形はほぼ1種類。そのうち、読む価値があるのは数十行あるかどうかです。
なぜ起きるか
デバッグ出力の量は、バグの複雑さではなく実行回数に比例するからです。
これは避けようがありません。どこで壊れるか分からないから出力を入れているのであって、分かっているなら最初から条件を付けています。「何が起きているか分からない」という状態と「絞り込めない」という状態は同じことなので、分からないうちは全部出すしかない。結果として、必要な情報の密度は限りなく低くなります。10GB のうち役に立つのが数KB、というのは誇張ではありません。
さらに悪いことに、この10GBは捨てられません。再現に手間がかかったなら、なおさらです。もう一度同じ条件を作れる保証がない以上、読み終わるまでは消せない。
汎用ツールでの対処と限界
まず全体の形を見ます。
wc -l debug.log # まず行数
awk '{print $3}' debug.log | sort | uniq -c | sort -rn | head # 出力種別の分布
grep -n 'state=BROKEN' debug.log | head # 異常っぽい行の位置
sed -n '84213900,84213960p' debug.log # その周辺だけ抜く
grep -n で位置を取り、sed -n で前後を抜く。この2段構えは強力で、たいていの調査はここで足ります。
限界は2つあります。ひとつめ、「異常っぽい行」の見当が付いていることが前提です。state=BROKEN のような分かりやすい印を自分で仕込んでいたなら勝ちですが、そういう印を仕込めるくらい分かっているなら、そもそもこのログは要りません。実際には「正常な行の形が、あるところから微妙に変わっている」ことに気づく必要があり、それは目で流し読みしないと分からない種類の発見です。
ふたつめ、その流し読みが 10GB では成立しないことです。エディタは開けず、less は開きますが行番号が出ないので「いま全体のどのへんか」が分かりません。第1回で見た、道具が沈む場所とまったく同じ壁です。
2. 再現に3時間かかるバグ — 毎回最初から読み直さない
状況
そのバグは、負荷をかけて3時間ほど回さないと出ません。運よく再現しました。ログを開いて調べ、その日は「ここまでは分かった」で終わります。
翌日、続きを調べようとログを開きます。索引が作られるのを待ちます。昨日たどり着いた行を探し直します。昨日使っていた検索条件を思い出します。それだけで午前が終わります。
なぜ起きるか
調査の状態が、ツールの外に置かれているからです。
再現に3時間かかるバグの調査は、必然的に複数日にまたがります。ところが多くのビューアやエディタは、閉じた瞬間に「どこを見ていたか」「何で絞り込んでいたか」を捨てます。残るのはファイルだけなので、翌日はファイルを開くところからやり直しになります。
しかも開き直しのコストは、ファイルが大きいほど大きくなります。8GBのログを開くのに2分かかるなら、1日に5回開き直せば10分。それ自体は小さく見えますが、効くのはむしろ「開き直したくないから開かない」という心理のほうです。ちょっと確認したいだけの仮説を、開くのが面倒だからという理由で試さなくなる。調査の質が、道具の待ち時間に削られます。
汎用ツールでの対処と限界
状態を外に書き出せば、ある程度は引き継げます。
grep -n 'txId=8842' huge.log > findings/txid8842.txt # 見つけた位置を保存
sed -n '12000000,12000500p' huge.log > findings/window.log # 作業窓を切り出す
調査メモに行番号を書き残すのも効きます。「84,213,912 行目から異常」と書いておけば、翌日は sed で飛べます。
限界は、切り出した瞬間に文脈が切れることです。findings/window.log は500行ぶんの世界しか持っていないので、「もう2000行前も見たい」と思った時点で原本に戻ります。戻ると、また開き直しです。
そして根本的な問題として、行番号は原本と結びついた情報なのに、その原本を開くコストが毎回かかるという循環があります。メモに 84213912 と書いてあっても、そこへ飛ぶには8GBのファイルを開く必要がある。「メモを取れば済む」という話ではないのは、このためです。
3. マルチスレッドのログが混線して読めない
状況
16スレッドで並列処理をしているアプリのログです。時系列順に並んではいますが、1行ごとに違うスレッドの発言が混ざっています。1つのスレッドの物語を追おうとすると、目が数行おきに飛びます。
12:04:31.220 [w-07] fetch start id=8841
12:04:31.221 [w-03] parse done id=8830
12:04:31.221 [w-11] fetch start id=8842
12:04:31.223 [w-07] fetch done id=8841
10分読んで、自分がどのスレッドを追っていたか分からなくなります。
なぜ起きるか
ログの並び順（時刻順）と、読みたい順（スレッド順）が一致していないからです。
これは設計のミスではありません。時刻順に書くのは正しく、それ以外に書きようがありません。しかしデバッグで知りたいのはたいてい「w-07 に何が起きたか」という縦の物語であり、ファイルは横の断面で並んでいます。この直交が、読みにくさの正体です。
厄介なのは、混線しているログでしか分からないバグがあることです。デッドロックや競合状態は、まさに「複数スレッドの時間関係」そのものが原因なので、スレッドごとに分離してしまうと見えなくなります。つまり、分けて読みたいのに、分けきってはいけない。
汎用ツールでの対処と限界
抽出は簡単です。
grep '\[w-07\]' app.log | less # 1本だけ抜く
grep -E '\[w-(07|11)\]' app.log # 2本を時刻順のまま
awk '{print $2}' app.log | sort | uniq -c | sort -rn # どのスレッドが多いか
grep --color=always -E '\[w-07\]|\[w-11\]|$' app.log | less -R # 色を付ける
最後の grep --color に空マッチ |$ を足す小技は、該当行だけを残さずに、該当行を目立たせるために効きます。文脈を保ったまま色だけ付けたいときの定番です。
限界は3つ。ひとつめ、less -R に流し込むと元の行番号が失われます。「この行はファイルの何行目か」が分からないので、後で戻れません。ふたつめ、色分けの種類が増えると grep の式が手に負えなくなります。16スレッドを16色に、は現実的ではありません。みっつめ、絞り込みと全体表示を行き来するたびにコマンドを打ち直すことです。「w-07 だけ見る → やっぱり全体で前後を見る → もう一度 w-07 だけ」という往復は、調査中に何十回も起きます。1回1回が数秒でも、思考は毎回中断されます。
4. 「動いていた頃」と「壊れた後」を並べて差分を見る
状況
先週まで正常に動いていました。今週から失敗します。両方のログが手元にあります。同じ処理の、同じ箇所を突き合わせれば、違いが見えるはずです。
そう思って diff にかけると、出力は数百万行になります。タイムスタンプもリクエストIDもスレッド名も毎回違うので、全行が「差分」として検出されるからです。
なぜ起きるか
行単位の差分は、行の中の「変わって当然の部分」を区別できないからです。
diff はテキスト比較の道具であって、ログの構造を知りません。人間は 12:04:31.220 [w-07] fetch start id=8841 を見たときに、時刻とスレッド名とIDは「毎回違う場所」、fetch start は「意味のある場所」と無意識に分けています。diff にはその区別がないので、全部を等しく差分として扱います。
そして本当に見たいのは、行の差分ではなくシーケンスの差分です。「正常時は fetch → parse → commit の順に出ていたのに、壊れた後は parse が抜けている」「retry が3回まで増えている」。つまり比べたいのは出来事の並び方であって、文字列ではありません。
汎用ツールでの対処と限界
変動部分を潰してから比べる、が定石です。
sed -E 's/^[0-9:.]+ //; s/id=[0-9]+/id=N/g; s/\[w-[0-9]+\]/[w]/' good.log > good.norm
sed -E 's/^[0-9:.]+ //; s/id=[0-9]+/id=N/g; s/\[w-[0-9]+\]/[w]/' bad.log > bad.norm
diff <(sort good.norm | uniq -c) <(sort bad.norm | uniq -c) # 出現回数の差で見る
行の骨格だけ残して回数を比べると、「このメッセージが正常時は0回、異常時は4,120回」といった形で差が浮きます。これはかなり効きます。
限界は2つ。ひとつめ、正規化した瞬間に原本の行番号が消えることです。「retry が増えている」と分かっても、bad.log の何行目で増え始めたのかは分かりません。結局、原本に戻って grep -n からやり直します。
ふたつめ、回数の比較は順序を捨てていることです。上の sort | uniq -c は集合として比べているので、「順番が入れ替わった」タイプの異常は検出できません。順序を見るには、結局2つのファイルを同時に開いて、同じ場所を並べて目で追う必要があります。ところがログが数GBずつあると、この「2本同時に開く」がまず成立しません。
4つに共通していたもの
| 場面 | 現れ方 | 止まる場所 |
|---|---|---|
| printf出力が10GBになった | 有用な密度が極端に低い | 流し読みできる道具がない |
| 再現に3時間かかる | 翌日また開き直しから | 調査の状態がツールの外にある |
| スレッドが混線している | 縦の物語が横に切られている | 絞り込みと全体の往復コスト |
| 正常時と異常時を比べる | diffが全行差分になる | 正規化すると行番号が消える |
4つとも、詰まっているのは「解析の方法」ではありません。必要な操作が、ファイルの大きさのせいで割に合わなくなるという一点です。
流し読みも、開き直しも、絞り込みと全体の往復も、2本を並べて見ることも、小さいファイルでなら誰でも当たり前にやっていることです。それが数GBになった途端、1回あたり数十秒〜数分の代償を要求されるようになり、人はその操作をやめます。やめた結果として調査が浅くなるので、道具の待ち時間が、そのままバグの発見率を下げています。
そしてこれは、この連載で何度も出てきた形でもあります。第1回の「開くのに全読みを要求する」、第2回の「一覧と現場の往復」、第3回の「解釈を切り替えるたびの読み直し」、第4回の「小さく置くと読めなくなる」。開発ログは寿命が短いぶん軽く見られがちですが、詰まり方は運用ログとまったく同じでした。
使っている道具
私が開発している UwView（無料）は、この「大きいと操作が割に合わなくなる」前提を外すために作ったビューアです。10GBのデバッグログでも開いた瞬間から全体を表示・スクロール・検索でき、索引はバックグラウンドで作られて、完成すると行番号が付きます。流し読みで異常の形に気づく、という第1章の作業がそのままできます。色分けのハイライトは行を捨てずに付くので、第3章のように文脈を保ったままスレッドを目で追えます。原本には書き込みません。
そして、再現に時間のかかるバグを数日かけて追うとき、あるいは正常時と異常時のログを並べて見るときは、UwView Pro をどうぞ。索引と圧縮を保存するので、2回目以降は行番号付きで瞬時に開けます（翌日の「開き直しから始まる午前」がなくなります）。圧縮キャッシュ経由の検索と約1/9保管も付くので、消せない再現ログを抱えたままでもディスクが楽になります（全OS対応・買い切り／月額プランあり）。
なお、開けることと書き換えられることは別の話です。デバッグ用に大量の行を削って整形したい、といった編集用途は現在別途開発中で、こちらの比較記事で途中経過を書いています。
リンク
- 第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/
- 色分けハイライトの使い方: https://uvp.y42u.net/blog/uwview-v11-color-highlighter/
- 実測（3サイズ・条件つき）: https://uvp.y42u.net/blog/uwview-pro-benchmark-3sizes/
- ソースコード（GitHub）: https://github.com/amru195704/UwView
開発者より: アプリ・Kindle本・オープンソースの一覧は GitHub: amru195704 にまとめています。
お願い
本記事の情報は参考目的で掲載しており、正確性・完全性を保証するものではありません。ログの出力量・再現時間・開くまでの待ち時間は、言語・実行環境・ストレージ構成により大きく異なります。コマンド例は環境（GNU/BSD、シェル、sed・awkの実装等）により調整が必要な場合があります。誤記・不正確な情報がございましたら、コメント欄よりご指摘いただければ、確認のうえ修正いたします。
