Why here

An etcd write does not run down one straight line: gRPC takes the request, it becomes a raft proposal, it is persisted, it is applied as state — and each of those can sit on a different goroutine. The source tells you there is a go func(). It does not tell you how many disk writes one Put costs.

So six probes spread along the whole write path: kvServer.Put (take the Put), EtcdServer.Put (server API), processInternalRaftRequestOnce (raft proposal), wal.Save (WAL save — one counter, one timed span), applyEntryNormal (apply an entry).

Traffic runs in five phases: a minute with no client traffic at all, one write a second, one client flat out, two clients flat out, and reads only. The first and last phases are the controls — they tell you which numbers were never caused by your requests.

The request side: five sources, one number

Take the Put, Server API, Raft proposal and Apply an entry all read 9,472 — not one more, not one less. etcd's own /metrics says grpc_put_ok 9,472, mvcc_puts 9,472, proposals_committed 9,472. My client script counted 9,472 too.

Five independent sources, none of which has to trust another. That is not interesting in itself, but it is the floor everything else stands on: when a number finally disagrees, you know it really disagrees rather than having been measured wrong.

"How many times did the WAL write" has three answers, and all of them are right

The persist side is a different story. For the same stretch of WAL work there are three numbers:

times the wal.Save function was entered (probe, line 959)      22,555
times it actually ran to the end (timed span, from line 960)   17,404
fsyncs etcd counted itself (etcd_disk_wal_fsync…)               9,421

All three are correct, because they count three different things. Split by phase, you can see exactly where they diverge:

phase                client writes   Save entered   Saves per write   fsyncs per write
one write a second              87            174            2.000               1.00
one client flat out          3,867          7,734            2.000               1.00
two clients flat out         5,518          9,496            1.721              0.991

2.000 is structure; 1.721 is traffic. When it is idle, one write enters Save exactly twice — that is the shape of raft's Ready loop, independent of load, and it holds to two decimal places. Only once several clients arrive at the same time does it fall: proposals get merged into one Ready round and written together.

Batching is not an optimisation that switches on when things get busy. It is that only a busy system has anything to merge. That sentence was not read out of the source; it fell out of the ratio across three phases.

And it reproduces. An earlier round the same day, with four clients: 2.000 / 2.000 / 1.691. The first two phases are identical; the third moves with concurrency.

Then the last phase

The last minute sends reads only, no writes. Every probe on the write path ought to sit still.

Take the Put does stay at 9,472, and so does Apply an entry. But wal.Save climbs from 17,404 to 22,555 — 5,151 more.

And the number of reads the client sent in that phase is exactly 5,151.

One read is one wal.Save call. None of those 5,151 ever closed the timed span — the counter on line 960 stays at 17,404. Back in the source, the first thing Save does is:

if raft.IsEmptyHardState(st) && len(ents) == 0 { return nil }

A linearizable read goes through raft's ReadIndex, which produces a Ready round with no entries and an unchanged HardState. Save is entered, checks, and returns — without touching the disk.

The earlier round says the same thing: 4,480 reads, 4,480 extra Save calls. Both rounds to the digit.

The result

Read only "wal.Save was called 22,555 times" and you would think this five and a half minutes held twenty thousand disk writes. The real number is 9,421 — and 5,151 of those calls came from requests that never write anything.

A counter tells you how many times a piece of code ran. That is the only thing it promises. How often it ran and how often it did work are two different questions — and the way to tell them apart is not to read the source, it is to stop the traffic and watch which numbers stop with it.

📊 The remote dashboard for this article (real measurements, viewable online): https://codebull-service-b7lha2dtrq-uc.a.run.app/public/etcd-write-path-20260905/ The dashboard holds this run's full upload. The Metrics tab shows the slope changing at each phase boundary; the Behavior Graph tab is the interactive version of the figure above — drag the timeline into the last minute and WAL save is still moving while Take the Put has stopped. (The panel's time axis is local time, UTC+8, against the UTC window quoted here.)

What this round changed in the observed service: one blank import in server/main.go to pull the SDK into the binary, and -gcflags="all=-dwarflocationlists=true -N -l" to compile it. Not one line of business logic, no added logs, no counters. All six probes were attached after etcd was already running.