DEV Community

Mukul S
Mukul S

Posted on

The Hidden Cost of a Log Line : Sync/Async Flush and everything in Between

log.info("user logged in") looks free. It isn't. Behind that one line is a chain of decisions — buffer or not, flush or not, block or drop, same thread or another — and each one trades latency, throughput, and durability against the others. This post walks the whole chain, from the method call down to the bytes hitting the disk platter.

If you've ever wondered why your p99 latency has a mysterious spike, why logs vanish after a crash, or what "async logging" actually buys you, this is for you.

First, the map: facade vs. implementation

Java logging is a two-layer cake, and mixing up the layers is the #1 source of confusion.
The facade is the API your code calls. The implementation is what actually writes the bytes.

your code
   │  log.info(...)
   ▼
┌───────────────────────────────┐
│  Facade: SLF4J (or Log4j2 API)│   ← the interface you compile against
└──────────────┬────────────────┘
               │ bound at runtime
   ┌───────────┼────────────┬──────────────┐
   ▼           ▼            ▼              ▼
Logback   Log4j2 Core   java.util.logging  ...
(the engine that buffers, formats, and flushes)
Enter fullscreen mode Exit fullscreen mode
  • SLF4J — the de-facto standard facade. Your app should log against this.
  • Logback — the reference SLF4J implementation. Solid, widely deployed.
  • Log4j2 — the performance-focused implementation, famous for its lock-free async loggers.
  • java.util.logging (JUL) — built into the JDK, rarely chosen on purpose.

Why the split? So you can swap engines without touching a single log. call. Everything interesting in this post — the buffering, the flushing, the async magic — happens in the implementation layer.


The anatomy of a single log call

Before we talk flushing, let's see what one log.info(...) actually does. There are five stages:

1. Level check      → is INFO enabled for this logger? (cheap, often the fastest bail-out)
2. Build LogEvent   → capture message, timestamp, thread, MDC context, maybe a stack trace
3. Filter           → run any configured filters
4. Layout / encode  → turn the event into bytes ("2026-07-28 12:00:01 INFO ...")
5. Append           → write those bytes to the destination (file, console, socket)
Enter fullscreen mode Exit fullscreen mode

Stage 5 — the append — is where sync vs. async and flush-vs-no-flush live. It's also, by far, the most expensive stage, because it may touch the disk.

Pro tip already: Stage 1 is why you sometimes see if (log.isDebugEnabled()). It skips stages 2–5 when the level is off. With modern parameterized logging (log.debug("x={}", x)) the framework does this check for you before building the string — so log.debug("x=" + x) is the real anti-pattern, because the string concatenation happens regardless.


Sync logging: the default, and its two hidden layers

"Synchronous" means the append happens on your application thread. Your thread doesn't return from log.info(...) until the write is done. Simple, predictable — and where all the flush nuance lives.
Here's the subtlety most people miss: between your log statement and the actual disk, there are two separate buffers.

 your app thread
      │  writes formatted bytes
      ▼
┌─────────────────────┐
│ App-level buffer    │   ← BufferedOutputStream inside the appender
│ (e.g. 4 KB)         │      flush() empties THIS
└──────────┬──────────┘
           │ flush()
           ▼
┌─────────────────────┐
│ OS page cache       │   ← the kernel's copy, still in RAM
│ (kernel memory)     │      fsync() empties THIS
└──────────┬──────────┘
           │ fsync()
           ▼
┌─────────────────────┐
│ Physical disk       │   ← now it survives a power loss
└─────────────────────┘
Enter fullscreen mode Exit fullscreen mode

Two different operations empty two different buffers, and people constantly confuse them:

  • flush() pushes bytes from the application buffer into the OS page cache. After a flush, another process (like tail -f) can see your log line. But it is still in RAM — a kernel panic or power loss loses it.
  • fsync() (via FileChannel.force()) forces the OS to write the page cache to physical storage. This is what actually makes a log line survive a crash — and it's dramatically slower. Most logging frameworks give you knobs for the first buffer and, effectively, never touch the second by default. That's the durability tradeoff hiding in plain sight. ### immediateFlush: the knob that matters most Both Logback and Log4j2 file appenders expose 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

What it does:

  • immediateFlush=true (the default): call flush() after every log event. Your line is in the OS cache the instant the call returns. Safe if the JVM crashes (the OS still has the bytes and will write them). But it means a syscall per log line — the throughput killer under load.
  • immediateFlush=false: let the BufferedOutputStream fill up (typically 8 KB) and flush only when it's full. Far fewer syscalls, much higher throughput. The cost: if the JVM dies, whatever's sitting in the app buffer (up to 8 KB of your most recent, most interesting logs) is gone. That's the fundamental sync-flush tradeoff in one sentence: flush every line for safety, or buffer for speed.

