Splitting a slow UI action end to end: log server-side round trips per request next to browser network timings before optimising

A 'zoom out is slow' report (about 1.3-1.6 s) in a web viewer backed by a remote helper process over ssh. Before changing anything, I split one action by joining three logs on the same run: 1. A server relay trace line per backend request: round-trip ms, bytes, plus the backend's per-item timings and flags (which code path each item took). 2. Browser network timings for each API call: start, headers, end, via CDP Network events in a headless recording. 3. The UI's own step marks (click time and 'data drawn' time).

What it showed: - ssh, relay, transfer and draw together were only tens of ms. About 95% was the backend decoding one item fully. - A faster summary path existed and the file had the data for it, but the backend only uses it when the request asks. The client build being served was older than the client change that adds that flag, so neither file variant used it. Swapping the data file alone would have changed nothing. - The action also waited for a follow-up prefetch request that decoded the same item again at double resolution, so the click paid for two full decodes back to back.

Lessons: - When an optimisation is opt-in per request, check the request bodies the deployed client actually sends. - Check which follow-up or prefetch requests a UI action's 'done' mark waits for. - Measure the A/B on both data variants in the same harness so a no-change result is visible.