Deciding where to stand
gin's middleware chain is a classic "you think you know it". You write r.Use(requestID(), accessLog(), auth()) and a picture forms: the request passes through three middlewares in order and reaches the handler. But there are questions that picture cannot answer: does the chain advance three times or four? When a request is stopped, does the rest still run? When no route matches, does the chain run at all? The answers are not in the source. They are at run time.
Standing inside my own middleware, I only see the layer I wrote; standing outside http.Handler, I only see in and out. So the probes sit inside gin: ServeHTTP:667 counts what comes in, ServeHTTP:668–674 times the whole request, handleHTTPRequest:708 captures the route match as M={httpMethod} P={rPath}, Context.Next:189 counts every advance of the chain, and redirectTrailingSlash:782 counts trailing-slash redirects.
Traffic ran in five phases of 70 requests at one per second, changing one thing each time: A GET /health (200), B GET /nope (404), C PUT /health (405), D without a token (401, auth aborts), E GET /health/ (301, trailing slash). The client can count what it sent: 350 requests, 1,050 expected Next() calls, 70 redirects. The three numbers measured inside the server are identical.
What six minutes showed
The route probe recorded 350 rows, and deduplicated there are only four shapes: M=GET P=/health 140 times, /nope 70, PUT /health 70, /health/ 70. Five phases, four shapes — A (200) and D (401) are the same thing at the moment the route is matched. The router does not know whether you are about to be stopped.
The Match the route → Advance the chain edge on the graph reads 1,050 ÷ 350 = ×3. Split the window by phase:
phase outcome Next() calls per request
A 200 280 4
B 404 280 4
C 405 280 4
D 401 210 3
E 301 0 0No phase is 3. ×3 is the average of 4, 4, 4, 3 and 0: a property of what traffic those minutes carried, not of the code. And the three values answer the three questions: the engine advances once and each middleware once more, so it is four, not three; auth never calls c.Next() when it stops a request, so the missing one is exactly its own; and for the 70 redirected requests the chain never advanced at all — rate limiting, auditing, tracing headers, whatever you hang on the chain, none of it ran for them. The layer that writes the access log sits on that chain too, so the service's own log has no line for any of those 70 requests.
That edge is dashed and marked 0–4 unobserved frames: requestID, accessLog, auth, serveError. Those are the three middlewares I wrote. The graph knows they ran; I just didn't measure them.
I thought that was gin's cost
The end-to-end probe took 350 samples: 207 under 1 ms, 29 between 54.374 and 55.581 ms, and nothing at all between 6.506 and 54.374 — two separate plateaus. By phase, A through D all have p95 between 54.441 and 54.839; only E is 1.573, and none of its 70 requests went over 40 ms.
The causality seemed to write itself: E is the only path that does not run the middleware chain and the only path without the plateau, so the 55 ms lives in the chain. The story was so tidy I almost wrote it that way.
What stopped me was a sentence the timing probe attaches to itself: on average 5.2 other probes ran inside each interval it timed, and "comparing paths that run through different numbers of probes compares the probes as much as the code." Requests in A to C pass through five stack-collecting probes; E passes through two. "E is faster" and "E crosses fewer probes" are two ways of saying the same thing.
So I switched to a ruler that does not depend on the probes — the client's curl %{time_total} — with the same five phases at 50 requests each, building up from a clean process one layer at a time:
configuration stack probes p50 (all) >40 ms max
nothing attached 0 0.40 ms 0 / 250 2.0 ms
timing only 0 0.45 ms 0 / 250 1.4 ms
timing + one stack-collecting 1 0.62 ms 1 / 250 126.7 ms
five probes (the main window) 4 1.33 ms 15 / 250 56.8 msIn the two configurations where nothing collected stacks, none of 500 requests went over 2.0 ms. Add one stack-collecting probe and a slow request comes back; with four, there are 15. Timing itself is worth 0.05 ms (0.45 against 0.40). I nearly wrote "where my instruments are densest" as "where gin spends its time".
Being honest about it
This round's latency numbers describe only the instrumented process. p50 0.904 and p95 54.578 ms were really measured, but they are the cost of gin plus four stack-collecting probes. Of gin's own cost, all I can say comes from the zero-probe client numbers: p95 between 1.04 and 1.21 ms in all five phases. That is a different instrument at a different place (including the network round trip), so the two sets cannot be subtracted, and I won't.
I am confident that stack collection brings the slow requests; I am not confident how often. The direction across the four configurations is consistent and clean (0, 0, 1, 15), but the rate varies a lot between rounds: the same "timing plus one stack-collecting probe" gave 1/250 here and 31/300 in the previous round. So I state the direction and no rate. What mechanism sits under those 55 ms (or 126.7 ms) I did not measure, so I don't write about it.
This page replaces its previous version. That version removed the three probes on the chain, saw the tail stay, and concluded "the tail isn't me". But one of the two probes it kept was collecting stacks — it removed the probes on the chain, not the stack collection. Treat "observing" as one switch instead of something with structure, and that is the conclusion you get.
I cannot separate the three middlewares. They share one line, Next(), so the graph has one Advance the chain node and this page will not say which layer costs more. Separately, the observation tool's live tally recorded Take the request → Match the route as 349; reading the raw events back one by one, all 350 carry Take the request on their stack, and the graph uses the latter. This SDK build cannot report dropped events, so every count is strictly "times recorded" — but they match the client's own 350, 1,050 and 70 exactly.
Result
I started out believing two things: "three middlewares means the chain runs three times", and "the milliseconds I measure are this service's cost". The first is wrong — it is four, and it becomes 3 or 0 depending on the outcome. The second is wrong more thoroughly and harder to catch, because what it produces is a causal story that looks entirely reasonable.
I now know that once you can see, there is a second question: how do you know you are seeing the system and not yourself? Trying "observed or not" as one switch only tells you whether it has anything to do with you; to know which part of you, the observation itself has to be taken apart and measured — timing is one layer, stack collection another, and their prices differ by an order of magnitude.
This round's remote dashboard no longer holds any data, so this page has no link to it; the interactive graph at the top is this round's complete read, and its timeline can be dragged onto any phase.
What this round did to the observed service: one blank import in main.go to link the SDK in, and a build with -gcflags="all=-dwarflocationlists=true -N -l". No business logic changed and no log lines or counters were added. All five probes were attached after the process was running, and all except the timing probe collect stacks. Window 2026-09-08 12:16:51.894Z → 12:22:48.151Z. Each of the four control configurations ran once; "nothing attached" was measured after restarting the process to a clean state (3 requests produced 0 events, copy budget back at 20/20), and the other two were added back onto that process one layer at a time.