Where to stand

(*processor).Execute is the convergence point for every GORM statement — creates, reads, updates, counts, deletes all pass through it. The upside of a convergence point is that one position covers everything; the downside is that it flattens the caller away, so on its own it cannot tell you who asked.

So this round loads that one function with all three signals — a count (line 82), a timed span (135 → 158), and verbatim content (line 139, pulling stmt.SQL.buf) — while the five call sites upstream carry one count each.

What I wanted to check is basic: three signals on the same function, do they speak about the same batch of events?

Three numbers

When the window closed, the three probes on that one function read:

count      (Execute:82)         1,888
verbatim   (Execute:139)        1,888
timed span (Execute:135 → 158)  1,652

The count and the verbatim content match to the unit: 8 × 236 = 1,888 — eight statement shapes, 236 of each, reconciling with the hit count.

The timer is 236 short.

My first thought was dropped events. The SDK's default limiter is 1,000 per second and this demo runs one round every three seconds — nowhere near it. And a drop should hit all three probes, not just the timer.

That number showed up earlier

On the same graph, the Read the first → one ORM execution edge carries a fanout of ×1.5. 472 calls, 708 executions, and the excess is 236.

The stacks draw it. Six frame chains reached the convergence point this round; five look like this:

goexit · main · main · Create · Execute     472
goexit · main · main · First  · Execute     472
goexit · main · main · Update · Execute     236
goexit · main · main · Count  · Execute     236
goexit · main · main · Delete · Execute     236

The sixth looks like this:

goexit · main · main · First · Execute · Preload · preloadEntryPoint · preload · Find · Execute   236

Execute appears twice on the same chain. A Preload expansion happens while the outer Execute has not returned yet — the inner one is nested inside the outer one's span.

A timed probe counts how many times a span closed. Those 236 nested executions never closed one: 1888 − 1652 = 236, the same count as the sixth chain.

A counter counts entries. A timer counts closes. Those are the same number right up until something calls itself.

And that p99 is eight statements stacked on one line

The timed side reports:

p50   5.232ms
p95  18.406ms
p99  67.321ms
max  80.272ms

p99 is thirteen times p50. And the distribution does not separate by statement kind — the INSERTs, the count(*), the Preload sub-query, the soft-delete UPDATE, all piled onto one line.

The verbatim probe answers half of it: there are eight candidates and all their shapes are on record. But knowing which kind is slow needs a timer on each upstream call site — which is exactly what a convergence point costs. One position covers everything, and in exchange it has one answer for "everything".

Being honest about it

Why the nested execution never closes a span, I did not measure. I measured the difference, and that the difference equals the sixth chain's count exactly. I have a guess at the mechanism, but no probe on it this round, so it stays out of the article.

"Not dropped events" is not something I can prove to the end. This demo is built against an SDK version that cannot report drops — the evidence pack says so itself: sampling.supported: false. What I can show is that the difference matches the nesting count too exactly to be loss. That is not the same as proving nothing was lost.

Five frames is a shorter stack than a real service has. The caller's name sits in the second-to-last frame because this demo's CRUD is written straight into main. A service with handlers and a service layer would give the same probe a much longer chain — the shortness is a property of this demo, not of the method.

Below the convergence point the graph is empty. The one ORM execution → statement out edge has zero unobserved frames because both probes live in the same function. The callback chain, the pool, the driver: none of it is on this picture.

What came out

With three signals on one line, the useful moment is not when they confirm each other. It is when they disagree.

The count and the timer differ by 236, and that 236 is not error, not sampling, not a misplaced probe — it is the trace of this function calling itself, and the only place it is visible is the stack. Each probe returned a correct number on its own. It was the gap between them that pointed at the fact nobody had written down.

What this round changed in the observed service: one blank import in 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. Eight probes across five functions, all attached after the process was already running.