Stream loop (sockets.py / connection.py)

recv() runs without timeout after the first receives - stop_stream() waits for the next message

Id: e1cc84dc-a9ff-495a-a8ac-916b3189fbe1 Type: decision Status: active Evidence: confirmed Source: maintainer confirmation 2026-09-10; connection.py (timeout_disabled), git history: threshold processed_receives_total > 3 predates commit fd370d8a (2024-03-27, which added the timeout_disabled flag), today > 10

BinanceWebSocketApiConnection.receive() wraps recv() in asyncio.wait_for(..., timeout=1) only until a stream has more than 10 processed receives; from then on, as long as the stream has subscriptions, it awaits recv() without a timeout. stop_stream() merely sets stop_request, which receive() checks at the top of each call. Consequence: on a stream that has subscriptions but currently receives nothing, a stop (or crash request) takes effect only when the next message arrives - or when the peer closes. Against Binance this is invisible because data keeps flowing; it surfaced in the local-server unit test for the websocket-library switch, where the test server had to send a heartbeat for the manager to shut down.

Reason: deliberate. wait_for() costs a task plus a timer per message, which is not wanted on the hot path once a stream is known to be alive. The timed phase at the start exists for the opposite case: a loop that never receives anything (bad subscription, dead endpoint) must still be stoppable, so the first receives are polled with a 1 s timeout until the stream has proven it delivers data.

Accepted consequence: the stop latency on an established but currently idle stream is acceptable to the maintainer; not a bug.

Rejected alternative: keeping a (long) timeout permanently - rejected because of the per-message overhead. Closing the websocket from stop_stream() directly was not in contention.

Per-message work in the loop that is not the transport - profiled

Id: 8a62fdfc-0fcb-4790-a8b9-efa1939a8967 Type: decision Status: active Evidence: confirmed Source: profiling pass 2026-09-10: cProfile of the stream thread (300k aggTrade messages from the local replay server, picows) plus a cumulative ablation with lean replacements of the hot-path methods, both libraries, median of 3; benchmark harness dev/test_websocket_library_benchmark.py See: websocket-library.md#benchmark-results — b8a65cf6-d48b-42dd-8924-e5682ba6f947 — as of 2026-09-28

The websocket-library benchmark showed a constant ~5 µs per message that UBWA spends on top of either library (raw libraries 2-3 µs/msg, through UBWA 6-9 µs/msg). Profiling attributes it as follows, per received message:

  • 18 logger.debug(f"...") calls while debug logging is off. The f-string is built before debug() checks the level, ~0.1 µs each. 12 of them are stream_list_lock was entered / Leaving stream_list_lock pairs inside set_heartbeat(), increase_received_bytes_per_second() and increase_processed_receives_statistic(); the rest are entry logs of receive(), is_stop_request(), is_crash_request() (each with a get_debug_log() call) and the dispatch log in start_socket().

  • 7 lock acquire/release cycles (stream_list_lock x5, total_received_bytes_lock, total_receives_lock), ~0.17 µs each.

  • Duplicate work: set_heartbeat() runs twice per message (in receive() and at the top of the loop iteration), is_stop_request() and is_crash_request() twice (loop condition and raise_exceptions() inside receive()).

  • sys.getsizeof(str(msg)) for the byte statistics (~0.1 µs, and it counts the str object header, not the payload).

Ablation, small messages (0.2 KB), through the full stack, raw_data:

Stage (cumulative) websockets msgs/s CPU µs/msg picows msgs/s CPU µs/msg
A baseline 119,880 8.41 166,906 6.07
B no debug f-strings in the hot path 160,992 6.28 268,185 3.82
C + per-stream counters without stream_list_lock 181,873 5.57 306,244 3.34
D + heartbeat/stop/crash once per iteration 181,969 5.56 344,516 2.93
E + len() instead of sys.getsizeof(str()) 191,839 5.30 370,564 2.76

Raw libraries for reference: websockets ~3.0 µs, picows ~2.0 µs. Stage E leaves ~0.8 µs of UBWA overhead with picows (dispatch cascade, one debug call, counters) and ~2.3 µs with websockets.

Lock-free counters, why it is safe and where it is not: the per-stream fields (last_heartbeat, processed_receives_total, the per-second dicts) have a single writer, the stream’s own thread; _frequent_checks() in the manager thread reads them and prunes old timestamp keys after copy.deepcopy() under the lock. A lock-free += on an existing key is safe; inserting a new timestamp key (once per second) while the manager thread deep-copies the dict can raise “dictionary changed size during iteration”, so the insert path must keep the lock. That is the split the ablation’s stage C did not yet make - the production change must.

Implemented (same day, all four stages, PR “perf: slim down the stream loop hot path”): the 18 debug f-strings in the hot path are gone (the lock entered/leaving pairs and the per-call entry logs; send() and the non-hot-path logs are untouched), the per-stream counters take stream_list_lock only on the once-per-second key insert, receive() no longer duplicates heartbeat and stop/crash checks, byte statistics use len() of the payload. Result through the full stack, raw_data, median of 3, same machine:

