Where to stand

A PUT comes in, the handler reads the product, changes a field, saves it back — three lines of Go. But this is three frameworks stacked: Gin's handler, GORM's ORM, database/sql's pool, the MySQL driver. Every layer might do a little extra on its own, and none of them will say so.

Standing inside my own handler is the easy choice and the wrong one: the handler knows it called Save(), not how many statements that one call turns into. So the probes bracket it — three at the top (edit a product, read it first, save it back), and at the bottom, right at the driver's doorstep: mysqlConn.QueryContext and ExecContext. That is the last gate before a statement leaves the process; past it there is only the network.

The traffic is deliberately split in two phases, 240 requests each, one per second, changing exactly one thing: the first four minutes send the product straight back the way GET returned it, nested category and supplier objects included; the last four send {"quantity":N} and never mention an association at all.

Predictable up front: 480 PUTs, 480 Saves. Not predictable: how many statements reach the doorstep, and whether the second phase sends fewer.

What eight minutes showed

The ratios landed first: 1440 ÷ 480 = 3 and 1443 ÷ 481 = 3. One edit, three reads and three writes — six statements.

The three writes read like this (verbatim from the panel):

UPDATE `products` SET `name`=?,`description`=?,`price`=?,`quantity`=?,`category_id`=?,`supplier_id`=?,`created_at`=?,`updated_at`=? WHERE `id` = ?
INSERT INTO `categories` (`name`,`created_at`,`updated_at`,`id`) VALUES (?,?,?,?) ON DUPLICATE KEY UPDATE `id`=`id`
INSERT INTO `suppliers` (`name`,`contact`,`created_at`,`updated_at`,`id`) VALUES (?,?,?,?,?) ON DUPLICATE KEY UPDATE `id`=`id`

The only thing I meant to change is quantity, in the first one. Two tables nobody intended to touch were written 480 times each.

And the stack on the write side prints the reason outright. This is its deepest chain, 169 of them (package prefixes dropped, along with the five observer frames at the top):

UpdateProduct · UpdateProduct · Save · DB.Save · processor.Execute
  · SaveBeforeAssociations · saveAssociations · DB.Create · processor.Execute · Create.func1
  · Tx.ExecContext · execDC · withLock · execDC.func2 · ctxDriverExec · ExecContext

SaveBeforeAssociations → saveAssociations → Create. Those two INSERTs are not mine — Save() stores the associations before it stores the row. Those three frames in the middle are the whole answer, and they are not in my code, and not in my logs.

I thought the front end was sending them

The explanation is a comfortable one: the browser takes the nested JSON that GET returned, changes a number, and PUTs the whole thing back, so the object GORM receives has category and supplier hanging off it and of course it stores them too. On that account, leaving the associations out of the body should make those two statements disappear.

That is what the second phase is for. Same one-per-second cadence, same 240 requests, body reduced to a single field.

It did not move.

phase                       PUT    UPDATE products   INSERT categories   INSERT suppliers      p50
A  whole nested JSON        240          240               240                240        18.011ms
B  {"quantity":N} only      240          240               240                240        17.441ms

Six statements, not one missing, and every count identical. The body went from a full object to one field, and the database side could not tell.

The reason is on the read side's stack: FindByID is Preload("Category").Preload("Supplier").First(...), so the object the handler holds already has both associations attached before the body is ever read. ShouldBindJSON overwrites the fields it was given; it cannot clear the ones it was not. What the front end sends was never the variable here.

Being honest about it

"The Preload is where those objects come from" is read off a stack, not measured. What I measured is that the body makes no difference, and the chain shows Preload → preloadEntryPoint → preload → Find. A real control would drop that Preload and run again, and that means editing the source — which this round does not do. So this step stops at "the stack says so".

The doorstep shows shape, not values. The ? in those three writes is a ?. I can see which columns were rewritten and not what they were rewritten to. That UPDATE even writes created_at back — the shape has something to say, and I have no number to say it with.

The two entry edges read 479, not 480. Both downstream steps were hit 480 times, but only 479 carried the entry frame on their stack. The graph draws what was measured rather than rounding it up.

The read side is 481, not 480. The extra one is 1.3 seconds before the window opened: the traffic script has to GET the product once before it has a nested body to send. It is on the graph, because it happened.

The top five frames of the deepest chain are me. Of the "25 deep" the panel reports, five are trap.Handler → HarvestPoint → GetOriginalPC — observation scaffolding, which I stripped out of the code block above. Observing is not free, and it cannot even hide on a stack.

What came out

I now know those two INSERTs have nothing to do with what the front end sends — they are that one Preload's bill, settled two lines later. I would have written it up as a front-end problem, because that explanation is both plausible and cheap for me.

And none of it says a word on a panel: the two phases' curves lie on top of each other, the p50s differ by 0.57 ms, and no bucket in those eight minutes looks wrong. Halving the body and running another four minutes took less than five minutes of my time, and it turned a "that must be it" into a "that is it".

📊 The remote panel behind this article (measured data, viewable online): https://codebull-service-b7lha2dtrq-uc.a.run.app/public/inventory-fanout-20260908/ The Behavior Graph tab is the interactive version of the diagram above — its timeline reads events in span 4,804 and 1,443 ÷ 481 = ×3.00; the Logs tab lets you reconcile the six statements verbatim; the Flamegraph tab is the 25-frame chain quoted above. (The panel's timeline is local time, UTC+8, matching the UTC window in the text.)

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. All six probes were attached after the process was already running, across five functions — two of them inside go-sql-driver/mysql, a package I have never written or edited.