log.info("user logged in")は無料に見える。しかしそれは違う。この1行の背後には、バッファするかどうか、フラッシュするかどうか、ブロックするかドロップするか、同じスレッドか別スレッドかといった一連の決定があり、それぞれがレイテンシ、スループット、耐久性をトレードオフしている。この記事では、メソッド呼び出しからディスクプラッタにバイトが書き込まれるまで、その全チェーンを解説する。
もし p99 レイテンシに謎のスパイクがある理由、クラッシュ後にログが消える理由、あるいは「非同期ロギング」が実際に何を提供するのか疑問に思ったことがあるなら、この記事はあなたのためのものです。
まず地図から：ファサード vs 実装
Java のロギングは二層構造であり、この二層を混同することが混乱の最大の原因です。
ファサードはコードが呼び出す API です。実装は実際にバイトを書き込む部分です。
your code
│ log.info(...)
▼
┌───────────────────────────────┐
│ Facade: SLF4J (or Log4j2 API)│ ← コンパイル対象のインターフェース
└──────────────┬────────────────┘
│ ランタイムでバインド
┌───────────┼────────────┬──────────────┐
▼ ▼ ▼ ▼
Logback Log4j2 Core java.util.logging ...
(the engine that buffers, formats, and flushes)
Enter fullscreen mode Exit fullscreen mode
- SLF4J — デファクトスタンダードのファサード。アプリケーションはこれに対してログを記録すべきです。
- Logback — SLF4J のリファレンス実装。堅実で広く展開されています。
- Log4j2 — パフォーマンス重視の実装で、ロックフリーの非同期ロガーで有名です。
- java.util.logging (JUL) — JDK に組み込まれていますが、意図的に選ばれることは稀です。
なぜ分離されているのか？log. の呼び出しに一切触れずにエンジンを交換できるようにするためです。この記事で興味深いこと — バッファリング、フラッシング、非同期マジック — はすべて実装層で起こります。
単一のログ呼び出しの解剖
フラッシングについて語る前に、log.info(...) が実際に何をするのかを見てみましょう。5つのステージがあります：
1. Level check → INFO がこのロガーで有効か？（安価で、しばしば最も早い bail-out）
2. Build LogEvent → メッセージ、タイムスタンプ、スレッド、MDC コンテキスト、場合によってはスタックトレースをキャプチャ
3. Filter → 設定されたフィルタを実行
4. Layout / encode → イベントをバイトに変換（"2026-07-28 12:00:01 INFO ..."）
5. Append → それらのバイトを宛先（ファイル、コンソール、ソケット）に書き込む
Enter fullscreen mode Exit fullscreen mode
ステージ 5 — append — が同期 vs 非同期、フラッシュ vs ノーフラッシュが存在する場所です。また、ディスクに触れる可能性があるため、はるかに最も高価なステージでもあります。
すでにプロのヒント： ステージ 1 が、
if (log.isDebugEnabled())を見る理由です。レベルがオフのときにステージ 2–5 をスキップします。現代のパラメータ化されたロギング（log.debug("x={}", x)）では、フレームワークが文字列を構築する前にこのチェックを行います — したがってlog.debug("x=" + x)が本当のアンチパターンです。文字列の連結はレベルチェックに関係なく実行されるからです。
同期ロギング：デフォルトとその2つの隠れたレイヤー
「同期」とは、append がアプリケーションスレッド上で起こることを意味します。あなたのスレッドは書き込みが完了するまで log.info(...) から戻りません。シンプルで予測可能 — そしてすべてのフラッシュのニュアンスが存在する場所です。
ほとんどの人が見逃す微妙さ：ログステートメントと実際のディスクの間には2つの別々のバッファがあることです。
your app thread
│ writes formatted bytes
▼
┌─────────────────────┐
│ App-level buffer │ ← アペンダー内の BufferedOutputStream
│ (e.g. 4 KB) │ flush() がこれを空にする
└──────────┬──────────┘
│ flush()
▼
┌─────────────────────┐
│ OS page cache │ ← カーネルのコピー、まだ RAM 内
│ (kernel memory) │ fsync() がこれを空にする
└──────────┬──────────┘
│ fsync()
▼
┌─────────────────────┐
│ Physical disk │ ← これで電源喪失後も残る
└─────────────────────┘
Enter fullscreen mode Exit fullscreen mode
2つの異なる操作が2つの異なるバッファを空にし、人々は常にそれらを混同します：
-
flush()はアプリケーションバッファからOS ページキャッシュへバイトをプッシュします。フラッシュ後、別のプロセス（tail -fなど）がログ行を見ることができます。しかしそれはまだ RAM 内にあります — カーネルパニックや電源喪失で失われます。 -
fsync()（FileChannel.force()を介して）は OS にページキャッシュを物理ストレージに書き込ませます。これが実際にログ行をクラッシュから生き残らせるものであり、劇的に遅いです。 ほとんどのロギングフレームワークは最初のバッファにノブを提供し、デフォルトでは実質的に2番目に触れません。それが平然と隠れている耐久性のトレードオフです。 ###immediateFlush：最も重要なノブ Logback と Log4j2 の両方のファイルアペンダーはimmediateFlushを公開しています： Logback:
<appender name="FILE" class="ch.qos.logback.core.FileAppender">
<file>app.log</file>
<immediateFlush>true</immediateFlush> <!-- default: true -->
<encoder>
<pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
</encoder>
</appender>
Enter fullscreen mode Exit fullscreen mode
Log4j2:
<File name="FILE" fileName="app.log" immediateFlush="true">
<PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
</File>
Enter fullscreen mode Exit fullscreen mode
これがするもの：
-
immediateFlush=true（デフォルト）：すべてのログイベント後にflush()を呼び出します。呼び出しが戻った瞬間にあなたの行は OS キャッシュにあります。JVM がクラッシュした場合でも安全です（OS はバイトを保持しており、それらを書き込みます）。しかしそれはログ行ごとに syscall を意味します — 負荷下でのスループットキラーです。 -
immediateFlush=false：BufferedOutputStreamが（通常 8 KB）いっぱいになるまで待機し、いっぱいになったときのみフラッシュします。syscall が大幅に少なくなり、スループットがはるかに高くなります。コスト：JVM が死んだ場合、アプリケーションバッファに残っているもの（最大 8 KB の最近の、最も興味深いログ）は失われます。 それが1文で表した同期フラッシュの根本的なトレードオフです：安全のために行ごとにフラッシュするか、速度のためにバッファリングするか。
注：Log4j2 は非同期ロガーのために自動的に
immediateFlush=falseの動作を強制します — 非同期の世界では、耐久性の修正は異なるからです（以下で詳しく説明）。
では同期ロギングはクラッシュから生き残るのか？
どのクラッシュとどのフラッシュ設定によるかによります：
| 障害 | immediateFlush=true |
immediateFlush=false |
fsync あり |
|---|---|---|---|
| JVM クラッシュ（例外、OOM） | ✅ 安全（OS が保持） | ⚠️ アプリバッファを失う | ✅ 安全 |
| プロセスを kill -9 | ✅ 安全（OS が保持） | ⚠️ アプリバッファを失う | ✅ 安全 |
| OS カーネルパニック | ❌ ページキャッシュを失う | ❌ より多く失う | ✅ 安全 |
| 電源喪失 | ❌ ページキャッシュを失う | ❌ より多く失う | ✅ 安全 |
ほぼ誰もログ行ごとに
fsyncを行いません — それは懲罰的に遅い（呼び出しごとにミリ秒）からです。ログは「ベストエフォートの耐久性」として扱われ、それが通常正しい選択です。実際に得ている保証を知っておくだけです。
非同期ロギング：ホットパスから外す
同期ロギングの本当の問題は正しさではなく、リクエストスレッドが I/O の請求を支払うことです。ディスクがつっかえたり、ログローテーションが停滞したり、バッファが間違ったタイミングでフラッシュしたりすると、そのレイテンシはちょうどその瞬間にログを記録したユーザーリクエストに直接降りかかります。これは謎の p99 スパイクの典型的な原因です。
非同期ロギングはログイベントを別のスレッドに委ねて即座に戻ることでこれを修正します：
app thread background thread
│ log.info(...) │
│──── enqueue event ────► [ queue ] │
│ returns instantly │──► format + write + flush
▼ ▼
keep serving the request does the slow I/O
Enter fullscreen mode Exit fullscreen mode
アプリスレッドの仕事は「イベントをキューに入れて次に進む」だけに縮小されます。フォーマット、書き込み、フラッシュという遅い作業は、誰も待っていない専用のロギングスレッド上で行われます。
このアイデアには2つの非常に異なる実装があり、その違いがすべてを決定します。
フレーバー 1: Logback / Log4j2 AsyncAppender（ブロッキングキュー）
これは古典的なアプローチです：実際のアペンダーを BlockingQueue（ArrayBlockingQueue）で支えられた非同期アペンダーでラップします。
<!-- Logback -->
<appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
<queueSize>256</queueSize> <!-- default: 256 -->
<discardingThreshold>51</discardingThreshold> <!-- default: 20% of queueSize -->
<neverBlock>false</neverBlock> <!-- default: false -->
<appender-ref ref="FILE"/>
</appender>
Enter fullscreen mode Exit fullscreen mode
ストレス下での動作を決定する3つのノブ：
-
queueSize— キューに待機できるイベント数。大きいほど大きなバーストを吸収し、より多くのメモリを使用します。 -
discardingThreshold— キューがこの程度いっぱいになると、優先度の低いイベント（TRACE/DEBUG/INFO）をドロップし、WARN/ERROR を保持します。Logback のデフォルトはキュー残量の 20% です。0に設定すると決して破棄しません。 -
neverBlock— キューが完全にいっぱいになったときの動作：-
false（デフォルト）：アプリスレッドはスペースが空くまでブロックします。すべてのログを保持しますが、避けようとしていた正確なレイテンシを再導入します — 非同期は負荷下でサイレントに同期になります。 -
true：イベントをドロップして次に進みます。レイテンシは平坦に保たれますが、バースト時にログを失います。 ここに無料のランチはありません。 持続的な過負荷下の有界キューには、プロデューサをブロックするか、イベントをドロップするか、無制限に成長する（OOM）の3つの選択肢しかありません。すべての非同期ロガーは、これらのどれをいつ行うかを選択しているだけです。 ### フレーバー 2: Log4j2 Async Loggers（LMAX Disruptor） Log4j2 の目玉機能は Async Loggers で、LMAX Disruptor — 高頻度取引から生まれたロックフリーリングバッファ — に基づいて構築されています。これはブロッキングキューとは根本的に異なるものであり、Log4j2 のベンチマークが非常に積極的な理由です。
-
<!-- すべてのロガーを非同期にする（システムプロパティ） -->
<!-- -Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector -->
<!-- または混合：特定のロガーのみ非同期、他は同期 -->
<AsyncLogger name="com.myapp" level="info"/>
<Root level="info">
<AppenderRef ref="FILE"/>
</Root>
Enter fullscreen mode Exit fullscreen mode
キューではなくリングバッファを使う理由は2つあります：
1. ロックフリー = 競合なし。 BlockingQueue はロックを使用します；多くのスレッドが同時にログを記録すると、そのロックをめぐって争い、シリアライズされます。Disruptor は代わりに事前割り当てされたリングバッファとアトミックシーケンスカウンタ（CAS）を使用します。プロデューサとコンシューマは相互排除ではなくカーソル位置を介して調整します。高スレッド数ではこれが違いとなります — Log4j2 自身の数値は、ブロッキングキューがプラトーするのに対し、非同期ロガーが数百万メッセージ/秒を維持することを示しています。
ring buffer (pre-allocated slots, reused forever)
┌───┬───┬───┬───┬───┬───┬───┬───┐
│ 5 │ 6 │ 7 │ │ │ 1 │ 2 │ 3 │
└───┴───┴───┴─▲─┴───┴───┴───┴─▲─┘
│ │
consumer cursor producer cursor
(writes to disk) (app threads publish here)
Enter fullscreen mode Exit fullscreen mode
2. ガーベージフリー。 リングバッファのスロットは一度割り当てられ、再利用されます。キューはイベントごとに新しいノードを割り当て、ガーベージコレクタに負荷をかけます。Disruptor は事前割り当てを行うため、定常状態では（ほぼ）ガーベージを作成しません — つまりロギングによる GC ポーズがないことを意味します。Log4j2 はこれを StringBuilder とバッファを再利用する「ガーベージフリーレイアウト」モードと組み合わせることで、ほぼゼロのアロケーションでハードにログを記録できます。
リングバッファが満杯になったらどうなるか？AsyncQueueFullPolicy
前述と同じ根本的な問題 — 有界バッファはオーバーフローする可能性がある — そして Log4j2 はポリシーを明示的にします：
-
Defaultポリシー：プロデューシングスレッドはスロットが空くまでブロック（ビジースピン/待機）します。ログは失われませんが、バックプレッシャがアプリスレッドに当たります。 -
Discardポリシー：満杯時に設定されたレベル以下のイベントをドロップ（デフォルト：INFO 以下をドロップ）。レイテンシを平坦に保ち、優先度の低いログを失います。 - カスタムポリシーをプラグインすることもできます。 また、知っておくべき鋭いエッジがあります：ログ呼び出しがバックグラウンドコンシューマスレッド自体上で起こった場合（例：レイアウト内や例外ハンドラからログを記録）、ブロッキングはデッドロックを引き起こすため、Log4j2 はこれを検知して代わりに同期的にルーティングします。
耐久性のひねり：非同期は同期セットアップでは失わないログを失う可能性がある
人々が忘れがちなトレードオフがあります。非同期ロギングでは、アプリスレッドが log.error("about to crash") から戻ったとき、そのイベントはメモリ内のキューにただ座っているだけです。フォーマットすらされておらず、ましてや書き込みやフラッシュはされていません。
次のミリ秒で JVM がクラッシュした場合、クラッシュを説明するそのエラーログは失われます。 同期の immediateFlush=true ロギングでは、同じ行は OS キャッシュにあり、生き残っていたでしょう。
これが非同期ロギングの残酷な皮肉です：最もログを記録しているとき — しばしば何かがうまくいかなくなる直前 — に最も速いのです。
緩和策：
-
シャットダウンフック / グレースフルドレイン。 両方のフレームワークは正常なシャットダウン時にキューをフラッシュしようとします。これはクリーンな終了を処理し、
kill -9やハードクラッシュは処理しません。 - 致命的エラーを同期的にログ記録。 一般的なパターン：INFO/DEBUG は非同期ですが、ERROR/FATAL は重要なものが耐久性を持つよう同期の即時フラッシュアペンダーを通してルーティングします。
- 損失を受け入れる。 高ボリューム、低価値のログ（アクセスログ、デバッグトレース）では、ハードクラッシュ時に最後の数百件を失うことは問題ありません。ログの価値に保証を合わせます。
数値化する（そしてベンチマークの罠）
スループットの大まかな順序（遅いものから速いものへ）：
sync + immediateFlush=true ▓▓ (行ごとの syscall)
sync + immediateFlush=false ▓▓▓▓▓▓ (バッファリング済み)
async AsyncAppender (queue) ▓▓▓▓▓▓▓▓▓▓
async Loggers (Disruptor) ▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓
Enter fullscreen mode Exit fullscreen mode
しかし — すべての正直なベンチマークが言うように — あなたの結果は大きく異なるでしょう、なぜなら：
- ピーク vs 持続的なスループットは異なる質問です。 非同期はバーストを吸収するのに素晴らしいです。しかしディスクの実際の書き込み帯域幅はハードな上限です。ディスクが排出できる以上のログ量を持続すると、キューが満杯になり、非同期はそのフルポリシー（ブロッキングまたはドロッピング）のいずれかに劣化します。非同期はディスクを速くするわけではなく、アプリをディスクのジッタから切り離すだけです。
-
レイアウトコストがしばしば本当のボトルネックです。 呼び出し元位置（
%class、%line、%method）を含む派手なパターンはすべてのログ行でスタックトレースのウォークを強制します — それは書き込み自体よりもコストがかかる可能性があります。ホットパスでは位置情報を避けましょう。 - マイクロベンチマークは嘘をつきます。 何も実行していないタイトなループでのロギングは、GC、CPU キャッシュ、他のスレッドがすべて競合している実際のアプリを反映しません。 実践的な要点は数字ではなく、決定木です。
実践的な決定ガイド
ほとんどのサービス向けのデフォルト：
非同期ロギング（可能なら Log4j2 Async Loggers、そうでなければ Logback AsyncAppender）、典型的なバーストを吸収するサイズの有界キューを備え、プレッシャ下で優先度の低いイベントを破棄します。
すべてのログ行が必要な場合（監査、コンプライアンス、金融）：
同期 + immediateFlush=true。スループットのヒットを受け入れます；耐久性を買っているのです。fsync は電源断時に本当にデータを失えない場合にのみ追加し — それがコストがかかることを理解してください。
レイテンシが神聖な場合（トレーディング、リアルタイム）：
Log4j2 Async Loggers をガーベージフリーレイアウトと破棄ポリシーで — 決してロギングにリクエストスレッドをブロックさせず、GC をトリガーさせない。
ほとんどの人をカバーする堅実なハイブリッド：
INFO/DEBUG → async, discard-under-pressure (高ボリューム、低価値)
WARN/ERROR → sync, immediateFlush=true (低ボリューム、高価値)
Enter fullscreen mode Exit fullscreen mode
ノイズには速度を、シグナルには耐久性を。
実際に覚えておくべき5つのこと
-
ログ呼び出しの下には2つのバッファがあります。
flush()はアプリバッファを OS に空にします；fsync()は OS をディスクに空にします。それらは同じではなく、2番目のみが電源喪失から生き残ります。 -
immediateFlushはコアの同期ノブです。true= 安全だが行ごとに syscall；false= 速いがクラッシュ時にアプリバッファを失う。 - 非同期は I/O をリクエストスレッドから移動させます — レイテンシジッタを殺します — しかしすべての有界キューは最終的に持続的な過負荷下でブロック、ドロップ、または OOM しなければなりません。あなたのものがどれをするかを知りましょう。
- Disruptor はロックフリーとガーベージフリーであることで勝ちます、魔法によるものではありません。高スレッド数でブロッキングキューを打ち負かし、GC ポーズを避けます。
- 非同期は耐久性を速度とトレードオフします。 クラッシュを説明するログは、キュー内で失われる可能性が最も高いものです。重要なログは同期的にルーティングしましょう。 ロギングはコードベースの中で最も退屈な行のように感じられます。また、静かに同時実行性、メモリ階層、syscall、GC、耐久性すべてに一度に触れる数少ないものの1つでもあります。今、あなたはその1行が実際に何をしているのかを知っています。🚀 ---
あなたのロギングセットアップは — 同期で安全、または非同期で高速ですか？そして「非同期ロギングが私のクラッシュログを食った」ことがあなたを悩ませたことはありますか？コメントで教えてください。
0 Comments
Log in to join the conversation.No comments yet. Be the first to share your thoughts.