Where to stand

An ORM's black box is always the same shape: the line of Go you wrote, and the statement that actually leaves the process, with a layer in between. The chained calls expand at run time, and nothing tells you how many statements that becomes, or what shape they take.

Counting calls inside my own code is the easy half — I know I called Delete(), I do not know what it turned into. So the probes bracket it: five call sites at the top, one count each (Create, First, Update, Count, Delete), and at the bottom the convergence point every statement passes through, (*processor).Execute, carrying three signals on one function — a count, a timed span, and a log point pulling stmt.SQL.buf out verbatim.

The top counts "how often I asked". The bottom counts "how often it ran, and what came out". The difference is what this layer adds on its own.

Predictable up front: how many times each call site runs. Not predictable: whether they add up to the bottom, and what those eight statements actually look like.

What eleven minutes showed

The call side landed first. 236 rounds, each with two Creates, two Firsts, and one each of Update / Count / Delete:

Create a row      472      = 236 × 2
Read the first    472      = 236 × 2
Update one field  236
Count the users   236
Delete the oldest 236
                     ————
calls              1,652

The convergence point was entered 1,888 times. 1888 − 1652 = 236 — exactly once per round.

The graph says where those 236 went: the Read the first → one ORM execution edge carries a fanout of ×1.5 (708 ÷ 472), while the other four are all ×1. The edge also names the frames in between: Preload → preloadEntryPoint → preload → Find.

One line of db.Preload("User").First(&found, order.ID) expands into two executions at run time. That ratio is written in no line of code.

I thought Delete sent a DELETE

Eight statement shapes, deduplicated, with the count of each:

INSERT INTO "users"  (…)                                                     236
INSERT INTO "orders" (…)                                                     236
SELECT * FROM "orders" WHERE "orders"."id" = $1 AND … ORDER BY … LIMIT $2    236
SELECT * FROM "users"  WHERE "users"."id"  = $1 AND "users"."deleted_at" IS NULL   236
SELECT * FROM "users"  WHERE "users"."deleted_at" IS NULL ORDER BY created_at asc … 236
SELECT count(*) FROM "users" WHERE "users"."deleted_at" IS NULL              236
UPDATE "users" SET "age"=$1,"updated_at"=$2 WHERE … AND "id" = $3            236
UPDATE "users" SET "deleted_at"=$1 WHERE "users"."id" = $2 AND …             236

8 × 236 = 1,888, matching the convergence point's hit count exactly.

Two INSERTs, four SELECTs, two UPDATEs. No DELETE.

It took me a moment staring at that list. The last line *is* db.Delete(&oldest). It does not take the row away; it writes a timestamp onto it.

UPDATE "users" SET "deleted_at"=$1 WHERE "users"."id" = $2 AND "users"."deleted_at" IS NULL

This is written in the type — User embeds gorm.Model, and that carries a DeletedAt. You can read it off the struct. I did not read it off the struct. I found it on a list with no DELETE on it. And the same fact's shadow is all over that list: six of the eight statements drag a deleted_at IS NULL behind them, count(*) included. I did not write that WHERE either.

And it comes back around

User.Email carries a uniqueIndex. That UPDATE never touches email — it writes deleted_at and nothing else.

So none of those 236 "deleted" users gave their email back. For this demo that is fatal: it mints users as user{n}@demo.com with a counter that resets when the process restarts, while last run's addresses are still sitting in the unique index. On the next start, Create collides from the very first round.

That part is inferred, not measured: the process did not restart inside these eleven minutes, so I never saw the collision. What I measured is that the UPDATE writes only deleted_at; the rest follows from it plus the uniqueIndex.

None of this is GORM doing something wrong — soft delete is exactly this semantics, and it declares it in the type. But "delete" does not mean the same thing in your code as it does in your database, and the layer in between does not volunteer the difference.

Being honest about it

I saw what GORM sent, not what PostgreSQL received. The convergence point sits on the ORM side; database/sql and the driver carry no probes this round. Confirming those eight statements leave the process unchanged means standing one layer lower.

How big the table got, I did not measure. The section above is read off the statement's shape: the UPDATE writes only deleted_at, so the row stays. No probe counted rows, so no table size appears anywhere in this article.

Below the convergence point the graph is empty. The one ORM execution → statement out edge is ×1 with zero unobserved frames because both probes sit in the same function; the genuinely deep part — the callback chain, the pool, the driver — is simply not on this picture. A graph that will not say where it stopped looking gets read as a complete one.

That edge reads 1,887, not 1,888. The convergence point was hit 1,888 times, but only 1,887 of them carried it on the downstream stack. The graph draws what was measured rather than rounding it up.

What came out

I now know that Delete() names my intent, not what the database receives — and I know it from a list that was missing a statement type, not from reading the source.

Eight shapes, 236 each, matching 1,888 executions to the unit. That tidiness is not the achievement; it is what leaves the one anomaly nowhere to hide. When every number reconciles, the one that doesn't is the story.

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.