Deciding where to stand

The program being watched is small: one process runs a gRPC server (grpc-go's stock health service) and a client, and every call goes over the same HTTP/2 connection. In the first part one goroutine calls 24 times a second; in the second, eight goroutines call 3 times a second each — the same total rate, with only the number of calls in flight changed.

All I wrote is one line, client.Check(ctx, req). Standing at that line, I can see that it came back; standing at the network card, I see bytes and not who sent them. So the probes sit in between: the calling line (One call), the server's handler (Handle the RPC), the line where grpc-go decides to send a PING after receiving DATA — one on the client and one on the server (Client sends a BDP ping, Server sends a BDP ping) — and the line that finally hands bytes to the socket (Write to the socket), capturing how many bytes it wrote.

I assumed a unary RPC on the wire was one request and one response. So why is the socket written five times as often as I make calls?

The first part: one caller

The window runs from 2026-10-05 13:50:45Z to 13:56:15Z. In the first part the program counted 3,452 calls of its own, and Handle the RPC reads 3,452. So far the ledger is level.

What is not level are the other three: Server sends a BDP ping 3,452 times, Client sends a BDP ping 3,451 times, Write to the socket 18,245 times. On every call, both sides sent a PING; the socket was written 5.3 times per call.

The ledger on the wire

The probes tell me something was sent, not what the wire looked like. So I ran the same program again with no probe at all and trapped only write from outside the process with strace, splitting every socket write into HTTP/2 frames. For the 2,880 calls of the first part, the two sides wrote these frames (tabulated from the decoded output):

                        client          server
HEADERS                 2,880           2,879
DATA                    2,880           2,879
HEADERS (trailers)          —           2,879
WINDOW_UPDATE           2,879           2,879
PING                    2,879           2,879
PING ACK                2,879           2,879

The part of a call I wrote is five frames: the client's HEADERS and DATA, the server's HEADERS, DATA and trailers. Six more are not in my program. One of the server's writes, byte for byte, is these 30 bytes:

00 00 04 08 00 00 00 00 00 | 00 00 00 0b                 ← WINDOW_UPDATE, increment 11
00 00 08 06 00 00 00 00 00 | 02 04 10 10 09 0e 07 07     ← PING

The increment of 11 is exactly the size of that request's DATA — the size=11 the probe captured. The PING's eight bytes are grpc-go's hard-coded bdpPing, with a comment left beside it in the source: "Easter-egg: what does the ping message say?" That payload appears 6,502 times in the whole capture, and so do the ACKs coming back.

This is grpc-go's BDP (bandwidth-delay product) estimator. The rule in bdp_estimator.go is simple: when DATA arrives and no PING is awaiting its reply, start a new round of estimation — send a WINDOW_UPDATE, then a PING, and when the ACK comes back, take one round-trip time. It only stops once the estimate reaches 16MB, which a service whose replies are a few bytes long never does.

Eight callers, the same rate

In the second part the program counted 3,960 calls. Server sends a BDP ping drops to 495 and Client sends a BDP ping to 496 — 3,960 ÷ 8 = 495. Write to the socket is down to 3,947, less than once per call.

The eight callers are driven by the same beat and arrive together every third of a second. The first request's DATA opens a round of estimation and sends a PING; the other seven arrive before the ACK comes back and are simply added to the same round's sample (that step is inferred from the source and the counts — nothing was watching who arrived first or when the ACK came back). A PING is once per round, not once per call — and with one caller, every round holds exactly one call.

The probe-free round agrees: of 2,880 calls in the second part, the client sent 381 PINGs and the server 361, against 2,880 ÷ 8 = 360 waves; the two sides wrote the socket 2,551 times in all, against 16,688 in the first part — the same 2,880 calls, 6.5 times fewer writes. Replies also start sharing writes — 28 of the server's writes carried three calls' HEADERS, DATA and trailers at once.

I assumed the wire cost of a gRPC call was fixed. Now I know it depends on how many calls share the connection at the same moment: at the same 24 calls a second, with one caller the control frames outnumber the data frames.

Being honest

Observation changes its rhythm, so the two sets of numbers are used separately. With one caller, the probes slowed each call enough that the program only reached 21 calls a second in the first part (3,452 against a target of 3,960); with no probe it made its full 2,880 in two minutes. The shape of the ledger — one round of PINGs per call with one caller, one per wave with eight — is the same in both; the frame types and counts are quoted only from the probe-free round.

Latency is quoted only from the control. The main window's call latency, p50 25.614 ms in the first part and 87.829 ms in the second, was almost entirely the probes' own cost. Another round timed only the calling line:

            first part (1 caller)   second part (8 callers)
p50         0.427 ms                0.537 ms
p95         1.123 ms                1.481 ms
p99         1.231 ms                1.969 ms

This round did not compare a connection with the PINGs against one without them, so how much the extra round trip costs a call, I did not measure.

The graph is five islands. Making the call, handling it, receiving DATA and deciding to PING, and writing to the socket each run on a different goroutine in grpc-go — the caller's own, the one the server starts per stream, one socket reader on each side, one loopyWriter on each side. Stacks do not cross a go func(), so there are no edges between them; what joins them is the counts: 3,452 = 3,452 = 3,452. Write to the socket carries both sides, which I separated by stack: 9,143 client writes and 9,102 server writes in the first part.

Whether it can be turned off is read from the source. Setting any initial window size in grpc-go (the client's WithInitialWindowSize / WithInitialConnWindowSize, the server's InitialWindowSize / InitialConnWindowSize) sets StaticWindowSize and the BDP estimator is never created. This round did not turn it off and rerun.

This is loopback. The round trip is under a millisecond, so the ACK always returns before the next call, which is why every call in the first part opens a new round. On a real network the round trip is longer, a round covers more calls, and the ratio will differ.

What I came away with

I now know that "one RPC" is not a fixed thing on the wire. At the same 24 calls a second, one caller makes both sides write six extra control frames per call and the socket get written almost six times; with eight callers sharing the connection, it takes eight calls to cost one round, and the socket is written less than once per call. The cost follows not how many calls there are, but whether they arrive together.

📊 This article's remote dashboard (measured data, viewable online): https://codebull-service-b7lha2dtrq-uc.a.run.app/public/grpc-frames-20261005/ On the Metrics tab the cumulative call count steepens where the second part starts (the first part was held to 21 calls a second by the observation); the Logs tab shows bytes=17 (PING / ACK), bytes=13 (WINDOW_UPDATE) and size=11, size=7 (the request and reply DATA that triggered a PING). (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 call counts the program prints are part of the demo and serve as the outside ledger). All six probes were attached after the process was already running: main.callOne:56 (count) and main.callOne:55–62 (timing), health.(*Server).Check:62, transport.(*http2Server).handleData:786, transport.(*http2Client).handleData:1215 (capturing size), and transport.(*bufWriter).flushKeepBuffer:369 (capturing w.offset). Latency comes from a separate control process timing only; the frame ledger comes from another process with no probe at all, run under strace --seccomp-bpf -e trace=write; both ran two minutes per part with the same program and flags. The program exits by design at the end of the window, so the observation tool reports the event stream as dropped; the last event is at 13:56:15Z.