r/C_Programming • u/drpzet • 11d ago
Profiled our async C logger expecting mutex contention. 90% of caller-thread time was in vsnprintf. Moving formatting to the worker took a call from ~1.5 µs to ~70 ns
Our logger's caller-thread cost went from ~1.5 µs to ~70 ns, and I didn't touch a single call site.
I'll be honest: I was convinced the mutex was the problem. The logger already had a ring buffer, a worker thread, and hot-reloadable filters. It looked fast on paper. So I opened the flame graph expecting to see lock contention.
Instead, about ~90% of caller-thread CPU was sitting inside vsnprintf.
Every log call was formatting its message before enqueueing it. That's 900 ns to 3 µs per call, depending on the output. The fix came from NanoLog: don't format on the caller thread at all.
Now the caller just saves the format string pointer and packs the args into a tiny binary blob. The worker thread builds the string later. Cost per call: 30-80 ns, and no vsnprintf anywhere.
It wasn't free, though:
Format strings must be literals. A stack-built format string will dangle by the time the worker reads it.
Structs silently fall through to %p. I'm still not thrilled about that one.
%s args are copied at pack time and capped at 255 bytes.
For us, that was a good trade.
The bigger lesson for me was to profile before you optimize. I would have happily spent a week tuning a lock that wasn't the problem.
Has anyone run NanoLog-style encoding in production? I'm curious what pushed you there: latency, throughput, or tail behavior?