Where the time actually went

Three rounds of optimization made the backend faster at what they targeted, yet a cached read still took 220 ms. A profile showed 94% of it was re-rendering JSON that hadn't changed.

Project
STP: Vehicle Cost Platform, part 9 of 10
Published
October 5, 2026
Reading time
3 min read

Optimizing what you expect to be slow is the easy part. The hard part is noticing that the time went somewhere else. In STP, three iterations made the backend faster at exactly what they targeted: graphs kept in memory, partial recomputation, several instances. Yet a cached read of a 20,000-part BOM still took about 220 ms, and none of those changes had been aimed at where that time went.

Measuring every version the same way

Before profiling anything, we built the measuring tool. back.perf bench generates BOMs of any size and shape (depth, share of parts with several parents, offers per part), runs the backend's real chain (parse, validate, save, publish, compute, cache, quote, API) against a disposable database, and reports medians. Each past version was checked out in its own git worktree and measured with its own copy of the tool, at 1,000 and 20,000 parts, 5 runs each, one version at a time.

The first table that came out of it was the one that mattered most. Every version, from the MVP on, computed exactly the same costs: 1,157,453.82 EUR at 1,000 parts and 41,541,375.82 EUR at 20,000. No optimization had changed a result.

1 ms10 ms100 ms1 swithout a revision: 468 ms22 msthe UI (sends its revision)5.8 msMVP41,541,375.82plan 1141,541,375.82plan 1241,541,375.82plan 1341,541,375.82plan 1441,541,375.82plan 15graphsin memory41,541,375.82plan 16partialrecompute41,541,375.82plan 173instances41,541,375.82plan 18responsekept41,541,375.82cost computed for the same 20,000-part BOM, in EUR✓ identical in every version
A cached read of a 20,000-part draft, version by version (log scale). The bottom row is what every version computed: the same cost, to the cent.

Faster where we looked, slow elsewhere

A profile of the remaining 220 ms gave an uncomfortable answer: 94% of a cached read was rendering the JSON of a result that was already computed, 9.5 MiB for 20,000 lines, serialized again on every request. Publishing had the same kind of surprise, with about 90% of its time spent on some 60,000 row-by-row INSERTs. And every autosave revalidated the BOM by rereading its parts from PostgreSQL (40,000 rows, ≈ 600 ms) while the backend already had them in memory.

cached read20,000 parts94%: rendering 9.5 MiB of JSON againbefore: ≈ 220 ms5.8 mskeep the rendered responsepublish a draft20,000 parts≈ 90%: some 60,000 row-by-row INSERTsbefore: 8.6 s2.2 sbatch them with unnestautosave validation20,000 partsrereading 40,000 rows of partsbefore: ≈ 600 msno rereaduse the parts already in memoryopen in the editor20,000 partswalking every edge per node1.4 million DOM elementsbefore: ≈ 19 s≈ 1.2 sindex once, render unfolded branches
Where the time went, and what was left after each fix. Each row has its own scale: the top bar is the time before, the bottom bar the time after.

Three fixes, measured

  • Keep the rendered response with the cache entry, bounded at 256 MiB. A cached read of 20,000 parts went from ≈ 220 ms to 5.8 ms (×45), and from 10.5 to 2.4 ms at 1,000 parts. The margin, which must be fresh, is grafted onto the stored bytes afterwards.
  • Batch the publication's inserts with INSERT … SELECT FROM unnest(…). That took publishing 20,000 parts from 8.6 s to 2.2 s (×4), and 1,000 parts from 441 to 117 ms.
  • Validate against the parts already in memory, which removed the 600 ms reread from every autosave.

One prototype didn't make it. Querying parts through a uuid[] index only gained ×1.1, because the time was in turning rows into objects, not in the query.

The UI had the same pattern. Opening a 20,000-part draft took about 19 s, because the editor's tree function walked every edge for every node it visited (7.7 s) and then rendered all 24,113 rows, about 1.4 million DOM elements. Indexing the structure once and rendering only unfolded branches brought it to about 1.2 s.

What we didn't fix

Same cached read, 30,000 parts, measured in the backend process and through the stack. Another instance doesn't shrink the response; compressing it, or sending detail lines on demand, would.
  • Memory peaks at about 680 MB for 20,000 parts, and an instance that has served a 30,000-part BOM reaches 1.3 to 1.7 GB.
  • Latency spikes: some cached reads take 600 to 800 ms instead of a few milliseconds, always the first one after a large computation. Our hypothesis is a full pass of Python's garbage collector, but we never verified it, so the report calls it a hypothesis and not a cause.
  • The response itself, at 30,000 parts. In-process, a cached read takes 11 to 29 ms, but through the stack it takes about 550 ms, because each response is 15 MB of JSON. Adding an instance doesn't help with that. Compressing responses, or sending the 30,000 detail lines only on demand, would.
  • Telemetry's own cost was never measured, since the bench runs without Kafka, and the report lists it as unknown.