jvq Blocks a Go Logging Change That Added Two Allocations to Every Request

An access logger writes one JSON line per request. In Go, the usual way to make that cheap is to append into a buffer the caller owns: no fmt, no encoding/json, no strings built along the way. Done right, the benchmark says 0 allocs/op, and the garbage collector never hears about the logger at all.

That property is easy to lose and hard to notice. Time per call wanders by several percent from run to run on a CI machine. An allocation count doesn’t wander. That’s why jvq compares allocations exactly, and why their budget can be an amount, here 0, instead of a percentage. This worked example is a small Go package set up to show it, with two real commits run through jvq 0.5.0 on a two-core cloud VM.

Both runs compare the branch with main. Progress lines left out.

The Setup

logline.Append(dst []byte, e *Entry) []byte writes the timestamp, service, method, path, status, latency and size. Its benchmark reuses one buffer, so a clean run shows 0 B/op and 0 allocs/op. The jvq.toml builds the test binary once per side and holds allocations at zero:

build   = "go test -c -o bench.test ."
command = "./bench.test -test.run=NONE -test.bench=. -test.benchmem"

[budget]
time   = "5%"
allocs = "0"   # the logger runs on every request: no new allocations

The Change: Redact Reset Tokens

Password reset links carry a token in the path, and tokens shouldn’t sit in logs. The pull request adds a redact step before the path is written:

func redact(path string) string {
	parts := strings.Split(path, "/")
	for i := 1; i < len(parts); i++ {
		if parts[i-1] == "reset" {
			parts[i] = "***"
		}
	}
	return strings.Join(parts, "/")
}

It’s correct, it has a test, and it reads well. It also runs on every path, including the great majority that have no token. Split makes a slice and Join makes a string, every time.

jvq measured 591 ns before and 948 ns after: +60.0%, interval +50.8% to +69.7%, over the 5% budget. Allocations went from 0 to 2 per call and bytes from 0 to 104. The build failed twice over, and jvq’s summary said why in one line: BenchmarkAppend allocs: +2 over the limit of 0.

The Fix

A simpler redaction that looks for the one thing it cares about first. It drops everything after /reset/ instead of replacing one segment, which is all a reset link needs:

func redact(path string) string {
	if i := strings.Index(path, "/reset/"); i >= 0 {
		return path[:i] + "/reset/***"
	}
	return path
}

A path without a token comes back untouched, with nothing allocated. jvq measured -2.7%, interval -10.7% to +4.2%, and allocations 0 before and 0 after. Pass.

Why the Allocation Gate Matters More Than This Example Shows

Here the time regression was large enough to fail on its own. Often it isn’t. One small allocation adds little time to a single call, and that little can hide inside the noise of a shared runner, where jvq would rightly call the time result a pass or inconclusive. The cost shows up later and elsewhere: more garbage, more frequent collections, longer pauses for every other request in the process. The allocs budget catches that case every time, because 1 is more than 0 on any machine.

The reference has the budget syntax, including budgets for single benchmarks. The quick start has the CI setup.