Deciding where to stand

goleveldb is a key-value store that lives inside your process. There is no network boundary: no slow query log, no packets to capture. db.Put(key, val, nil) returns nil, and everything in between happens on the same process's stacks. Its documentation says concurrent writes are "merged" — one caller takes the write lock and writes the queued callers' data along with its own.

The program being watched is small: 24 writes a second, 1KB each, written by one goroutine for four minutes and by eight goroutines for the next four, at the same total rate. Each of the eight writes 3 a second, driven by its own ticker.

The probes sit at four places on the write path: the line where Put comes in (Call Put), the line in putRec where a merged caller gets its reply and returns (Handed to someone else), the first line of writeJournal (Write the WAL), and the first line of unlockWrite (Release the lock and reply). That last one captures its own argument merged — how many other callers' writes the lock holder carried on this trip.

I assumed that when eight callers arrive together, one of them takes the lock and writes the other seven. So merged should mostly read 7 — shouldn't it?

The first four minutes: one writer

The window runs from 2026-10-05 07:01:53Z to 07:09:53Z. In the first four minutes the program counted 5,755 writes of its own; on the graph Call Put reads 5,755, Write the WAL reads 5,755, and merged was 0 all 5,755 times. Every write took the lock itself and wrote the WAL itself, 5,755 ÷ 5,755 = ×1.00. Nobody to merge with, and no surprises yet.

Every wave, two people

In the last four minutes the program counted 5,760 writes, and Call Put reads 5,760; Write the WAL drops to 1,440 and Handed to someone else reads 4,320. 1,440 + 4,320 = 5,760: either you write it yourself or someone carries it for you.

merged is no longer only 0 — but it is almost never 7:

merged (carried along)   times
0                         691
6                         691
1                          29
5                          29

They come in pairs, and 691 + 29 = 720 — four minutes, eight writers at 3 a second each, exactly 720 waves. I lined up the Release the lock and reply events by time: all 691 merged=6 events come right after a merged=0, 6 to 37 milliseconds later; all 29 merged=5 come right after a merged=1, 6 to 34 milliseconds later. Waves are at least 273 milliseconds apart.

The last seconds of the window on the panel's Logs tab, verbatim (panel time is UTC+8):

[15:09:50.104] leveldb.(*DB).unlockWrite:141   merged=0 overflow=0
[15:09:50.134] leveldb.(*DB).unlockWrite:141   merged=6 overflow=0
[15:09:50.436] leveldb.(*DB).unlockWrite:141   merged=0 overflow=0
[15:09:50.465] leveldb.(*DB).unlockWrite:141   merged=6 overflow=0

So every wave has the same shape. The first caller takes the lock with nobody behind it and writes the WAL alone; by the time it lets go, the other seven are waiting, one of them takes the lock and writes the remaining six along with its own. Two WAL writes, six carried. The ledger closes: 691×1 + 691×7 + 29×2 + 29×6 = 5,760, exactly what the program counted itself; and merged sums to 4,320, which is exactly what the other probe, Handed to someone else, counted.

Why the first caller carries nobody can be read in the source: writeLocked only takes callers who are *already waiting* at that instant (a select with a default), and it does so before writing the WAL. Eight tickers fire almost together; at the instant the first caller wins the lock, the others are most likely still on their way (that step is inference — see the honest section).

I assumed merging meant one caller writing for everyone. Now I know it writes for whoever is already at the door when it gets the lock — and eight callers who arrive "together" are, to the lock, two groups.

And what does merging cost?

Merging is not free: a carried caller waits for the lock holder to finish the whole batch before it gets its reply. I meant to read that straight off the main window's One write timing: p50 3.690 ms in phase A, 14.649 ms in phase B, four times slower.

Most of that number was me. I ran the same program again with no probe inside leveldb at all, keeping only the caller-side timing:

                     phase A (1 writer)   phase B (8 writers)
p50                  0.108 ms             0.158 ms
p95                  0.156 ms             0.298 ms
p99                  0.198 ms             0.394 ms

