How To Cure log4net's Lock Convoy on a Sitecore CD
How synchronous logging quietly became our Content Delivery server's biggest concurrency bottleneck, how memory dumps caught it red-handed, and the sixty-line never-blocking appender that fixed it — plus the trade-offs you're signing up for.
At the worst moment of a load test, our Sitecore Content Delivery server had 427 threads. I took a memory dump and counted where they were. 279 of them, two thirds of the entire process, were parked on a single lock, waiting for permission to write a log line.
Not rendering. Not querying SQL. Not serializing JSON. Waiting to log.
This post is about how logging becomes a performance problem, how we caught it, the small appender that fixed it, and, because every fix in this category is a trade, exactly what you give up in exchange. If you run Sitecore XP or XM on a CD that degrades under load while its CPU naps, there's a decent chance this is you, and the diagnostic takes about ten minutes.
How a log line becomes a bottleneck
Nobody thinks of logging as code on the hot path. That blind spot is the whole problem, because on a busy Sitecore CD, an anonymous page request can emit a surprising number of log events: platform helpers, custom pipeline processors, field-level warnings, instrumentation someone forgot to remove. Individually each statement is defensible. Collectively, a single page render can quietly produce dozens of them, and at an INFO root level they all go to the file.
Each event is microseconds of work. The problem is what they all share: log4net's file appender writes under one process-wide lock. Every event (format the layout, check the file roll, write, flush) happens inside lock(this) on the appender. One lock, all threads, every request.
Under light traffic that's invisible. Under concurrency it becomes a lock convoy, and convoys are worth understanding because the failure shape is so counterintuitive: no individual hold is slow. Each write takes well under a millisecond. But when the arrival rate of log events exceeds the lock's service rate, every arriving thread goes to sleep, and waking a sleeping thread costs a context switch. Threads now spend their lives sleeping, waking, holding the lock briefly, and rejoining the back of the queue. The lock isn't hot because the work is big; it's hot because the coordination is expensive, and it recruits every request thread in the process.
Then the amplification kicks in, courtesy of Little's law: concurrency = arrival rate × time-in-system. The convoy doesn't reject requests, it stretches them. Stretch every request 10 to 15x and your in-flight population explodes; ours went from ~20 concurrent requests to 350+. The thread balloon pressures the GC and the session layer, which produces errors, which produce more log events, which feed the convoy. The dumps caught that loop in the act: session database connection failures being logged by threads parked inside the appender lock, waiting their turn to report the trouble they were part of.
Finding it: the profiler hinted, the dumps convicted
We got two independent looks at this, and they teach different lessons.
The first was a sampling profiler (dotTrace against the w3wp worker, weeks earlier, on a single container). One rendering pipeline was spending ~3.7% of all sampled time in synchronous logging; deleting the useless statements dropped it to ~0.5%. A free win, but a profiler measures CPU on stacks, and a convoy's cost is mostly threads sleeping, which a sampler under-attributes. It showed us wasted work, not the systemic failure.
The systemic failure showed up under fleet-scale load, and the tool that convicted it was the humble memory dump: three snapshots of the degrading w3wp, seconds apart, read with WinDbg and SOS. Two commands did most of the work:
!syncblk: which locks are held, by which thread, with how many waiters. Our top entry was the appender lock, with a triple-digit waiter count.~*e !clrstack: every thread's managed stack. Grouped into families, 279 of 427 stacks ended in the same place,AppenderSkeleton.DoAppendinsideMonitor.Enter.
That's the diagnostic I'd hand any Sitecore team: under load, take one dump of your CD and run !syncblk. If your file appender is in the top row with double- or triple-digit waiters, you have this problem. Ten minutes, no code.
One myth the dumps also killed: this has nothing to do with file locking. log4net holds the log file handle open for the appender's lifetime, so there's no per-write open/close contention on the filesystem. The convoy lives entirely in the in-process monitor. Making the file faster (SSD, separate disk) changes nothing; the queue is in front of the lock, not the disk.
Why you can't just NuGet your way out
The standard .NET answer is "use an async appender package." On Sitecore you can't, for a reason worth knowing: Sitecore doesn't ship Apache log4net. It ships its own fork (Sitecore.Logging.dll), descended from a much older line; the types still live in log4net.spi, a namespace Apache retired ages ago. Community async appenders compile against modern Apache log4net and will not load against the fork. Whatever you use has to be built against Sitecore's assembly.
The good news: the fix is about sixty meaningful lines.
The fix: enqueue and leave
The design goal, stated precisely: a request thread must never wait on the log path. Not for formatting, not for the file, not for a full buffer, not ever again. The shape that achieves it:
- Producers (request threads) do a filter check and a
TryAddinto a bounded in-memory queue, then return. Microseconds. - One background writer thread drains the queue and does everything expensive (layout formatting, roll checks, file writes) against the original, untouched file appender.
- If the queue is ever full, events are dropped and counted, never blocked on. The writer periodically logs a
dropped N eventsmarker so any loss is visible and quantified.
Here's the implementation, trimmed to its essentials (built against the Sitecore fork; note the log4net.spi using):
using System;
using System.Collections.Concurrent;
using System.Threading;
using log4net.Appender;
using log4net.spi; // Sitecore's fork keeps the pre-Apache-2.x namespace
namespace MySite.Logging
{
/// <summary>
/// Never-blocking async wrapper around a synchronous appender. Producers
/// enqueue and return; one background thread forwards to the wrapped
/// appender, so formatting, roll checks, and file writes all happen off
/// the request path. On a full queue the event is dropped and counted.
/// </summary>
public class AsyncForwardingAppender : ForwardingAppender
{
private const int DropMarkerIntervalSeconds = 10;
private BlockingCollection<LoggingEvent> _queue;
private Thread _writer;
private long _dropped;
private DateTime _lastDropMarkerUtc = DateTime.MinValue;
/// <summary>Bounded queue size; settable from config.</summary>
public int QueueCapacity { get; set; } = 10000;
public override void ActivateOptions()
{
base.ActivateOptions();
if (_queue != null) return;
_queue = new BlockingCollection<LoggingEvent>(Math.Max(1000, QueueCapacity));
_writer = new Thread(DrainQueue) { Name = "AsyncLog-Writer", IsBackground = true };
_writer.Start();
}
protected override void Append(LoggingEvent loggingEvent)
{
if (loggingEvent == null) return;
var queue = _queue;
if (queue == null || queue.IsAddingCompleted)
{
// Not activated yet, or shutting down: write synchronously
// rather than lose the event.
base.Append(loggingEvent);
return;
}
// Capture message, thread name, and exception text on the calling
// thread, because the event is about to cross to the writer thread
// where that context no longer exists. Partial deliberately skips
// the expensive LocationInfo/UserName captures.
loggingEvent.Fix = FixFlags.Partial;
var threadName = loggingEvent.ThreadName; // getter caches on first access
try
{
if (!queue.TryAdd(loggingEvent))
{
Interlocked.Increment(ref _dropped); // full: drop, never block
}
}
catch (InvalidOperationException)
{
// CompleteAdding raced this producer during shutdown.
base.Append(loggingEvent);
}
}
public override void OnClose()
{
var queue = _queue;
if (queue != null)
{
try { queue.CompleteAdding(); } catch (ObjectDisposedException) { }
var writer = _writer;
if (writer != null && writer.IsAlive)
{
writer.Join(TimeSpan.FromSeconds(5)); // drain on shutdown
}
}
base.OnClose();
}
private void DrainQueue()
{
try
{
foreach (var loggingEvent in _queue.GetConsumingEnumerable())
{
try { base.Append(loggingEvent); }
catch { /* a failed write must never kill the writer */ }
EmitDropMarkerIfDue();
}
}
catch (ObjectDisposedException) { }
}
private void EmitDropMarkerIfDue()
{
if (Interlocked.Read(ref _dropped) == 0) return;
var now = DateTime.UtcNow;
if ((now - _lastDropMarkerUtc).TotalSeconds < DropMarkerIntervalSeconds) return;
_lastDropMarkerUtc = now;
var dropped = Interlocked.Exchange(ref _dropped, 0);
try
{
var marker = new LoggingEvent(
typeof(AsyncForwardingAppender).FullName,
log4net.LogManager.GetLoggerRepository(),
typeof(AsyncForwardingAppender).FullName,
Level.WARN,
$"[AsyncLog] dropped {dropped} events (queue full)",
null);
marker.Fix = FixFlags.Partial;
base.Append(marker);
}
catch { /* marker emission is best-effort */ }
}
}
}
Wiring it up is a config patch: declare the wrapper around your existing file appender, and repoint the root logger at it. Nothing about the original appender changes: same layout, same file, same rolling behavior, now fed by one thread.
<configuration xmlns:set="http://www.sitecore.net/xmlconfig/set/"
xmlns:patch="http://www.sitecore.net/xmlconfig/">
<sitecore>
<log4net>
<appender name="AsyncLogFileAppender"
type="MySite.Logging.AsyncForwardingAppender, MySite">
<appender-ref ref="LogFileAppender" />
</appender>
<root>
<appender-ref ref="LogFileAppender">
<patch:attribute name="ref">AsyncLogFileAppender</patch:attribute>
</appender-ref>
</root>
</log4net>
</sitecore>
</configuration>
(That patch:attribute trick, rewriting the existing appender-ref in place rather than deleting and re-adding, is the least invasive way to interpose on Sitecore's logging config, and it survives upgrades that touch the surrounding XML.)
Three implementation notes that will save you an afternoon
1. You cannot override DoAppend, and reflection will lie to you about it. The natural plan is to override DoAppend and skip the skeleton's lock entirely. Reflection even reports it as virtual. But the compiler refuses with CS0506, because in the fork DoAppend is an implicit interface implementation, and those are emitted as virtual final in IL. MethodInfo.IsVirtual is true; overridable it is not. Override Append instead. Yes, that means producers still pass through the skeleton's lock(this), and that's fine: the lock is now held for a filter check plus a TryAdd (nanoseconds) instead of format-plus-write-plus-flush. Convoys form when hold-time times arrival-rate gets large; you've just cut the hold-time by four orders of magnitude.
2. Fix the event before it crosses threads. A LoggingEvent lazily resolves its message, thread name, and exception text from the calling thread's context. Hand it to a background thread without fixing and you'll log the writer thread's name on every line, or worse, render a message from state that has since been mutated or disposed. FixFlags.Partial captures what matters and deliberately skips LocationInfo (a stack walk) and UserName (an OS call), which are exactly the expensive captures you don't want back on the request path.
3. The writer must be unkillable and the shutdown must drain. A failed write swallows its exception and moves on; one bad event must not end logging forever. And OnClose completes the queue and joins the writer with a timeout, so an app-pool recycle flushes what's buffered instead of dropping it.
The trade-offs, honestly
Every async logging design is a position on one question: when the system can't keep up, who pays, the request or the log? The synchronous default makes requests pay, and you've seen what that bill looks like. This design makes the log pay. Be clear-eyed about what that means.
Overflow drops events instead of blocking. In normal operation nothing is lost: the queue only matters when log production outruns the writer for long enough to fill it, and the capacity is yours to choose. Ten thousand events absorbs any realistic burst; size it larger if your log volume warrants, since memory is the only real constraint. In all our load testing the queue overflowed exactly once, during a deliberate log-churn storm, and the behavior was the design working: 5,371 events dropped, counted, and reported by the marker, with zero request threads waiting. The reason to drop rather than block on that rare day is the whole thesis of the fix: log storms and traffic spikes arrive together, so a blocking overflow policy would resurrect the convoy at the exact moment you need it gone. One genuine exclusion: if a log stream is a compliance artifact (audit trails, security events), best-effort is the wrong contract no matter how rarely it drops. Route those to a durable sink and keep the never-blocking path for diagnostics.
A crash eats the queue. Buffered events die with the process, and the final seconds before a crash are precisely the ones you'll want. Our accepted mitigations: the bounded queue keeps the exposure window small (10,000 events is seconds of tail, not minutes), and graceful shutdowns drain. A variant worth considering if this keeps you up at night: bypass the queue and write synchronously for ERROR-and-above, accepting a tiny convoy risk on your rarest events to make your loudest ones durable. We didn't need it; you might.
The log lags reality. Your tail -f is now seconds behind during bursts, because the single writer drains at whatever your storage sustains (ours: only ~106 lines/second against slow bind-mounted storage; container log volumes are rarely fast). Timestamps are captured at enqueue time, so the timeline in the file stays truthful even when the writing lags. But "watch the log to see what's happening right now" gets fuzzier under exactly the load where you're most curious.
Bounded memory, but budget it. Ten thousand fixed events at a KB or two each is tens of megabytes worst-case, held exactly when the process is already stressed. Bounded is the point, but size the bound with your pod's memory limit in mind, not aspirationally.
And it is not a license to log freely. The appender made our logging cheap; it did not make it free. The Fix still renders every message on the request thread, and deleting our worst hot-path log statements was worth 3+ points of sampled CPU on its own before the appender ever shipped. Do the hygiene first. The appender is insurance against the hot-path log statement nobody has noticed yet, and on a codebase with history, there is always one.
Did it work?
Same fleet, same load profile, fresh dumps. The process that previously showed 427 threads with 279 queued on the appender lock now showed 72 threads, an empty !syncblk, and exactly one thread anywhere inside log4net: the writer, doing its job alone. The convoy wasn't reduced; it was structurally abolished, because the resource threads used to fight over is no longer shared.
The logging fix was one of several that day (cache sizing was the other headline, a story of its own), so I won't claim a throughput number for this change alone. The claim I can defend from the dumps is the one that matters: request threads no longer wait to log, under any load we can generate. Sixty lines, one config patch, and a set of trade-offs you can reason about, in exchange for never again letting the log file schedule the thread pool.
Go take a dump of your CD under load and run !syncblk. I'll wait.
Have questions about this implementation? Email me at fcostoyaprograms@gmail.com.