skip to content

A Go pipeline stage logging with slog allocates six times per record at 40k records/s. Where do you look, and what do you change first?

level: seniorimportance: should knowfreq 34%

answer

  1. measure the call site first
  2. constant fields need not be re-formatted
  3. typed attrs instead of interfaces
  4. guard the level that is switched off
  5. do not attach the raw payload

basics

~20 s

Benchmark the log call on its own with -benchmem to attribute the allocations, then move the constant fields onto a With-derived logger built once, switch the per-record call to LogAttrs with typed constructors, and stop attaching the raw payload buffer.

solid answer

~50 s

First attribute the cost: two benchmarks over the same handler writing to `io.Discard`, one with the log call and one without, and compare `allocs/op` from `go test -bench=. -benchmem`. Then work outward from the call site. Constant fields — stage name, shard, version — move onto a logger built once with `Logger.With`, so the handler serialises them once instead of per record. The remaining varying fields switch from the `...any` form to `LogAttrs` with `slog.String`/`slog.Int`, which removes the interface boxing and the run-time key/value decoding. Any argument that is expensive to build gets guarded by `logger.Enabled`, which matters most for a Debug line that is off in production but still evaluates its arguments. Finally look at the payload: attaching a multi-kilobyte `[]byte` to every line costs far more in the handler than everything above put together.

code

go · 11 lines
go
// Before: four fields re-formatted per record, and the whole payload on the line.
logger.Info("enriched", "stage", stageName, "shard", shardID,
	"payload", rec.Payload, "bytes", len(rec.Payload))

// After: bind the constants once, at stage start-up.
stage := logger.With(slog.String("stage", stageName), slog.Int("shard", shardID))

// After: per record, only what varies, and only as much of it as is useful.
stage.LogAttrs(ctx, slog.LevelInfo, "enriched",
	slog.String("id", rec.ID),
	slog.Int("bytes", len(rec.Payload)))

go deeper

for a junior

Know the two levers you can pull without deep knowledge: do not attach a large buffer to a line that runs per record, and build a logger with its constant fields once rather than repeating them on every call.

for a middle

Explain each fix mechanically: what With hands to the handler, why LogAttrs avoids boxing, and why an argument to a disabled Debug call is still evaluated. Be able to name the benchmark flag that shows allocs per operation.

for a senior

Sequence the work and defend the order with measurements. Attribute the allocations to the call site before touching it, keep the changes behaviour-preserving, and recognise when the handler rather than the caller is the real allocator.

for a principal

Frame it as a budget question: how much of a hot path's time the team is willing to spend on observability, what every line must carry, and who decides when a field that operators query is dropped for throughput.

