Plot grid first render blocks the shared IOLoop, superlinearly in cell count

[SimonHeybrock]

A plot grid's first render blocks the dashboard's shared Tornado IOLoop, and the block grows faster than the number of cells in the grid. At 24 cells -- a legal grid, the size widget allows 2-6 rows by 2-6 columns -- one session switching to the grid tab makes every other session on that server unresponsive for 11 seconds.

This is the residual of #1185 after PR 1197 fixed the colormap cold start that dominated it. It was previously assumed to be a first-paint latency for the rendering user only; measuring from a second, idle session shows it is server-side and shared.

Measurements

Fake backend, dummy fixture, Detectors grid expanded to N 1x1 cells, idle 24-core machine. Two browser sessions: one renders the grid, the other sits idle on the Workflows tab and probes. The idle session's fetch latency is a server-side measurement -- its own main thread is idle, which its setInterval lateness (<= 8 ms throughout) confirms.

cells	models in doc	server block (seen by the idle session)	client block (renderer's own main thread)
3	267	0.7 s	1.9 s
6	489	0.9 s	4.3 s
12	937	2.8 s	13.9 s
24	~1900	11.1 s	17.6 s

The client column is the browser-side cost of instantiating the model tree. It is far larger, but it is a per-user cost and belongs to #1055, whose "switch into plot tab" target reports 1.7-1.9 s of blocked main thread with 4 plots -- consistent with the 3-cell row here. This issue is about the server column.

Server-side accounting matches the observed block. At 12 cells:

[passprof] tab_switch 444ms (wall) models 84->325
[passprof] pass full=True handlers=4 models=325 inner=1632.9/1508.0ms freeze_exit=59.1/55.9ms hold_exit=615.7/537.2ms (wall/cpu)

444 ms + 2.31 s = 2.75 s against 2.78 s measured from the idle session. inner is entirely PlotGridTabs._poll_for_plot_updates; hold_exit is event dispatch and serialization; freeze_exit is bokeh's model-graph recompute.

Steady state scales too. One session on a 12-cell grid costs ~200 ms of handler plus ~40-60 ms of freeze-exit per 1 Hz data tick -- about 25% of a core, per session, per grid. The unconditional 5 s full pass costs 40-68 ms of freeze-exit at 937 models with inner=0.2 ms, i.e. bokeh recomputing the model graph for a pass that changed nothing.

What a cell is made of

74 models per cell, from diffing the document's settled model census at 3 cells against 6 cells (222 models for 3 extra cells). Grouped by what owns them:

group	models/cell	what
bokeh plot internals	~37	figure, two axes (each with ticker, formatter, label policy, scale, range, grid), title, glyph renderers, ColumnDataSource + view + selection objects, colorbar + mapper, legend, box-select annotation
bokeh toolbar	~18	pan, wheel zoom, box zoom, reset, save, hover, a CustomAction, the ToolProxy objects GridPlot's toolbar merging adds on top, and a Tooltip/TooltipIcon per tool
our Panel chrome	~19	6 HTML panes, 3 SVGIcon, ~2 Button, ~6 Row/Column, Spacer, Dropdown -- the cell titlebar

Half the models in a cell are not the plot. A quarter is a full interactive toolbar on a tile that can be a couple of hundred pixels wide; a quarter is the titlebar we build ourselves. Both are app-side choices.

One concrete piece of waste inside the plot group: every GlyphRenderer instantiates four glyph objects, the real one plus copies a live monitoring view never displays.

[census] glyph_variants {'glyph': 'Image', 'selection_glyph': 'Image',
                         'nonselection_glyph': 'Image', 'muted_glyph': 'Image',
                         'hover_glyph': 'NoneType'}

That is 16 of the ~110 plot-internal models per 3 cells. It is a bokeh default, so the question is whether holoviews can be told not to populate them.

Caveats: the synthetic grid cycles the fixture's three cell templates (two single-layer image cells, one two-layer lines cell), so 74 is an average over a slightly heavier mix than a pure image grid; and because the census covers the whole document, models are grouped by type rather than attributed to an individual widget. ToolProxy at ~3/cell means the GridPlot toolbar merging adds models rather than replacing the per-figure tools -- worth confirming before treating merging as a saving.

Open question

What makes it superlinear. Per-cell work inside the pass looks roughly linear from 3 to 12 cells (tab_switch 130/245/490 ms; inner 377/703/1633 ms), yet the measured block goes 0.9 -> 2.8 -> 11.1 s from 6 to 24. Either something in the pass is O(cells^2) only at larger sizes, or the block at 24 cells spans several passes. Instrumenting a 24-cell run is the first step -- it was not captured here because the tour driver's fixed wait window is too short at that size.

Directions

• Chunk cell materialization across ticks so no single pass holds the loop for seconds. Does not reduce total work, but bounds the block, which is the point.
• Skip the freeze-exit recompute on full passes where no handler mutated anything. Small in absolute terms (<1% duty), but it is pure waste and grows with document size.
• Reduce models per cell (74 at present, see the breakdown above): drop or share the per-figure toolbar, slim the titlebar, suppress unused glyph variants. Pays off on both the server and, much more, the client.

Reproducing

Harness and usage notes: https://gist.github.com/SimonHeybrock/e99259966da78a49a8225cd0a470ff9d

export PLAYWRIGHT_CHROMIUM_EXECUTABLE=/usr/bin/chromium   # devcontainer only
python grid_stall.py --mode observer --cells 24           # server vs client split
python grid_stall.py --mode tour --cells 12               # per-step + server instrumentation
ESSLD_CENSUS=1 python grid_stall.py --mode tour --cells 6 # model census; diff two cell counts

Run from the repo root on an otherwise idle machine: under CPU oversubscription the loop's scheduling delay dominates and swamps the effect.

Two measurement traps, both hit during this investigation:

• A fetch probe in the rendering page cannot separate a blocked server loop from a blocked browser main thread -- both delay the round trip. Probe from a second, idle session.
• Tornado's request_time under-reports a blocked loop: a loop that cannot read the socket has not started the clock. It showed 349 ms while the loop was in fact blocked for 2.8 s.

[SimonHeybrock]

The open question: it is not superlinear, it saturates

Instrumenting a 24-cell run (in-server IOLoop stall monitor + per-phase timing, so no second session is needed) shows the premise of the "superlinear" reading is wrong. The pass is roughly linear in cells. What changes at 24 cells is that the per-tick cost crosses the tick period, after which the loop never goes idle again — and a block measured in a fixed observation window is then bounded only by the window. The 11.1 s at 24 cells was 20 s of waiting, not a block that ended.

At 24 cells the loop stays saturated for as long as the browser is attached: passes of 0.6–1.4 s recur back-to-back at the 1 Hz data rate, for the full 80 s the earlier run watched. Every other session on the server is degraded for the whole time, not for 11 s.

Steady state, per data frame

Idle 24-core machine, fake backend, dummy fixture, one session on the grid unless noted. Two layers per cell (fixture template mix). pass is handler + freeze-exit + hold-exit.

grid	models (settled)	pass, wall	duty at 1 Hz	handler CPU per layer
3 cells	307	93 ms	9 %	13.0 ms
6 cells	567	169 ms	17 %	11.8 ms
12 cells	1091	347 ms	35 %	11.9 ms
24 cells	2139	1056 ms	106 %	17.1 ms
12 cells x 2 sessions	1091 each	411 ms each	82 %	13.8 ms
12 cells x 4 sessions	1091 each	435 ms each	174 %	13.6 ms

Linear cost, plus a modest per-unit inflation near saturation: 3 -> 12 cells is flat at ~12 ms of handler CPU per layer, and at 24 cells it is 17 ms. Two experiments separate the causes. Two sessions of 12 cells put the same object count in the process as one 24-cell session, with half the cells per pass: per-layer cost stays at 12-cell levels, so it is not the process heap. Four sessions of 12 cells saturate the loop (174 % aggregate) with a small document, and reproduce ~15 % of the inflation, so contention with the ingestion thread accounts for part of it; the rest tracks the per-pass working set. Either way it is a constant factor, not an O(cells^2) term — call counts in the pass scale exactly 2x from 12 to 24 cells.

The two together are what tips it over: the linear part alone would put 24 cells at ~66 % duty; the inflation pushes it past 100 %.

Where a pass goes at 24 cells: SessionLayer.update_pipe ~85 % (48 calls, holoviews re-render into the bokeh models), the cell titlebar update_freshness/update_layer_time ~15 %, and freeze-exit on top at ~0.05–0.1 ms per model. GC is noise (~15 ms/pass, with occasional 200–350 ms gen-2 collections). Bokeh's hold("combine") scan over held events, an obvious quadratic candidate, is ~5 ms per pass at 230 events — not it.

First render, separately

grid	tab switch	materialization
3 cells	117 ms	0.68 s
6 cells	190 ms	1.01 s
12 cells	435 ms	3.10 s
24 cells	1106 ms	9.47 s

Also linear-with-inflation, and a one-off. Settled cost is ~87 models per cell (from differencing settled counts across grid sizes) rather than the 74 reported earlier, which came from a census taken before the cells had finished materializing.

What this means for the directions

The budget is what matters: ~27 ms of shared IOLoop time per visible cell per data frame, so a dashboard process sustains roughly 35 cell-frames per second across all its sessions. A 6x6 grid — legal, 36 cells — exceeds that on its own at 1 Hz. So do three users on 12-cell grids. This is a capacity ceiling, not a first-paint problem.

• Chunking cell materialization bounds the first-render block (up to 9.5 s at 24 cells), which is worth doing, but it does not touch steady state, which is where the 24-cell grid actually lives.
• Skipping the freeze-exit recompute on no-op full passes is worth ~2–4 % duty at 2139 models. Still pure waste, still small.
• Reducing models per cell cuts first render and freeze-exit, and helps the client a lot — but steady-state cost is per layer, not per model, so trimming the toolbar and titlebar does not move the 12 ms/layer repaint.
• The only lever on the ceiling is the repaint itself: either the per-layer render path gets cheaper, or big grids repaint at less than the data rate (per-grid rate cap, or round-robin so a pass repaints a bounded number of cells).

Reproducing

Same harness, extended: --mode render (single session, server log is the report, survives a click timing out on a blocked page), --mode two --sessions N (N sessions, for separating heap from document size), plus server-side IOLoop stall monitoring, per-phase timing, GC accounting and delayed cProfile arming (ESSLD_PROFILE, ESSLD_PROFILE_DELAY).

Two more measurement traps, on top of the two already noted:

• cProfile is process-wide on Python 3.12 (sys.monitoring is global), so a pass profile also contains the ingestion thread's work — the fake backend's data synthesis shows up inside the tick. Use time.thread_time for attribution and treat profile totals as relative only.
• The observation window has to outlive the render, or the reported block is just the window: 20 s of waiting is what produced the 11.1 s figure.

[SimonHeybrock]

Tracking

Keeping this issue open as the tracker rather than opening a meta-issue: the measurement baseline and the harness live here, and every child is judged against the same number. Ordered by return per unit of work:

• Build per-layer cell toolbars lazily instead of hidden #1204 — build per-layer cell toolbars lazily instead of hidden (PR Build per-layer cell toolbars lazily instead of hidden #1205). 98 -> 75 models/cell, freeze-exit 49 -> 40 ms at 12 cells.
• Collapse the per-frame .opts() wrappers on session plots #1199 — collapse the per-frame .opts() wrappers. -27 % of every layer repaint, contained change.
• Reduce Bokeh models per plot cell (98 today, ~50 reachable) #1201 — reduce models per plot cell to ~50 (glyph variants, per-figure toolbar, titlebar chrome).
• Skip the freeze-exit model-graph recompute on passes that changed nothing #1202 — skip the freeze-exit recompute on passes that changed nothing. 2-4 % duty, pure waste.
• Chunk plot-grid cell materialization across ticks #1203 — chunk cell materialization across ticks. Bounds the one-off first-render block (9.5 s at 24 cells); does not touch steady state.
• Fast-path steady-state plot updates past holoviews #1200 — fast-path steady-state updates past holoviews. The only item that moves the ceiling.

Acceptance is a re-measurement with the harness above, not a code review: today a 24-cell grid at 1 Hz costs 1056 ms of shared IOLoop per tick (106 % duty, i.e. permanently saturated). The target is that the same grid sits well under half the loop — steady-state pass under ~500 ms — and that no single first render blocks the loop for more than ~1 s.

Numbers to re-run per change: --mode render --cells {6,12,24} for the pass cost and duty, ESSLD_CENSUS=1 diffed across two cell counts for models per cell.