Timeline

The multiplication sign in 'zit 34.1ms×2' never matched a byte compare, so the duration parsed as zero and the store note appeared beside an identical zit figure — claiming a wait already accounted for. check-in: 433a022052 user: quarry tags: trunk

A call on context.Background() carries no timer, so a page blocking six seconds on a warm pass reported 'ops 11.09s, zit 32.9ms' — and the ops panel's claim that ops minus zit is index work was false while it did. Overlap catches what attribution misses: subprocess busy time inside the render window, unioned, reported only when it exceeds what was already attributed. check-in: 17454ef71f user: quarry tags: trunk

quarry could not answer two questions about its own behaviour. A render time was printed in the page footer and discarded, so a 4.24s files page was visible only to whoever loaded it and read the footer. Subprocess load was visible nowhere: a warm loop once ran 134 concurrent `zit ls --long` against the same hash, load average 546 on 14 cores, and /fleet said "all healthy" throughout.

/fleet/ops, site-admin only. Slowest routes by p95 — a mean hides the tail, and the tail is the thing worth finding. Store subprocesses rolled up per verb, with the number that actually mattered: how many run at once, and the peak, which outlives the incident. Recent renders with ops time and the zit time inside it.

Instrumented at the two seams that cover everything: the ops registry, which every page's data crosses, and the outermost middleware, which is the only place the template's own cost is known — the footer's breakdown is assembled before the template runs, so a page can never report the time it spent rendering itself.

Datastar with no no-script path, deliberately: an internal dashboard that cannot move while an operator watches a fleet index is worth much less than one that can, and no consumer depends on it. The op behind it is registered and versioned like any other.

The rings are small and in memory. This is the snapshot; history belongs in the analytics store behind obs.Sink, which is an interface with a no-op default so the persistent implementation can be cgo without the request path importing it. closed check-in: 022966bc05 user: dmestas tags: fleet-ops

A diff is two zit subprocesses on purpose, run at once. Adding their durations printed more time than the whole request took — "rendered in 410.1ms (zit 706.8ms×2)", and "79.94s (zit 159.05s×2)" on a cold tcl page. A number larger than the total reads as a broken page rather than as two calls overlapping.

Record now takes the start instant instead of a duration, because a duration cannot say whether two calls overlapped, and the union of the spans is what a reader actually waited. closed check-in: 4aaf089616 user: dmestas tags: timing-wall

Nothing in quarry limited concurrency — every zit subprocess ran in the request goroutine with the arrival rate as the only bound. work.Lane is a concurrency limit plus a queue cap that SHEDS past it: a request accepted into a queue it cannot be served from consumes the capacity that would have served someone else.

Wired to archive first, which buffers 256 MiB per request on an anonymous route. That is latent rather than live — archive 503s on zit#97 — which is why the bound belongs there now, so the endpoint is born bounded rather than acquiring a limit after someone finds it.

Footer precision: '<1ms' was true and useless once most pages went sub-millisecond, collapsing the interesting range into one label. timing.Format keeps ~3 significant figures across five orders of magnitude, so 900µs and 90µs no longer read the same. Fossil has the mirror-image bug: three decimals of seconds prints everything faster than a millisecond as 0.000s. check-in: 45bb75ade2 user: dmestas tags: trunk

The footer said 'rendered in 344ms'; it now says 'rendered in 344ms (zit 270ms)'. One number says a page is slow, not which layer to look at, and quarry's layers differ by three orders of magnitude — an index read is microseconds, zit ls --long on tk is 2.6 seconds.

The accumulator rides the request context, which is what makes it correct under load: package-level counters would blend concurrent requests together, and concurrency is what this exists to measure.

zit read calls take a context now and use exec.CommandContext, so an abandoned request kills its subprocess instead of leaving it to finish a 2.6-second listing nobody will read.

SQL is not instrumented yet; the index does not take a context. check-in: 85b9909d1c user: dmestas tags: trunk