## Attribute before you optimise Six allocations per record is a number, not a diagnosis. Before changing code, establish that the log call is the source. The cheap way is a pair of benchmarks over a realistic record, both pointed at the same handler writing to `io.Discard` so the comparison is about the code and not about I/O: ``` go test -bench=Stage -benchmem ``` Run the stage with the log call and again with it removed; `-benchmem` prints `B/op` and `allocs/op`, and the difference between the two rows is what the logging actually costs. This matters because a transform that decodes JSON or grows a slice can easily out-allocate its own log line, and rewriting the logging then buys nothing. ## Then work outward from the call site **1. Move the constant attributes off the hot path.** Fields like the stage name, the shard, the build version and the input topic do not change per record. Bind them once with `Logger.With`, which calls the handler's `WithAttrs`; the built-in text and JSON handlers serialise those attributes at that moment and copy the finished bytes into every later record. Build the derived logger where the stage starts, never inside the loop — a `With` per record costs more than the inlined fields it replaces. **2. Change the call form for what remains.** `logger.Info("enriched", "bytes", n, "id", id)` builds a `[]any`, boxes each non-pointer value into an interface, and makes slog decode the alternating pairs at run time. `logger.LogAttrs(ctx, slog.LevelInfo, "enriched", slog.Int("bytes", n), slog.String("id", id))` passes typed `slog.Attr` values whose `slog.Value` carries strings and numbers in its own fields, so there is no boxing and no decoding. With the built-in handlers this is usually the difference between a handful of allocations and zero or one. **3. Guard the arguments you would rather not build.** Go evaluates every argument before the call runs, so a Debug line whose level is off in production still executes whatever you passed it. Wrap those in `if logger.Enabled(ctx, slog.LevelDebug)`. On a line that is genuinely enabled this buys nothing; on a disabled one in a 40k/s loop it removes the whole argument. **4. Take the payload off the line.** This is usually the largest single item and the easiest to miss, because it costs bytes rather than allocations. Attaching the record's raw `[]byte` payload means the handler renders every byte of it into every line — and the built-in JSON handler, having no typed path for a `[]byte`, marshals it through `encoding/json`, which renders it as a base64 string. A 4 KB payload turns a 200-byte line into something twenty times larger, per record, at 40k records a second. Log an identifier and `len(payload)` instead; the payload is already somewhere you can go and fetch it. ## Do not forget the handler If the call site is already clean and the allocations persist, the handler is the suspect. A handler that builds a map per record, reaches for `fmt.Sprintf`, or allocates a fresh output buffer for each line will dominate anything the call site does. The built-in handlers reuse a buffer from a `sync.Pool` between records and hold a single lock only around the write; that is the bar to compare against. Benchmark the same record through `slog.NewJSONHandler` and through the handler you actually deploy, and if the gap is large the fix is in the handler, not in your call sites. ## What to leave alone Resist rewriting every log call in the service. The mechanical cost only matters where the call is hot; on a start-up line or an error path the variadic form is clearer and the difference is unmeasurable. And keep the changes behaviour-preserving: `With` plus `LogAttrs` emits exactly the same fields, so it is a safe change to make under load. Dropping the payload attribute is the one change that alters the line, and it is worth agreeing with whoever queries those logs before you make it. ## The order matters The sequence above is deliberately cheapest-first in engineering effort and largest-first in effect: measure, bind the constants, retype the variables, guard the expensive, shrink the payload, then question the handler. Stop as soon as the benchmark says you are done — the last two steps cost real time and are wasted if the first two already took the line from six allocations to one.

  • How do you show the allocations come from the log call rather than the transform?
    Write two benchmarks over the same input and the same handler writing to `io.Discard` — one running the stage with the log call, one with it removed — and compare `allocs/op` from `-benchmem`. The difference between the rows is attributable to the call site. Without that comparison you are guessing which half of the stage to rewrite.
  • What if the handler itself is where the allocations are?
    Then no call-site change helps much. Push the same record through `slog.NewJSONHandler` and through the handler you deploy and compare. A handler that builds a map, formats with `fmt.Sprintf`, or allocates a fresh output buffer per record will dominate; the built-in ones reuse a buffer from a `sync.Pool`, which is the bar to match.
  • What is the argument for keeping the raw payload off the line?
    Every attribute the handler renders is bytes it must escape and write. A multi-kilobyte buffer turns a small line into a large one on every record, and the built-in JSON handler marshals an untyped value through `encoding/json`, which renders a `[]byte` as base64. Log an identifier and a length and leave the payload where it already lives.
  • Would raising the stage's minimum level fix a hot Debug line on its own?
    Only partly. It stops the handler formatting and writing, which is the bulk of the cost, but the arguments to that Debug call are still evaluated and boxed on every record because Go evaluates arguments before the call runs. Guard the line with `logger.Enabled` as well if the argument is expensive to build.

saying these in an interview costs you the question

  • Rewrites the call sites before measuring anything
  • Calls Logger.With inside the per-record loop
  • Attaches the whole payload buffer to every line
  • Assumes a disabled level makes the call cost nothing
  • Never considers that the handler may be the allocator
  • Rewrites every log call in the service, hot or cold