Note: Log4j2 automatically forces immediateFlush=false behavior for its async loggers — because in the async world, the fix for durability is different (more on that below).

So does sync logging survive a crash?

Depends on which crash and which flush setting:

Failure immediateFlush=true immediateFlush=false With fsync
JVM crash (exception, OOM) ✅ safe (OS has it) ⚠️ lose app buffer ✅ safe
Kill -9 the process ✅ safe (OS has it) ⚠️ lose app buffer ✅ safe
OS kernel panic ❌ lose page cache ❌ lose more ✅ safe
Power loss ❌ lose page cache ❌ lose more ✅ safe

Almost nobody does fsync per log line — it's punishingly slow (milliseconds per call). Logs are treated as "best effort durable," and that's usually the right call. Just know the guarantee you're actually getting.


Async logging: get off the hot path

Sync logging's real problem isn't correctness — it's that your request thread pays the I/O bill. If the disk hiccups, if a log rotation stalls, if the buffer flushes at the wrong moment, that latency lands directly on the user request that happened to log at that instant. This is a classic source of mysterious p99 spikes.
Async logging fixes this by handing the log event to another thread and returning immediately:

 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

Your app thread's job shrinks to "drop the event in a queue and move on." The slow work — formatting, writing, flushing — happens on a dedicated logging thread that nobody's waiting on.
There are two very different implementations of this idea, and the difference is the whole ballgame.

Flavor 1: Logback / Log4j2 AsyncAppender (a blocking queue)