Scenario ~msg size msgs websockets msgs/s picows msgs/s picows speedup websockets CPU µs/msg picows CPU µs/msg
small_aggtrade 0.2 KB 300,000 201,912 403,316 2.00x 5.1 2.5
medium_kline 0.3 KB 150,000 195,460 371,019 1.90x 5.2 2.9
large_depth20 1.0 KB 60,000 153,187 259,960 1.70x 6.8 4.1
xlarge_depth_diff 9.1 KB 30,000 64,172 67,972 1.06x 16.3 15.4
huge_ticker_arr 453.9 KB 600 1,768 1,662 0.94x 608.7 641.0
multiplex_mix 0.2 KB 120,000 180,406 334,188 1.85x 5.7 3.2

Compared with the pre-optimization table in websocket-library.md: websockets 116k -> 202k msgs/s (1.7x), picows 163k -> 403k msgs/s (2.5x) at 0.2 KB. picows now sits at ~2.5 µs/msg against ~2.0 µs for the raw library.

Rejected alternative for the debug logs: keeping them behind an if self.debug: guard. Rejected because the removed lines carried no information (lock was entered / Leaving lock, entry of a getter), and even a guarded call costs ~0.05 µs x 18 per message. Logs that report an event or an error stay.

Revisit when: a second writer for last_heartbeat, processed_receives_total or the per-second dicts is introduced - then the lock-free increments in set_heartbeat(), increase_received_bytes_per_second() and increase_processed_receives_statistic() need the lock back.

Endpoint responses are detected in the first 256 characters, not by scanning the payload

Id: 2be4c0ef-a914-4ae8-880c-6e2c56473864 Type: decision Status: active Evidence: confirmed Source: big-message re-measurement 2026-09-16 (websocket-library.md, “Benchmark results”); dev/test_websocket_library_benchmark.py before/after on the same machine (8 cores, websockets 16.0, picows 2.3.0), median of 3; RESPONSE_SCAN_CHARS in sockets.py; unit test test_response_markers_scanned_in_head_only Revisit when: Binance changes a response envelope so that result, error or the request id can sit beyond the first 256 characters (a new leading field with variable-length content) See: websocket-library.md#benchmark-results — b8a65cf6-d48b-42dd-8924-e5682ba6f947 — as of 2026-09-28 See: https://github.com/oliver-zehentleitner-aigent/picows — 0dfae98e-3584-46ed-86cc-d5207eb3f66b — as of 2026-09-30

Every received message used to be scanned twice in full, "error" in msg and "result" in msg, to route endpoint responses into the error/result ringbuffers; in WS API mode the pending request ids were searched the same way. On a 454 KB !ticker@arr message those scans were ~315 µs of the ~600 µs UBWA spent per message - more than receiving and decoding it - and they were what made UBWA slower than the loopback wire in the replay benchmark (the trigger of the picows big-message artifact). Now the checks run on msg[:RESPONSE_SCAN_CHARS] (256).

Reason 256 is enough: the markers are in the JSON head by construction. Stream endpoint: {"result":null,"id":N}, {"error":{...},"id":N}. WS API: {"id":"<uuid, 36 chars>","status":NNN,"result"|"error":...} puts the marker at ~55 characters; rateLimits follows the result. 256 leaves headroom for longer ids and whitespace. A data message ({"stream":..., {"e":...) never carries these keys in its head.

Also a correctness fix: a data payload that contained the word error or result anywhere (a symbol note, a text field) was copied into the ringbuffers on top of being delivered - the new unit test sends such a payload and fails on the previous code.

Rejected alternatives:

  • Parse every message with orjson and look at the keys: costs a full parse in raw_data mode where none is otherwise needed, on the same order as the scans it would replace.

  • Exact startswith() checks ({"result", {"error", {"id"): brittle against field order and whitespace in the envelopes, and the WS API envelope starts with id, not with the marker.

  • Leave it: the scans were the dominant per-message cost for anything above ~10 KB, see the table.

Before/after, through the full stack, raw_data, median of 3:

Scenario ~msg size websockets msgs/s before -> after picows msgs/s before -> after websockets CPU µs/msg picows CPU µs/msg
small_aggtrade 0.2 KB 199,903 -> 199,732 389,817 -> 380,421 5.1 -> 5.1 2.7 -> 2.7
large_depth20 1.0 KB 156,952 -> 167,888 277,895 -> 315,078 6.9 -> 6.5 4.0 -> 3.6
xlarge_depth_diff 9.1 KB 66,368 -> 100,373 67,336 -> 117,231 16.0 -> 10.9 15.7 -> 9.4
huge_ticker_arr 453.9 KB 1,810 -> 4,540 1,690 -> 3,904 625.5 -> 281.5 678.7 -> 318.5

dict mode, 454 KB: websockets 391 -> 468 msgs/s, picows 427 -> 522. Small messages are unchanged (the slice of a 200-byte string is noise). In the loopback firehose replay picows still trails websockets at 454 KB in raw_data mode (0.86x) because the consumer is still slower than the wire there; with --rcvbuf 131072 the same scenario is picows 1.55x (5,218 vs 3,375 msgs/s, 213 vs 334 µs) and 9 KB is 1.41x.