Merging costs 0.05 ms at p50, not several milliseconds. In another round with a single probe on putRec's merged branch — a line phase A never reaches — phase A's p50 still went to 1.429 ms: once a probe is attached, the whole function is swapped for a copy, and the copy is slower whether or not that line runs. So no millisecond figure from the main window is compared anywhere in this piece.

Could "two per wave" be my doing too? If observation stretches how long the lock is held, more callers end up waiting at the door. I reran it under two lighter setups: counting only, no stacks — 1,438 WAL writes in phase B; no probe inside the lock at all, only counting the carried callers — 5,760 − 4,321 = 1,439. In the last round nothing was attached to leveldb, and I watched only the write calls into the journal file from outside the process with strace: phase B is still dominated by "one record, then seven" (572 one-record writes, 638 seven-record writes), except the two writes of a wave are about 0.5 ms apart instead of 6 to 37. The shape is leveldb's; the spacing was mine.

Being honest

The graph is rebuilt from the raw events. Both the observation tool and the panel drew an edge that cannot exist: Handed to someone else → Write the WAL. A merged write returns at line 334 and never reaches the WAL; but every WAL write's stack passes through putRec (at line 362), and the tool matches stack frames by function name alone. The recorded stacks carry line numbers, so this graph is rebuilt matching function and line: all four edges are backed by stacks, and no other edge turns up. The dashed Call Put → Write the WAL edge skips two frames, putRec and writeLocked, which I did not probe.

"The others are still on their way" is inferred from the source and the timestamps, not measured. What I measured is two lock holders per wave, 6 to 37 ms apart; nothing was watching when each caller reached the door.

The 720 waves are my tickers' doing. Eight writers driven by the same beat arrive together every third of a second. Real traffic is not that tidy, and merged would spread out more — the 29 waves split 1+5 are what slightly staggered arrivals look like.

Observation changes its rhythm. As above: in the main window the two lock holders of a wave were 6 to 37 ms apart; with no probe, about 0.5 ms. "Two per wave" held under all four observation setups, but the exact 691/29 split was only measured in the round with probes; the probe-free round is decoded from the byte sizes of journal writes, and some writes split at a 32KB block boundary do not reassemble, so only its shape is quoted, not its counts.

These WAL writes are not fsynced. The program passes nil write options, so sync is false and writeJournal returns once the record is handed to the operating system. With synchronous writes each WAL write would cost something else entirely, and this round did not measure it. Compaction is outside what was observed.

What I came away with

I now know that "at the same time" is not a moment to a write lock; it is an order. The WAL writes merging saves are real — 5,760 down to 1,440 in this round — but how many it saves depends on how many callers are standing at the door at the instant the lock is taken, not on how many arrived in the same second.

📊 This article's remote dashboard (measured data, viewable online): https://codebull-service-b7lha2dtrq-uc.a.run.app/public/leveldb-write-merge-20261005/ On the Metrics tab the cumulative line for writeJournal bends at the moment phase B starts, and the Logs tab shows merged=0 and merged=6 arriving in pairs. The panel's own Behavior Graph tab still carries the extra Handed to someone else → Write the WAL edge, for the reason given above. (The panel's time axis is local time, UTC+8, against the UTC window quoted here.)

What this round changed in the observed program: one blank import in main.go to bring the SDK into the binary, and a build with -gcflags="all=-N -l -dwarflocationlists=true". No business logic was touched and no log line or counter was added (the per-phase counts the program prints are part of the demo and serve as the outside ledger). All five probes were attached after the process was already running: leveldb.(*DB).Put:372, putRec:334, writeJournal:19, unlockWrite:141 (capturing merged and overflow), and the timing on main.writeOne:54–58. The latency comparison comes from a separate control process (from 07:16:41Z, timing only); two more control rounds carried only stackless counting probes, and one ran with no probe at all under strace --seccomp-bpf -e trace=write. All five rounds used the same program, flags and traffic (-rate 24 -a 4m -b 4m -workers 8).