This is the classic approach: wrap a real appender in an async one backed by a BlockingQueue (an 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

The three knobs that decide its behavior under stress:

  • queueSize — how many events can wait in line. Bigger = absorbs bigger bursts, uses more memory.
  • discardingThreshold — when the queue gets this full, drop lower-priority events (TRACE/DEBUG/INFO) and keep WARN/ERROR. Logback defaults this to 20% of the queue remaining. Set it to 0 to never discard.
  • neverBlock — what to do when the queue is completely full:
    • false (default): the app thread blocks until space frees up. You keep every log, but now you've reintroduced the exact latency you were trying to avoid — async silently becomes sync under load.
    • true: drop the event and move on. Latency stays flat, but you lose logs during bursts. There is no free lunch here. A bounded queue under sustained overload has only three options: block the producer, drop events, or grow unbounded (OOM). Every async logger is just choosing which of these to do, and when. ### Flavor 2: Log4j2 Async Loggers (the LMAX Disruptor) Log4j2's headline feature is Async Loggers, built on the LMAX Disruptor — a lock-free ring buffer that came out of high-frequency trading. This is a genuinely different beast from a blocking queue, and it's why Log4j2 benchmarks so aggressively.
<!-- Make ALL loggers async (system property) -->
<!-- -Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector -->
<!-- Or mix: specific loggers async, rest sync -->
<AsyncLogger name="com.myapp" level="info"/>
<Root level="info">
    <AppenderRef ref="FILE"/>
</Root>
Enter fullscreen mode Exit fullscreen mode

Why a ring buffer instead of a queue? Two reasons:
1. Lock-free = no contention. A BlockingQueue uses locks; when many threads log at once, they fight over that lock and serialize. The Disruptor uses a pre-allocated ring buffer and atomic sequence counters (CAS) instead of locks. Producers and the consumer coordinate via cursor positions, not mutual exclusion. At high thread counts this is the difference — Log4j2's own numbers show async loggers sustaining millions of messages/sec where a blocking queue plateaus.

        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. Garbage-free. The slots in the ring buffer are allocated once and reused. A queue allocates a new node per event, feeding the garbage collector. The Disruptor pre-allocates, so in steady state it creates (almost) no garbage — which means no GC pauses caused by logging. Log4j2 pairs this with a "garbage-free" layout mode that reuses StringBuilders and buffers, so you can log hard with near-zero allocation.

What happens when the ring buffer fills? AsyncQueueFullPolicy

Same fundamental problem as before — a bounded buffer can overflow — and Log4j2 makes the policy explicit:

  • Default policy: the producing thread blocks (busy-spins/waits) until a slot frees up. No lost logs, but backpressure hits your app thread.
  • Discard policy: drop events at or below a configured level (default: drop INFO and below) when full. Keeps latency flat, loses low-priority logs.
  • You can also plug in a custom policy. And there's a sharp edge worth knowing: if a log call happens on the background consumer thread itself (e.g. logging from inside a layout or an exception handler), blocking would deadlock — so Log4j2 detects this and routes it synchronously instead.

The durability twist: async can lose logs a sync setup wouldn't

Here's the tradeoff people forget. With async logging, when your app thread returns from log.error("about to crash"), that event is just sitting in a queue in memory. It hasn't been formatted, let alone written or flushed.
If the JVM crashes in the next millisecond, that error log — the one explaining the crash — is gone. With synchronous immediateFlush=true logging, the same line would have been in the OS cache and survived.
This is the cruel irony of async logging: it's fastest exactly when you're logging the most, which is often right before something goes wrong.
Mitigations:

  • Shutdown hooks / graceful drain. Both frameworks try to flush the queue on orderly shutdown. This handles clean exits, not kill -9 or hard crashes.
  • Log fatal errors synchronously. A common pattern: async for INFO/DEBUG, but route ERROR/FATAL through a synchronous, immediate-flush appender so the important stuff is durable.
  • Accept the loss. For high-volume, low-value logs (access logs, debug traces), losing the last few hundred on a hard crash is fine. Match the guarantee to the value of the log.

Putting numbers to it (and the benchmarking trap)

Rough ordering of throughput, slowest to fastest:

sync + immediateFlush=true        ▓▓                      (syscall per line)
sync + immediateFlush=false       ▓▓▓▓▓▓                  (buffered)
async AsyncAppender (queue)       ▓▓▓▓▓▓▓▓▓▓
async Loggers (Disruptor)         ▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓
Enter fullscreen mode Exit fullscreen mode

But — and every honest benchmark says this — your mileage will vary wildly, because:

  1. Peak vs. sustained throughput are different questions. Async is fantastic at absorbing bursts. But your disk's real write bandwidth is a hard ceiling. If you sustain more log volume than the disk can drain, the queue fills and async degrades to whatever its full-policy is (blocking or dropping). Async doesn't make your disk faster — it just decouples your app from disk jitter.
  2. Layout cost is often the real bottleneck. A fancy pattern with caller location (%class, %line, %method) forces a stack-trace walk on every log line — that can cost more than the write itself. Avoid location info in hot paths.
  3. Microbenchmarks lie. Logging in a tight loop with nothing else running doesn't reflect a real app where the GC, the CPU cache, and other threads are all contending. The practical takeaway isn't a number — it's a decision tree.

A practical decision guide

Default for most services:
Async logging (Log4j2 Async Loggers if you can, Logback AsyncAppender otherwise), with a bounded queue sized to absorb your typical burst, and low-priority events discarded under pressure.
When you need every log line (audit, compliance, financial):
Synchronous + immediateFlush=true. Accept the throughput hit; you're buying durability. Add fsync only if you truly can't lose data on a power cut — and know it'll cost you.
When latency is sacred (trading, real-time):
Log4j2 Async Loggers with garbage-free layout and a discard policy — never let logging block a request thread, and never let it trigger GC.
A solid hybrid that covers most people:

INFO/DEBUG  → async, discard-under-pressure  (high volume, low value)
WARN/ERROR  → sync, immediateFlush=true       (low volume, high value)
Enter fullscreen mode Exit fullscreen mode

You get speed for the noise and durability for the signal.


The five things to actually remember

  1. A log call has two buffers below it. flush() empties the app buffer to the OS; fsync() empties the OS to disk. They are not the same, and only the second survives a power loss.
  2. immediateFlush is the core sync knob. true = safe but a syscall per line; false = fast but you lose the app buffer on a crash.
  3. Async moves I/O off your request thread — killing latency jitter — but every bounded queue must eventually block, drop, or OOM under sustained overload. Know which one yours does.
  4. The Disruptor wins by being lock-free and garbage-free, not by magic. It beats blocking queues under high thread counts and avoids GC pauses.
  5. Async trades durability for speed. The log explaining your crash is the one most likely to be lost in the queue. Route critical logs synchronously. Logging feels like the most boring line in your codebase. It's also one of the few that quietly touches concurrency, the memory hierarchy, syscalls, GC, and durability all at once. Now you know what that one line is really doing. 🚀 ---

What's your logging setup — sync-and-safe, or async-and-fast? And has "async logging ate my crash log" ever bitten you? Tell me in the comments.

Top comments (0)