Design a Logging Framework
Design a Logging Framework
Every service you will ever operate leans on a logging framework, and "design a logging library" is a recurring LLD interview ask because it quietly tests three separate skills at once: can you decouple what gets logged from where it goes and how it's formatted (that's the Chain of Responsibility and Strategy patterns doing real work, not vocabulary); can you filter cheaply (checking a level before you build a string); and — the part that actually separates a toy from something you'd run in production — do you know that a naive logging call can silently stall the request that triggered it. This lab makes you build a leveled, multi-destination logger from an empty file in Java and Go, measure the synchronous-I/O stall for real, and then fix it with a bounded async queue whose full-queue policy you have to defend.
1. The trap
You're asked to "add logging" to a hot request path. The obvious first draft:
void handleRequest(Request req) {
log.info("handling request " + req.id() + " for user " + req.userId());
// ... do the actual work ...
log.info("completed request " + req.id() + " in " + elapsed + "ms");
}
// log.info just writes straight to a file, synchronously, on the request thread:
void info(String msg) {
writer.write(msg + "\n");
writer.flush(); // and maybe fsync(), if you want durability
}
This works fine in a demo. It quietly breaks two ways once it's under real load, and you will hit both if you don't design around them:
- The request thread pays for a disk write on every single log call.
flush()(worse, anfsync()) is a syscall that can block for milliseconds — not nanoseconds — especially once the disk is busy, on a network-mounted volume, or during an EBS/NFS hiccup. Multiply that by every log line in a hot loop and your p99 latency becomes "however slow the disk was at that moment," not "however fast your code is." We measure this exact stall in Movement 5: 2,000 synchronous, fsync'd log calls cost 77 ms of caller-side time in Java and 5.14 seconds in Go on the same machine — a reminder that the absolute cost of a syscall is wildly hardware/OS-dependent, but the shape of the problem (the caller pays for I/O) is universal. - There's no separation between "what to log," "where it goes," and "how it looks." One
Stringconcatenation, one destination, one format. Add a second destination (ship to a log aggregator AND keep a local file) and you're duplicating the write call everywhere. Want JSON instead of plain text for machine parsing? You're rewriting every call site.
Both problems have the same fix shape: decouple the decision to log from the act of writing it, and decouple the act of writing from the thread that's on the request's critical path. That's the whole lab.
2. Scope it like a senior
Before writing a class, pin the contract down. Ask:
- What levels, and what's the filtering unit? The standard five —
TRACE < DEBUG < INFO < WARN < ERROR— and filtering happens per logger (a named source, e.g.com.acme.orders) so one subsystem can run atDEBUGwhile the rest of the app stays atINFO. - How many destinations, and can they differ per subsystem? Console for local dev, a rotating file in production, maybe both at once, each possibly at a different threshold (e.g. file gets
DEBUG, console onlyWARN+). That's the Appender abstraction, and it implies more than one can be attached at a time. - Is the wire format fixed? No — plain text for a human tailing a file today, JSON for a log shipper tomorrow. The record and its rendering must be separate types (Formatter as a Strategy), or every format change is a rewrite.
- Synchronous or does a log call need to never block the caller? This is the load-bearing question. A payments-critical path cannot tolerate an unbounded stall on every log line — but "never block" has a corollary: if producers can log faster than the sink can absorb it, memory or messages have to give. Which one is a product decision, not a technical one, and we make it explicitly in Movement 3.
- What happens on crash or shutdown? If logs are buffered in memory for async delivery, a hard kill loses whatever hasn't been flushed. A real answer needs an explicit drain-then-close step wired to shutdown, not "it'll probably be fine."
- Ordering guarantees? Do log lines from one thread need to appear in the order they were emitted? (Yes, generally — a single producer's messages must stay in order at a given sink; cross-thread global ordering is not usually promised, and timestamps do that job instead.)
Answering these before coding is what turns "print statements with extra steps" into an actual design.
3. Reason to the design
Attempt 0 — one method, one destination, no filtering. A single log(String) that writes straight to a file. It compiles, but every level is unconditionally live (no way to quiet TRACE in production without a code change) and there is exactly one place logs can go.
Attempt 1 — add levels, and filter BEFORE building the message. The first real design decision: the level check must happen before the message is formatted, not after.
// Wrong order -- pays the formatting cost even when the line is discarded:
String msg = "user=" + user.id() + " cart=" + cart.expensiveToString();
if (level.ordinal() >= threshold.ordinal()) write(msg);
// Right order -- the guard is the FIRST thing that runs:
if (level.ordinal() >= threshold.ordinal()) {
write("user=" + user.id() + " cart=" + cart.expensiveToString());
}
This is why every real framework structures the public API as logger.debug(String) that internally guards, rather than making the caller remember to wrap every call in an if (isDebugEnabled()) — though the guard-and-build-lazily version is exactly what you reach for when the message itself is expensive to construct (e.g. serializing an object). Either way: never build a message the level check would have discarded.
Attempt 2 — separate the destination (Appender) from the rendering (Formatter, a Strategy). A ConsoleAppender and a FileAppender both need to turn a LogRecord into text, but they shouldn't each hardcode their own text layout — that couples "where" to "how." Pull the rendering out into a Formatter interface (PlainFormatter today, a JsonFormatter tomorrow), and pass one into any appender. Now adding a destination is a new small class; changing the wire format is a one-line swap, no appender touched.
Attempt 3 — more than one appender, more than one logger: the chain of responsibility. Real systems have a hierarchy of named loggers (com.acme → com.acme.orders → com.acme.orders.payment), and a child logger without its own level or appenders should inherit from its parent, walking up the chain until it finds one. This is literally the Chain of Responsibility pattern applied to log dispatch: each logger in the chain gets a chance to handle the record with its own appenders, then — unless told not to (additive = false) — passes it up to the parent, which does the same. It's exactly how java.util.logging, Log4j, and Logback structure logger hierarchies, and it's why setting one subsystem to DEBUG doesn't require re-wiring every appender by hand.
Attempt 4 — the concurrency crux: synchronous appenders own the caller's thread. Every appender so far does its I/O inline, on whatever thread called log(). That's Movement 1's trap, now precisely located: it's not the Logger or the Chain that's slow, it's a specific Appender doing synchronous I/O. The fix is to make ANY appender async by wrapping it: an AsyncAppender holds a bounded queue and a single background writer thread that drains it and calls the real (slow) appender. log() now only has to enqueue — typically sub-microsecond — and returns immediately. The queue is bounded on purpose: an unbounded queue defers the problem instead of solving it — if the writer is ever slower than producers for a sustained burst, an unbounded queue grows without limit and eventually OOMs the process. So capacity is finite, which forces the one decision every logging framework has to make explicitly: what happens when the queue is full?
- Block the caller until there's room. Correct (no log loss), but now a burst on a slow sink re-introduces exactly the stall you were trying to remove — just delayed and smoothed instead of per-call.
- Drop the incoming record (reject-new /
DROP_NEW). The caller never blocks, but you silently lose the newest log lines during the burst — the very lines describing what's happening right now, often the ones you want most during an incident. - Evict the oldest queued record to make room (
DROP_OLDEST, a ring-buffer policy). The caller never blocks and you keep the freshest information, at the cost of silently losing whatever was queued earliest.
There is no universally correct answer — it's a product decision (Movement 6 makes it a real trade-off table). We build all three so you can pick with your eyes open instead of inheriting whatever a library defaults to.
4. Build it — milestones
Build the framework with this contract, milestone by milestone. Attempt each one yourself before reading the reference implementation — it's positioned after this list on purpose.
- Core contract:
Logger.log(Level, String)(plustrace/debug/info/warn/errorconvenience methods); anAppenderinterface withappend(LogRecord)/flush()/close(); aFormatterinterface withformat(LogRecord) -> String. - M1 — levels + filtering + one appender. A single
Loggerwith a threshold and oneConsoleAppender. Prove the guard runs before formatting. - M2 — Formatter as a Strategy + multiple appenders per logger. Swap
PlainFormatterin and out without touching an appender; attach two appenders to one logger, each with its own threshold. - M3 — logger hierarchy (the chain). Parent/child loggers; a child with no appenders of its own inherits level and dispatch up the chain;
additive=falsestops propagation. This is the Chain of Responsibility in Movement 3, made real. - M4 — the async appender. Wrap any appender in a bounded-queue + background-writer-thread decorator with a configurable overflow policy (
BLOCK/DROP_NEW/DROP_OLDEST). This is the concurrency crux — the rest of the framework is straightforward OO; this milestone is the one an interviewer will drill into. - M5 — graceful shutdown. A
close()that stops accepting new intent, drains whatever is already queued, flushes and closes the delegate — wired to a shutdown hook so a normal process exit doesn't lose buffered-but-unwritten lines.
Reference implementation — Java
Two files. LoggingLab.java is the framework: levels, the record, the Formatter strategy, the Appender hierarchy (including the fsync'ing SyncFileAppender that IS the stall), the chain-of-responsibility Logger, and AsyncAppender with all three overflow policies. Both compiled clean with javac and ran end to end before this page was written.
import java.io.FileOutputStream;
import java.io.IOException;
import java.util.List;
import java.util.concurrent.ArrayBlockingQueue;
import java.util.concurrent.BlockingQueue;
import java.util.concurrent.CopyOnWriteArrayList;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicLong;
// ---- Levels ----
enum Level { TRACE, DEBUG, INFO, WARN, ERROR }
// ---- The event ----
final class LogRecord {
final Level level;
final String message;
final long timestampMillis;
final String threadName;
LogRecord(Level level, String message) {
this.level = level;
this.message = message;
this.timestampMillis = System.currentTimeMillis();
this.threadName = Thread.currentThread().getName();
}
}
// ---- Formatter (Strategy): how a record becomes text ----
interface Formatter { String format(LogRecord r); }
final class PlainFormatter implements Formatter {
public String format(LogRecord r) {
return "[" + r.timestampMillis + "] [" + r.level + "] [" + r.threadName + "] " + r.message;
}
}
// ---- Appender: where a record goes ----
interface Appender {
void append(LogRecord r);
void flush();
void close();
}
abstract class AbstractAppender implements Appender {
protected final Level threshold;
protected final Formatter formatter;
protected AbstractAppender(Level threshold, Formatter formatter) {
this.threshold = threshold;
this.formatter = formatter;
}
protected boolean accepts(Level l) { return l.ordinal() >= threshold.ordinal(); }
}
final class ConsoleAppender extends AbstractAppender {
ConsoleAppender(Level threshold, Formatter f) { super(threshold, f); }
public void append(LogRecord r) {
if (!accepts(r.level)) return;
System.out.println(formatter.format(r));
}
public void flush() { System.out.flush(); }
public void close() { }
}
// Synchronous file appender: fsync's every line -- this IS the stall we measure below.
final class SyncFileAppender extends AbstractAppender {
private final FileOutputStream out;
SyncFileAppender(Level threshold, Formatter f, String path) throws IOException {
super(threshold, f);
this.out = new FileOutputStream(path, true);
}
public synchronized void append(LogRecord r) {
if (!accepts(r.level)) return;
try {
out.write((formatter.format(r) + "\n").getBytes("UTF-8"));
out.getFD().sync(); // force to physical disk -- the expensive part
} catch (IOException e) {
throw new RuntimeException(e);
}
}
public synchronized void flush() {
try { out.flush(); } catch (IOException e) { /* best effort */ }
}
public synchronized void close() {
try { out.close(); } catch (IOException e) { /* best effort */ }
}
}
// ---- Logger: the chain of responsibility over handlers ----
// Every logger has its own appenders AND (optionally) a parent. A record fires
// this logger's own appenders, then -- if additive -- propagates up the chain
// to the parent's appenders, exactly like java.util.logging / Log4j / Logback.
final class Logger {
private final String name;
private final Logger parent;
private volatile Level level; // null == inherit from parent
private final List<Appender> appenders = new CopyOnWriteArrayList<Appender>();
private volatile boolean additive = true;
Logger(String name, Logger parent) { this.name = name; this.parent = parent; }
void setLevel(Level l) { this.level = l; }
void addAppender(Appender a) { appenders.add(a); }
void setAdditive(boolean a) { this.additive = a; }
private Level effectiveLevel() {
Logger l = this;
while (l != null) {
if (l.level != null) return l.level;
l = l.parent;
}
return Level.INFO; // guard default if nobody set one
}
boolean isEnabled(Level l) { return l.ordinal() >= effectiveLevel().ordinal(); }
// THE level check happens here, BEFORE a LogRecord is built or formatted.
// A disabled TRACE call costs one enum comparison, not a string build + I/O.
void log(Level l, String message) {
if (!isEnabled(l)) return;
dispatch(new LogRecord(l, message));
}
private void dispatch(LogRecord r) {
for (Appender a : appenders) a.append(r); // this logger's own handlers
if (additive && parent != null) parent.dispatch(r); // ...then the chain
}
void trace(String m) { log(Level.TRACE, m); }
void debug(String m) { log(Level.DEBUG, m); }
void info(String m) { log(Level.INFO, m); }
void warn(String m) { log(Level.WARN, m); }
void error(String m) { log(Level.ERROR, m); }
}
// ---- AsyncAppender: bounded queue + background writer thread ----
// Wraps ANY appender (sync file, console, network...) so the caller never
// blocks on I/O -- except under the BLOCK overflow policy, by design.
final class AsyncAppender implements Appender {
enum OverflowPolicy { BLOCK, DROP_NEW, DROP_OLDEST }
private final Appender delegate;
private final BlockingQueue<LogRecord> queue;
private final OverflowPolicy policy;
private final Thread writer;
private volatile boolean running = true;
private final AtomicLong dropped = new AtomicLong();
AsyncAppender(Appender delegate, int capacity, OverflowPolicy policy) {
this.delegate = delegate;
this.queue = new ArrayBlockingQueue<LogRecord>(capacity);
this.policy = policy;
this.writer = new Thread(new Runnable() {
public void run() { drainLoop(); }
}, "async-log-writer");
this.writer.setDaemon(true); // still must call close() to flush on shutdown!
this.writer.start();
}
public void append(LogRecord r) {
switch (policy) {
case BLOCK:
try { queue.put(r); } catch (InterruptedException ie) { Thread.currentThread().interrupt(); }
break;
case DROP_NEW:
if (!queue.offer(r)) dropped.incrementAndGet(); // caller's record is discarded
break;
case DROP_OLDEST:
while (!queue.offer(r)) {
if (queue.poll() != null) dropped.incrementAndGet(); // evict the head to make room
}
break;
default:
throw new IllegalStateException("unknown policy");
}
}
private void drainLoop() {
while (running || !queue.isEmpty()) {
try {
LogRecord r = queue.poll(200, TimeUnit.MILLISECONDS);
if (r != null) delegate.append(r);
} catch (InterruptedException ie) {
Thread.currentThread().interrupt();
}
}
}
long droppedCount() { return dropped.get(); }
int queueSize() { return queue.size(); }
public void flush() { delegate.flush(); }
// Crash-safety: call this from a shutdown hook. It stops accepting new
// work signal, joins the writer so the queue drains, THEN flushes+closes
// the delegate. Skip this and buffered-but-unwritten records are lost.
public void close() {
running = false;
try { writer.join(5000); } catch (InterruptedException ignored) { }
delegate.flush();
delegate.close();
}
}
Wire it up (in a shutdown hook, for real usage): Runtime.getRuntime().addShutdownHook(new Thread(asyncAppender::close)); — the daemon writer thread alone is NOT enough, because the JVM can exit while the queue still has unwritten records; only an explicit drain-then-close on shutdown guarantees they land on disk.
Reference implementation — Go
Same design, two files, idiomatic Go: the bounded queue is a buffered channel, and the background writer is a goroutine ranging over it. go build ./... and go vet ./... both pass clean, and the program was run under go run -race with no races reported.
package main
import (
"fmt"
"os"
"sync"
"sync/atomic"
"time"
)
// ---- Levels ----
type Level int
const (
TRACE Level = iota
DEBUG
INFO
WARN
ERROR
)
func (l Level) String() string {
switch l {
case TRACE:
return "TRACE"
case DEBUG:
return "DEBUG"
case INFO:
return "INFO"
case WARN:
return "WARN"
case ERROR:
return "ERROR"
default:
return "UNKNOWN"
}
}
// ---- The event ----
type LogRecord struct {
Level Level
Message string
TimeMs int64
Goroutine string
}
// ---- Formatter (Strategy): how a record becomes text ----
type Formatter interface {
Format(r LogRecord) string
}
type PlainFormatter struct{}
func (PlainFormatter) Format(r LogRecord) string {
return fmt.Sprintf("[%d] [%s] %s", r.TimeMs, r.Level, r.Message)
}
// ---- Appender: where a record goes ----
type Appender interface {
Append(r LogRecord)
Flush()
Close()
}
// ConsoleAppender
type ConsoleAppender struct {
Threshold Level
Fmt Formatter
mu sync.Mutex
}
func (c *ConsoleAppender) Append(r LogRecord) {
if r.Level < c.Threshold {
return
}
c.mu.Lock()
defer c.mu.Unlock()
fmt.Println(c.Fmt.Format(r))
}
func (c *ConsoleAppender) Flush() {}
func (c *ConsoleAppender) Close() {}
// SyncFileAppender fsyncs every line -- this IS the stall we measure below.
type SyncFileAppender struct {
Threshold Level
Fmt Formatter
file *os.File
mu sync.Mutex
}
func NewSyncFileAppender(threshold Level, f Formatter, path string) (*SyncFileAppender, error) {
file, err := os.OpenFile(path, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644)
if err != nil {
return nil, err
}
return &SyncFileAppender{Threshold: threshold, Fmt: f, file: file}, nil
}
func (a *SyncFileAppender) Append(r LogRecord) {
if r.Level < a.Threshold {
return
}
a.mu.Lock()
defer a.mu.Unlock()
a.file.WriteString(a.Fmt.Format(r) + "\n")
a.file.Sync() // force to physical disk -- the expensive part
}
func (a *SyncFileAppender) Flush() { a.mu.Lock(); defer a.mu.Unlock(); a.file.Sync() }
func (a *SyncFileAppender) Close() { a.mu.Lock(); defer a.mu.Unlock(); a.file.Close() }
// ---- Logger: the chain of responsibility over handlers ----
// Every logger has its own appenders AND (optionally) a parent. A record fires
// this logger's own appenders, then -- if Additive -- propagates up the chain
// to the parent's appenders, exactly like java.util.logging / Log4j / Logback.
type Logger struct {
name string
parent *Logger
level *Level // nil == inherit from parent
appenders []Appender
additive bool
mu sync.Mutex
}
func NewLogger(name string, parent *Logger) *Logger {
return &Logger{name: name, parent: parent, additive: true}
}
func (l *Logger) SetLevel(lv Level) { l.level = &lv }
func (l *Logger) SetAdditive(v bool) { l.additive = v }
func (l *Logger) AddAppender(a Appender) { l.mu.Lock(); l.appenders = append(l.appenders, a); l.mu.Unlock() }
func (l *Logger) effectiveLevel() Level {
for cur := l; cur != nil; cur = cur.parent {
if cur.level != nil {
return *cur.level
}
}
return INFO // guard default if nobody set one
}
func (l *Logger) IsEnabled(lv Level) bool { return lv >= l.effectiveLevel() }
// THE level check happens here, BEFORE a LogRecord is built or formatted.
// A disabled Trace call costs one int comparison, not a string build + I/O.
func (l *Logger) Log(lv Level, msg string) {
if !l.IsEnabled(lv) {
return
}
l.dispatch(LogRecord{Level: lv, Message: msg, TimeMs: time.Now().UnixNano() / int64(time.Millisecond)})
}
func (l *Logger) dispatch(r LogRecord) {
l.mu.Lock()
apps := l.appenders
l.mu.Unlock()
for _, a := range apps {
a.Append(r) // this logger's own handlers
}
if l.additive && l.parent != nil {
l.parent.dispatch(r) // ...then the chain
}
}
func (l *Logger) Trace(m string) { l.Log(TRACE, m) }
func (l *Logger) Debug(m string) { l.Log(DEBUG, m) }
func (l *Logger) Info(m string) { l.Log(INFO, m) }
func (l *Logger) Warn(m string) { l.Log(WARN, m) }
func (l *Logger) Error(m string) { l.Log(ERROR, m) }
// ---- AsyncAppender: bounded queue (channel) + background writer goroutine ----
// Wraps ANY appender (sync file, console, network...) so the caller never
// blocks on I/O -- except under the Block overflow policy, by design.
type OverflowPolicy int
const (
Block OverflowPolicy = iota
DropNew
DropOldest
)
type AsyncAppender struct {
delegate Appender
queue chan LogRecord
policy OverflowPolicy
dropped int64
done chan struct{}
}
func NewAsyncAppender(delegate Appender, capacity int, policy OverflowPolicy) *AsyncAppender {
a := &AsyncAppender{delegate: delegate, queue: make(chan LogRecord, capacity), policy: policy, done: make(chan struct{})}
go a.drainLoop()
return a
}
func (a *AsyncAppender) Append(r LogRecord) {
switch a.policy {
case Block:
a.queue <- r
case DropNew:
select {
case a.queue <- r:
default:
atomic.AddInt64(&a.dropped, 1) // caller's record is discarded
}
case DropOldest:
for {
select {
case a.queue <- r:
return
default:
select {
case <-a.queue: // evict the head to make room
atomic.AddInt64(&a.dropped, 1)
default:
}
}
}
}
}
func (a *AsyncAppender) drainLoop() {
for r := range a.queue {
a.delegate.Append(r)
}
close(a.done)
}
func (a *AsyncAppender) DroppedCount() int64 { return atomic.LoadInt64(&a.dropped) }
func (a *AsyncAppender) Flush() { a.delegate.Flush() }
// Crash-safety: call this from a shutdown path (e.g. signal handler). It stops
// accepting new work, drains the queue, THEN flushes+closes the delegate.
// Only safe to call once producers have stopped sending (Block would panic
// on a closed channel otherwise).
func (a *AsyncAppender) Close() {
close(a.queue)
<-a.done
a.delegate.Flush()
a.delegate.Close()
}
Note the one deliberate language difference the page owns up to: Java's close() stops the writer and joins it (bounded wait, then proceeds regardless); Go's Close() closes the channel and blocks on <-a.done until the writer has drained everything. Both require producers to have stopped calling Append/append first under the BLOCK/Block policy — closing while a producer is still blocked on a full queue is a bug in both languages (a hang in Java, a panic-on-closed-channel in Go).
5. Break it — the failure lessons, reproduced
The driver. This calls ONLY the types defined in Movement 4 above, in a second file per language, so the whole program — framework + driver — is copy-paste compilable and runnable as shown: javac LoggingLab.java LabMain.java && java LabMain in Java, go build . && ./logginglab in Go (both files in the same directory; both declare `package main` in Go, and Java's is the default package). It exercises the chain (Movement 3), then Lesson A (sync vs. async caller latency) and Lesson B (full-queue overflow policy) below.
import java.io.File;
public final class LabMain {
public static void main(String[] args) throws Exception {
chainDemo();
System.out.println("----");
syncVsAsyncLatency();
System.out.println("----");
overflowPolicyDemo();
}
// 1. Level filtering + chain of responsibility (parent/child loggers).
static void chainDemo() {
Logger root = new Logger("root", null);
root.setLevel(Level.INFO);
// appender threshold is TRACE (its own, independent gate) -- the LOGGER
// level is what actually restricts what reaches it in this demo.
root.addAppender(new ConsoleAppender(Level.TRACE, new PlainFormatter()));
Logger child = new Logger("app.orders", root);
child.setLevel(Level.DEBUG); // more verbose than root, locally
// no appenders of its own -- it relies on the chain to root's console appender
child.debug("order 42 validated"); // passes child's DEBUG gate, reaches root's appender
child.trace("this line never prints");// filtered by child's own gate before formatting runs
root.debug("root logger itself is at INFO, so this line never prints either");
}
// 2. Sync (fsync-per-line) vs async appender: measure the caller-side stall.
static void syncVsAsyncLatency() throws Exception {
int n = 2000;
File f1 = File.createTempFile("sync-log", ".log");
File f2 = File.createTempFile("async-log", ".log");
f1.deleteOnExit(); f2.deleteOnExit();
SyncFileAppender syncAppender = new SyncFileAppender(Level.TRACE, new PlainFormatter(), f1.getAbsolutePath());
long t0 = System.nanoTime();
for (int i = 0; i < n; i++) syncAppender.append(new LogRecord(Level.INFO, "hot-loop line " + i));
long syncMillis = (System.nanoTime() - t0) / 1_000_000;
syncAppender.close();
SyncFileAppender delegate = new SyncFileAppender(Level.TRACE, new PlainFormatter(), f2.getAbsolutePath());
AsyncAppender asyncAppender = new AsyncAppender(delegate, 10_000, AsyncAppender.OverflowPolicy.BLOCK);
long t1 = System.nanoTime();
for (int i = 0; i < n; i++) asyncAppender.append(new LogRecord(Level.INFO, "hot-loop line " + i));
long asyncMillis = (System.nanoTime() - t1) / 1_000_000;
asyncAppender.close(); // drains + fsyncs everything before returning
System.out.println(n + " log calls, synchronous fsync-per-line appender: " + syncMillis + " ms on the CALLING thread");
System.out.println(n + " log calls, async appender (bounded queue, BLOCK policy): " + asyncMillis + " ms on the CALLING thread");
System.out.println("caller-side speedup: " + String.format("%.1f", (double) syncMillis / Math.max(asyncMillis, 1)) + "x (the fsync cost moved to the background writer thread)");
}
// 3. Full-queue behavior: a slow delegate (simulated disk) + a fast producer.
static void overflowPolicyDemo() throws Exception {
int capacity = 50;
int produced = 5000;
// DROP_NEW: producer never blocks; excess records are discarded and counted.
SlowAppender slowDelegateA = new SlowAppender(2 /* ms per write, simulating a loaded disk */);
AsyncAppender dropAppender = new AsyncAppender(slowDelegateA, capacity, AsyncAppender.OverflowPolicy.DROP_NEW);
long tA = System.nanoTime();
for (int i = 0; i < produced; i++) dropAppender.append(new LogRecord(Level.INFO, "burst " + i));
long producerMillisDrop = (System.nanoTime() - tA) / 1_000_000;
dropAppender.close();
System.out.println("[DROP_NEW] produced=" + produced + " delivered=" + slowDelegateA.count() +
" dropped=" + dropAppender.droppedCount() + " producer-blocked-for=" + producerMillisDrop + "ms (barely blocks)");
// DROP_OLDEST: producer never blocks either, but keeps the MOST RECENT records
// (evicts the head of the queue instead of rejecting the tail).
SlowAppender slowDelegateC = new SlowAppender(2);
AsyncAppender dropOldAppender = new AsyncAppender(slowDelegateC, capacity, AsyncAppender.OverflowPolicy.DROP_OLDEST);
long tC = System.nanoTime();
for (int i = 0; i < produced; i++) dropOldAppender.append(new LogRecord(Level.INFO, "burst " + i));
long producerMillisDropOld = (System.nanoTime() - tC) / 1_000_000;
dropOldAppender.close();
System.out.println("[DROP_OLDEST] produced=" + produced + " delivered=" + slowDelegateC.count() +
" dropped=" + dropOldAppender.droppedCount() + " producer-blocked-for=" + producerMillisDropOld + "ms (keeps freshest " + capacity + ")");
// BLOCK: producer throughput is throttled down to the slow delegate's speed -- nothing is lost.
SlowAppender slowDelegateB = new SlowAppender(2);
AsyncAppender blockAppender = new AsyncAppender(slowDelegateB, capacity, AsyncAppender.OverflowPolicy.BLOCK);
long tB = System.nanoTime();
for (int i = 0; i < produced; i++) blockAppender.append(new LogRecord(Level.INFO, "burst " + i));
long producerMillisBlock = (System.nanoTime() - tB) / 1_000_000;
blockAppender.close();
System.out.println("[BLOCK] produced=" + produced + " delivered=" + slowDelegateB.count() +
" dropped=" + blockAppender.droppedCount() + " producer-blocked-for=" + producerMillisBlock + "ms (back-pressure hits the caller)");
}
// A stand-in for a slow disk/NFS-mounted log volume: every append costs `delayMs`.
static final class SlowAppender implements Appender {
private final int delayMs;
private volatile int delivered = 0;
SlowAppender(int delayMs) { this.delayMs = delayMs; }
public void append(LogRecord r) {
try { Thread.sleep(delayMs); } catch (InterruptedException ignored) { }
delivered++;
}
public void flush() { }
public void close() { }
int count() { return delivered; }
}
}
package main
import (
"fmt"
"os"
"time"
)
func main() {
chainDemo()
fmt.Println("----")
syncVsAsyncLatency()
fmt.Println("----")
overflowPolicyDemo()
}
// 1. Level filtering + chain of responsibility (parent/child loggers).
func chainDemo() {
root := NewLogger("root", nil)
root.SetLevel(INFO)
// appender threshold is TRACE (its own, independent gate) -- the LOGGER
// level is what actually restricts what reaches it in this demo.
root.AddAppender(&ConsoleAppender{Threshold: TRACE, Fmt: PlainFormatter{}})
child := NewLogger("app.orders", root)
child.SetLevel(DEBUG) // more verbose than root, locally
// no appenders of its own -- it relies on the chain to root's console appender
child.Debug("order 42 validated") // passes child's DEBUG gate, reaches root's appender
child.Trace("this line never prints") // filtered by child's own gate before formatting runs
root.Debug("root logger itself is at INFO, so this line never prints either")
}
// 2. Sync (fsync-per-line) vs async appender: measure the caller-side stall.
func syncVsAsyncLatency() {
n := 2000
f1 := tempPath("sync-log")
f2 := tempPath("async-log")
defer os.Remove(f1)
defer os.Remove(f2)
syncAppender, err := NewSyncFileAppender(TRACE, PlainFormatter{}, f1)
must(err)
t0 := time.Now()
for i := 0; i < n; i++ {
syncAppender.Append(LogRecord{Level: INFO, Message: fmt.Sprintf("hot-loop line %d", i), TimeMs: nowMs()})
}
syncElapsed := time.Since(t0)
syncAppender.Close()
delegate, err := NewSyncFileAppender(TRACE, PlainFormatter{}, f2)
must(err)
asyncAppender := NewAsyncAppender(delegate, 10000, Block)
t1 := time.Now()
for i := 0; i < n; i++ {
asyncAppender.Append(LogRecord{Level: INFO, Message: fmt.Sprintf("hot-loop line %d", i), TimeMs: nowMs()})
}
asyncElapsed := time.Since(t1)
asyncAppender.Close() // drains + fsyncs everything before returning
fmt.Printf("%d log calls, synchronous fsync-per-line appender: %v on the CALLING goroutine\n", n, syncElapsed)
fmt.Printf("%d log calls, async appender (bounded queue, Block policy): %v on the CALLING goroutine\n", n, asyncElapsed)
speedup := float64(syncElapsed) / float64(maxDur(asyncElapsed, time.Millisecond))
fmt.Printf("caller-side speedup: %.1fx (the fsync cost moved to the background writer goroutine)\n", speedup)
}
// 3. Full-queue behavior: a slow delegate (simulated disk) + a fast producer.
func overflowPolicyDemo() {
capacity := 50
produced := 5000
// DropNew: producer never blocks; excess records are discarded and counted.
slowA := &SlowAppender{delayMs: 2} // simulating a loaded disk
dropAppender := NewAsyncAppender(slowA, capacity, DropNew)
tA := time.Now()
for i := 0; i < produced; i++ {
dropAppender.Append(LogRecord{Level: INFO, Message: fmt.Sprintf("burst %d", i)})
}
producerElapsedDrop := time.Since(tA)
dropAppender.Close()
fmt.Printf("[DropNew] produced=%d delivered=%d dropped=%d producer-blocked-for=%v (barely blocks)\n",
produced, slowA.count(), dropAppender.DroppedCount(), producerElapsedDrop)
// DropOldest: producer never blocks either, but keeps the MOST RECENT records
// (evicts the head of the queue instead of rejecting the tail).
slowC := &SlowAppender{delayMs: 2}
dropOldAppender := NewAsyncAppender(slowC, capacity, DropOldest)
tC := time.Now()
for i := 0; i < produced; i++ {
dropOldAppender.Append(LogRecord{Level: INFO, Message: fmt.Sprintf("burst %d", i)})
}
producerElapsedDropOld := time.Since(tC)
dropOldAppender.Close()
fmt.Printf("[DropOldest] produced=%d delivered=%d dropped=%d producer-blocked-for=%v (keeps freshest %d)\n",
produced, slowC.count(), dropOldAppender.DroppedCount(), producerElapsedDropOld, capacity)
// Block: producer throughput is throttled down to the slow delegate's speed -- nothing is lost.
slowB := &SlowAppender{delayMs: 2}
blockAppender := NewAsyncAppender(slowB, capacity, Block)
tB := time.Now()
for i := 0; i < produced; i++ {
blockAppender.Append(LogRecord{Level: INFO, Message: fmt.Sprintf("burst %d", i)})
}
producerElapsedBlock := time.Since(tB)
blockAppender.Close()
fmt.Printf("[Block] produced=%d delivered=%d dropped=%d producer-blocked-for=%v (back-pressure hits the caller)\n",
produced, slowB.count(), blockAppender.DroppedCount(), producerElapsedBlock)
}
// A stand-in for a slow disk/NFS-mounted log volume: every append costs delayMs.
type SlowAppender struct {
delayMs int
delivered int64
}
func (s *SlowAppender) Append(r LogRecord) {
time.Sleep(time.Duration(s.delayMs) * time.Millisecond)
s.delivered++
}
func (s *SlowAppender) Flush() {}
func (s *SlowAppender) Close() {}
func (s *SlowAppender) count() int64 { return s.delivered }
func nowMs() int64 { return time.Now().UnixNano() / int64(time.Millisecond) }
func must(err error) {
if err != nil {
panic(err)
}
}
func tempPath(prefix string) string {
f, err := os.CreateTemp("", prefix+"-*.log")
must(err)
name := f.Name()
f.Close()
return name
}
func maxDur(d, floor time.Duration) time.Duration {
if d < floor {
return floor
}
return d
}
Measured output (this machine, one run each):
Java: 2000 log calls, synchronous fsync-per-line appender: 77 ms on the CALLING thread
2000 log calls, async appender (bounded queue, BLOCK policy): 11 ms on the CALLING thread
caller-side speedup: 7.0x
Go: 2000 log calls, synchronous fsync-per-line appender: 5.140220541s on the CALLING goroutine
2000 log calls, async appender (bounded queue, Block policy): 1.168458ms on the CALLING goroutine
caller-side speedup: 4399.1x
The absolute numbers are hardware- and OS-dependent — this run's fsync() happened to cost roughly 100× more per call in the Go binary than in the JVM process on the exact same disk, which is itself a useful lesson: never trust a fsync/disk-write latency number without measuring it on your actual target hardware, because filesystem, OS write-cache policy, and even language runtime I/O buffering all move it by orders of magnitude. What's stable across both runs is the shape: the synchronous appender makes the caller pay for every I/O; the async appender reduces the caller's cost to "enqueue one object," full stop.
Lesson B — a full queue silently drops logs (or silently stalls the producer), reproduced with real counts. Wrap a deliberately slow delegate (2 ms per write, standing in for a loaded disk or an NFS-mounted log volume) in a 50-capacity AsyncAppender, then produce 5,000 records back-to-back — far faster than the delegate can drain:
Java (capacity=50, delegate=2ms/write, produced=5000):
[DROP_NEW] delivered=52 dropped=4948 producer-blocked-for=5ms (barely blocks; loses 99% of the burst)
[DROP_OLDEST] delivered=53 dropped=4947 producer-blocked-for=10ms (barely blocks; keeps the freshest 50)
[BLOCK] delivered=5000 dropped=0 producer-blocked-for=14683ms (nothing lost; caller pays ~14.7s)
Go (capacity=50, delegate=2ms/write, produced=5000):
[DropNew] delivered=51 dropped=4949 producer-blocked-for=542µs (barely blocks; loses 99% of the burst)
[DropOldest] delivered=51 dropped=4949 producer-blocked-for=857µs (barely blocks; keeps the freshest 50)
[Block] delivered=5000 dropped=0 producer-blocked-for=12.46s (nothing lost; caller pays ~12.5s)
This is the entire back-pressure decision made visible as numbers instead of an abstract trade-off: DROP_NEW/DROP_OLDEST keep the producer fast (sub-15 ms even for 5,000 records) but you lose ~99% of the burst — almost 5,000 log lines, gone, with only a counter (dropped=4948) telling you it happened. BLOCK loses nothing, but the producer now pays the ENTIRE cost of the slow sink — roughly 5000 × 2ms ≈ 10s of theoretical minimum, observed at ~12.5–14.7s including scheduling overhead. Neither result is a bug; both are the deterministic, designed-in consequence of the policy you picked. The bug would be picking a policy and NOT knowing this is what it does under load.
6. Optimise — with trade-offs
| Decision | Option | Buys you | Costs you | Use when |
|---|---|---|---|---|
| Sync vs async appender | Synchronous appender | Simplicity; strict ordering; a write that returns has landed | Caller pays full I/O latency on every call (measured: 77ms–5.1s for 2,000 lines) | Low-volume paths, CLI tools, or when every line must be durable before the call returns (e.g. audit logs before an irreversible action) |
| Async appender (bounded queue + writer thread) | Caller cost drops to "enqueue one object" (measured: sub-15ms–1ms) | A crash before the writer drains can lose buffered lines; adds one more thread/goroutine and a queue to reason about | Default choice for request-serving hot paths and high-volume services | |
| Full-queue policy | BLOCK | Zero log loss, guaranteed | Re-introduces the stall you built async logging to remove — now smoothed across a burst instead of per-call (measured: ~12.5–14.7s producer stall under a sustained slow sink) | Compliance/audit logging, or any system where losing a log line is worse than a slow request |
DROP_NEW (reject incoming) | Producer never blocks; simplest to implement (a single offer()) | Loses exactly the newest information during a burst — often the most relevant lines during an incident (measured: 4,948 of 5,000 dropped) | High-volume telemetry/metrics-style logs where an occasional gap is acceptable and producer latency is sacred | |
DROP_OLDEST (ring buffer) | Producer never blocks; keeps the most RECENT window of activity | Same loss rate as DROP_NEW in a sustained burst, but the surviving records are the freshest, not the earliest — costs a second queue operation (evict) per full append | Dashboards/tailing use cases where "what's happening right now" matters more than "what happened first" | |
| Config granularity | Root-only level/appenders | One knob, trivial to reason about | Can't quiet a noisy subsystem or turn up one module's verbosity without affecting everything | Small services, single-purpose tools |
Per-logger hierarchy (this lab's Logger chain) | Turn one subsystem to DEBUG in production without touching the rest; appenders can differ per branch | More moving parts (effective-level resolution, additivity) to reason about and test | Any service with more than one subsystem worth isolating — i.e. almost all of them | |
| Async mechanism | Simple bounded BlockingQueue/channel + one writer thread (this lab) | Easy to build and reason about; the three overflow policies map directly onto queue operations | One lock/channel is a shared bottleneck; at very high throughput it can itself become the contention point | The overwhelming majority of services — get this right before reaching for anything fancier |
| LMAX Disruptor (what Log4j2's AsyncAppender uses) | Lock-free ring buffer with pre-allocated slots — far higher throughput, far lower and more predictable latency, no GC pressure from queue nodes | Significantly harder to implement/debug correctly (memory ordering, sequence barriers); massive overkill below extreme log volumes | You've profiled and proven the simple queue is the bottleneck at very high (100k+ msgs/sec) logging rates |
The judgment call that actually gets asked: "block vs drop" is not a technical question, it's "what's worse for this system: a slow request, or a missing log line?" A payments audit trail answers "slow request" every time (BLOCK, maybe even fall back to synchronous for that one logger). A high-QPS request-tracing log answers "missing line" every time (DROP_OLDEST, because the freshest trace usually matters most, plus a dropped-count metric so the gap is at least visible). Naming the concrete cost you're trading, with the number attached, is what a staff engineer's answer sounds like — "it depends" without the number is not an answer.
7. Defend under drilling
- "What's the actual cost difference between sync and async logging?" It's not a vague "async is faster" — it's specifically that the caller no longer pays for I/O latency; it pays for one bounded-queue enqueue instead, which on this measurement dropped caller-side cost for 2,000 log calls from 77 ms to 11 ms in Java (7×) and from 5.14 s to 1.17 ms in Go (4,399×, because this machine's Go
fsync()happened to be far more expensive per call than the JVM's). The mechanism, not the multiplier, is the answer: I/O cost moves from the request thread to a dedicated background writer. - "What happens when the async queue fills up?" Exactly one of three things, and it's a config choice you make explicit up front, not a surprise you discover in production: it blocks the producer (zero loss, ~12.5–14.7s of measured stall under a sustained 2ms/write slow sink at 5,000 records), it drops the newest record and increments a counter (measured 4,948/4,947 of 5,000 dropped, sub-15ms producer cost), or it evicts the oldest queued record to admit the newest (same loss rate here, but keeps the freshest window). Whichever you pick, you MUST also expose the dropped-count as a metric — a silent drop policy with no visibility is the actual anti-pattern, not the drop policy itself.
- "How do you not lose logs on crash — flush and shutdown hooks?" A daemon writer thread alone does NOT guarantee delivery: the JVM/Go process can exit while records still sit in the queue. The fix is an explicit drain-then-close wired to the shutdown path (
Runtime.getRuntime().addShutdownHookin Java; a signal handler callingClose()beforeos.Exitin Go) that stops accepting new writes, waits for the writer to fully drain the queue, then flushes and closes the underlying appender. This only protects against a graceful shutdown (SIGTERM, normal exit) — a hard kill (SIGKILL, power loss) can still lose whatever was queued but not yet fsync'd; if that's unacceptable (compliance logs), the honest answer is "log those specific events synchronously," accepting the latency cost for that one category. - "Level check before or after formatting?" Before — always.
Logger.log()/Logger.Log()in the reference implementation checksisEnabled(level)as the very first statement and returns immediately if it's false, BEFORE aLogRecordis even constructed. A disabledTRACEcall costs one enum/int comparison. Get this backwards — format first, check second — and a disabled debug log in a hot loop still pays for string concatenation, object allocation, and (if a caller pre-serializes an object for logging) potentially expensive work, all for a message that's discarded on the next line. - "What breaks at 100x the load?" The single background writer thread/goroutine becomes the bottleneck — it drains one record at a time regardless of how many producers are enqueuing, so total system throughput plateaus at "however fast one writer can push to the sink," no matter how many application threads are logging. At that point you'd either shard appenders (multiple queues + writers, e.g. keyed by logger name or hash of caller) or escalate to a real streaming pipeline: local logging becomes "ship structured events to Kafka," the bounded local queue becomes a topic partition with its own retention/back-pressure story, and "queue full, drop or block" becomes "producer's
buffer.memoryfull,send()blocks then times out" — the exact same three-way decision, now distributed. See Metrics, Logs & Traces — the Three Pillars for where this framework sits inside a full observability pipeline.
8. You can now defend
- You can build a leveled logging framework from scratch with a real separation of concerns — Logger (filtering + dispatch), Formatter (Strategy, how a record renders), Appender (where it goes) — and explain why collapsing them into one class breaks the moment you need a second destination or format.
- You can name and implement the logger hierarchy as a genuine Chain of Responsibility (own appenders fire, then propagate to the parent unless additivity is off), not just as vocabulary, and say why that's how Log4j/Logback actually work.
- You've measured — not assumed — that synchronous I/O in an appender stalls the calling thread (77ms–5.14s for 2,000 calls in this run) and that moving it behind a bounded async queue drops caller-side cost to single-digit milliseconds or less, while understanding exactly what that queue's overflow policy costs you (measured: ~99% loss under DROP_NEW/DROP_OLDEST vs. multi-second producer stall under BLOCK, for the identical burst).
- You can defend the block/drop/drop-oldest decision as a product trade-off with real numbers attached, escalate it to its distributed analogue (Kafka producer back-pressure), and state precisely why "level check before formatting" is not a style nitpick but the difference between a disabled log line costing one comparison versus a full message build.
Re-authored/Deepened for this guide. Reference code compiled and executed (javac/java; go build, go vet, go run -race) before publishing; both break-it measurements (sync-vs-async caller latency, full-queue overflow policies) reproduce the stated numbers on this machine. See also: the Chain of Responsibility Pattern, the Strategy Pattern, and Metrics, Logs & Traces.
🤖 Don't fully get this? Learn it with Claude
Stuck on Design a Logging Framework? Open Claude, copy a block below, and it'll teach you this exact concept — visually and interactively.
Build the mental picture, not memorization.
I just read a lesson on **Design a Logging Framework** (Hands-On Builds) and want to truly understand it. Explain Design a Logging Framework from first principles using ONE vivid real-world analogy and a visual mental model — draw it as ASCII art or a clear step-by-step diagram — with a concrete example using real numbers. Then ask me one question to check I got the mental picture, and wait for my reply. If you're unsure or a claim isn't standard, say so and reason from first principles instead of guessing.
Socratic — adapts to where you're stuck.
Teach me **Design a Logging Framework** interactively. Ask me ONE guiding question at a time, wait for my answer, and adapt to my confusion — build the idea with me step by step instead of explaining it all at once. If you're unsure or a claim isn't standard, say so and reason from first principles instead of guessing.
Active recall exposes what you missed.
Quiz me on **Design a Logging Framework** with 5 questions, easy to tricky, ONE at a time. Tell me if each answer is right; at the end, explain clearly what I got wrong and why. If you're unsure or a claim isn't standard, say so and reason from first principles instead of guessing.
Intuition + hook + flashcards for long-term memory.
Help me remember **Design a Logging Framework** for the long term: give the one-sentence intuition, a memorable hook/mnemonic, a tiny worked example, and 3 active-recall flashcards (Q -> A). If you're unsure or a claim isn't standard, say so and reason from first principles instead of guessing.