GraphServer pickles snapshots under the global command lock, stalling a starting graph

[cboulay]

Summary

GraphServer builds and pickles snapshot payloads while holding its single global _command_lock. That lock also serializes process registration and pub/sub edge setup, so a client that snapshots a graph while it is starting up stalls the graph's own units — far enough to exhaust a publisher's buffer ring and emit under subscriber backpressure!.

Where

ezmsg/core/graphserver.py (v3.9.0):

async def _handle_session_snapshot_request(self, writer):
    async with self._command_lock:
        snapshot = self._snapshot()
        snapshot_bytes = pickle.dumps(snapshot)      # serialization inside the lock
        ...

async def _handle_session_settings_snapshot_request(self, writer):
    async with self._command_lock:
        snapshot = {addr: self._settings_state[addr].value for addr in sorted(self._settings_state)}
        snapshot_bytes = pickle.dumps(snapshot)      # ditto
        ...

_handle_session_settings_events_request has the same shape. The same _command_lock is taken by, among others, _handle_process_register_request and _handle_session_edge_request — i.e. exactly what every process and every pub/sub edge in a starting graph needs.

Observed behaviour

An external client (our experiment-control UI) polls GraphContext.snapshot() to discover when a launched pipeline has registered. While a 2-hub acquisition pipeline was coming up:

• the pipeline's own hub boundary logged .../HUB1/__relay_out_OUTPUT_SIGNAL/OUTPUT under subscriber backpressure! within the first ~2 seconds
• the client's own snapshot() / settings_snapshot() round-trip exceeded a 5 s deadline and was cancelled, leaving revert: Could not clear GraphContext session state: GraphContext session task is not running

Stopping the polling — the only change — removed both, on the heaviest configuration we have. The publisher's ring is 16 buffers at ~100 msg/s in that configuration, so the subscriber stall was ≥160 ms; it is a discrete block, not a throughput deficit. Reducing our poll rate from 100 ms to a 0.25→1.0 s backoff (≈21 snapshots down to ≈4 in the same window) is what we shipped as a mitigation, but any client snapshotting a busy graph can still cause this.

Suggested fix

Copy the state under the lock and serialize outside it:

async def _handle_session_snapshot_request(self, writer):
    async with self._command_lock:
        snapshot = self._snapshot()       # cheap, consistent
    snapshot_bytes = pickle.dumps(snapshot)   # expensive, no lock held
    writer.write(uint64_to_bytes(len(snapshot_bytes)))
    writer.write(snapshot_bytes)
    writer.write(Command.COMPLETE.value)

_snapshot() already returns a GraphSnapshot built from server state, so if it (and the _settings_state comprehension) produce values that are not mutated afterwards, the pickle needs no lock at all. If those payloads can alias mutable server state, the copy under the lock should be deepened rather than the pickle moved back in.

A cheaper, complementary option: cache the pickled snapshot and invalidate it on topology change, so repeated polls from a discovery client cost one serialization rather than N.

Environment

• ezmsg 3.9.0, Python 3.12, macOS (Apple silicon)
• Graph service in its own process; pipeline processes connect to it over graph_address
• Reproduces on the graph's startup window specifically, when registration/edge traffic contends with snapshot requests

Happy to open a PR for the copy-under-lock change if the approach looks right.

[cboulay]

Correction — please treat the "Observed behaviour" section as retracted.

The reproduction I described was based on a misread log: I compared runs believing the backpressure warning disappeared when our client stopped polling, and it did not. With the polling suppressed the warning still occurs, so the causal link I asserted between snapshot polling and the backpressure/stall is not supported, and neither is the 5 s timeout attribution.

What stands is the code-level observation in the "Where" and "Suggested fix" sections, which is independent of our symptom: _handle_session_snapshot_request, _handle_session_settings_snapshot_request and _handle_session_settings_events_request build and pickle.dumps their payloads inside async with self._command_lock, and that same lock serializes _handle_process_register_request and _handle_session_edge_request. Holding a global lock across serialization is still worth avoiding — a snapshotting client can delay registration and edge setup for as long as the pickle takes — but I no longer have a measurement showing what that costs in practice, so please weight this as a code review note rather than a reported regression.

Happy for this to be closed if you'd rather see it re-filed with real numbers attached; I'll follow up if I get them. Apologies for the noise.

[cboulay]

Follow-up: our symptom is explained, and it was not this. This issue is not blocking us.

The backpressure warning that prompted the report came from SamplingDelayAlignment in ezmsg-blackrock, whose numba kernels pay a one-time cost on first execution in a process. Measured on a 256-channel hub with 1 ms chunks:

	first call	steady state
filter_len=13, cold numba cache	267 ms	0.016 ms
filter_len=13, warm cache	61 ms	0.016 ms
filter_len=0 (pass-through)	0.03 ms	0.002 ms

At 30 samples/ms that first call queues ~61 chunks behind it, which the hub then drains as a burst through a 16-buffer publisher ring — one under subscriber backpressure!, in the first seconds, never again. Steady state is ~60x faster than realtime, so nothing is actually starved. It reproduced with our UI closed entirely, and disappeared with the filter disabled, which is what finally localized it.

So: no GraphServer involvement, and nothing here that blocks us. Our client-side mitigation (backing snapshot polling off from 100 ms to 0.25–1.0 s) we're keeping on its own merits, not as a fix.

The code observation in the original report stands as written — serialization inside _command_lock, which also gates _handle_process_register_request and _handle_session_edge_request — but it is a design note with no measured impact behind it, so please triage it at whatever priority that deserves, including closing it.