MT-7273: Optimize Message parsing, copying and encoding for large messages by sipho-sarao · Pull Request #268 · ska-sa/katcp-python

sipho-sarao · 2026-07-21T06:37:16Z

MT-7273: Optimize Message parsing, copying and encoding for wide messages

Problem

A 4096-channel CBF+ ?gain request yields a ~60 KiB KATCP line with ~4100 arguments. Processing these large messages hits noticeable CPU bottlenecks:

MessageParser.parse: ~7.5 ms
Message.copy(): ~3.3 ms (re-runs format_argument on already-bytes args)
Message.__bytes__: ~1.8 ms

For the CBF+ proxy, this cost is incurred on every proxied gain message and dominates request latency investigated in this branch.

Changes (`katcp/core.py`)

MessageParser.parse - If a line contains no backslash, skip per-argument UNESCAPE_RE.sub / SPECIAL_RE.search calls and validate via a single scan over the argument region (excluding space/tab delimiters). Construct the result via a new Message._from_parsed() helper to bypass __init__'s re-validation loops.
Message.copy - Use direct slot assignment + list() instead of re-formatting every argument. Preserves existing behavior (does not copy mid).
Message.__bytes__ - Avoid regex substitution overhead on unescaped args by checking ESCAPE_RE.search first, and combine empty-argument formatting into the loop pass..

Non-functional changes in this PR:

tox.ini: Pins coverage<5 (CI fix - build node lacks _sqlite3 needed by coverage ≥5; 4.x is the last major supporting Python 2.7).
bench/: Added the verification and benchmark scripts described below. These are self-contained scripts to reproduce the performance and equivalence claims of the large-message optimisation, added for reviewers and future regression checks. They locate the repo automatically (or via the KATCP_REPO env var) and can be run on Python 2.7 and 3.

Verification & Benchmarks

Tests: Core + BNF grammar test suites pass on Python 2.7 (62 tests).
Fuzzing: 300,000-line differential fuzz test against master (covering heavy escapes, bad names/mids, and whitespace variations). Produced identical outputs, exception types, and error messages.
Micro-benchmarks (Py2.7 @ 4096 args):
- Parse: 7.47 ms --> 1.76 ms
- Copy: 3.30 ms --> 0.013 ms
- Encode: 1.82 ms --> 0.93 ms
- (Py3.10 parse drops 4.97 ms --> 1.60 ms)
End-to-End Latency: Proxied gain round-trip dropped from 34.8 ms to 14.9 ms. Pipelined throughput under burst dropped from 49.5 ms/msg to 15.2 ms/msg.
Live A/B (cbf_plus_dev_1, 880 serial 4096-channel set-gain messages):
- Total time: 97.8 s --> 29.7 s
- p50 latency: 77.8 ms --> 32.7 ms
- Worst message: 25.3 s --> 60.2 ms
- Proxy CPU cost: ~50 ms --> ~16 ms / msg (~14% core load down from ~50%)

Note: Small messages also benefit slightly from bypassing constructor validation (1-arg parse drops from 9.2 µs to 4.1 µs). The escape-containing fallback path remains unchanged.

Testing Instructions

Verification tools are included under bench/ (see bench/README.md).

Local repo tests:

cd bench
python ab_compare.py          # Benchmarks master vs working tree via git worktree
python fuzz_parse_branch.py   # Differential fuzz test vs master's parser
python run_core_tests.py      # Core + BNF test suites

…sages

ludwigschwardt · 2026-07-21T12:07:24Z

Interesting! What is the latency after the fix?

sipho-sarao · 2026-07-21T15:46:46Z

Interesting! What is the latency after the fix?

Great question, here is the latency broken down across three measurement contexts on my devbox environment:

1. Live proxy on my devbox (cbf_plus_dev_1, Py2.7, busy shared system; 4096-channel set-gain, ~20 KiB/message, serial, state-neutral):

Per-message round trip	Before	After
p50	67.8 ms	31.5 ms
p95	143.4 ms	35.0 ms
Worst observed (880-msg run)	25.3 s	60 ms

So ~30 ms per gain-set end-to-end on a loaded devbox, and the long tail is effectively gone. The new p95 sits well below the old median.

2. Controlled proxy chain (client -> proxy -> zero-work device, isolating CAM stack cost with full 60 KiB complex-formatted payloads):

34.8 ms --> 14.9 ms per message.

3. Codec CPU cost alone (the specific functions optimized in this PR, Py2.7 @ 4096 args):

Parse: 7.47 ms --> 1.76 ms
Handler copy: 3.30 ms --> 0.013 ms
Encode: 1.82 ms --> 0.93 ms
Total codec CPU: ~12.6 ms --> ~2.7 ms per message.

What remains after the fix is mostly the product-controller round trip (~10 ms, as it re-parses the line on its side outside of katcp-python) plus residual Tornado/thread plumbing. The KATCP codec is no longer the dominant bottleneck.

Overall throughput for the ticket's 880-message scenario dropped from ~98 s down to ~30 s on my devbox. All numbers are reproducible using the ab_compare.py script in bench/.

ludwigschwardt

Just some generic comments for now...

ludwigschwardt · 2026-07-21T16:44:34Z

+            escape_match = self._escape_match
+            escaped_args = []
+            for x in self.arguments:
+                if search(x):


What does the search check do that makes it better than before?

In the vast majority of KATCP arguments and in all arguments of the bulk numeric payloads this PR targets (gains, weights, delays, numeric sensor values), there are no characters needing escaping. I stand to be corrected.

Previously, self.ESCAPE_RE.sub() was executed unconditionally on every single argument, including even when nothing matches (sub() then returns the original object, no new bytes are built), it still pays the substitution's setup overhead for the callable-replacement path. When measured on my devbox Py2.7 proxy runtime, per clean argument: search takes ~278 ns vs sub taking ~457 ns.

search(x) acts as a fast-path pre-check:

Short-circuits clean arguments: re.search() does a single C-level scan of the bytes and returns None, avoiding the heavier sub() call entirely, saving ~0.7 ms per 4096-argument message.

Local variable binding: Aliasing search = self.ESCAPE_RE.search outside the loop avoids repeated attribute lookups on every iteration across thousands of arguments.

Together with folding the former empty-argument pass (x or b"\\@") into the same loop, this takes the encode step from 1.8 ms down to 0.9 ms per 4096-argument message.

The trade-off: escape-bearing arguments (mainly human-readable descriptions in #help, #sensor-list, or #log informs) take the sub() path as before, paying search + sub (+340 ns measured per escaped argument). Since the guard is per-argument, clean arguments within those same messages still benefit from the fast path.

I'm not sure if the trade-off of doing a checking with re.search first is worth the impact on cases that do need escaping, since those cases do an re.search in addition to re.sub. Also when benchmarking this did you include overhead of the if-statement too? I don't think it's accurate to compare re.search and re.sub in isolation.

ludwigschwardt · 2026-07-21T16:47:39Z

+import sys
+import unittest
+
+from _repo import katcp_repo


Why would you need special logic to find the KATCP repo?

Mainly to support the A/B differential scripts (ab_compare.py and fuzz_parse_branch.py) and flexible execution:

Explicit checkout target vs site-packages: It guarantees the scripts test the specific source tree you intend (including the temporary git worktree checkout that ab_compare.py generates for the baseline side), preventing Python from silently importing an already-installed katcp from site-packages.

Out-of-tree execution: KATCP_REPO=/path/to/katcp-python lets you run the suite against an arbitrary local checkout without copying the bench/ directory over. (For ab_compare.py and fuzz_parse_branch.py, the target must be a git repo since they run git worktree / git show against it to obtain the baseline).

Location independence: Discovery is anchored on the script's own __file__, so invocation works from any working directory. git rev-parse --show-toplevel additionally resolves the true repo root rather than assuming bench/'s parent is it.

For a simple single-branch run, sys.path.insert(0, dirname(dirname(__file__))) would do, _repo.py just keeps the discovery consistent between local runs and the git-worktree differential scripts. Happy to drop the rev-parse call and use dirname as the default if preferred.

ludwigschwardt · 2026-07-21T16:48:09Z

+
+if '--fast' in sys.argv:
+    sys.argv.remove('--fast')
+    import fastkatcp  # noqa: F401


Where does fastkatcp come from?

Good catch, it doesn't come from anywhere in this repo. fastkatcp was my investigation-phase monkeypatch form of this fix: an import-time patch I used to hot-deploy the optimisations onto my devbox proxy for testing before this branch existed.

The --fast hooks were scaffolding from that phase and are vestigial here. Removed the flag and the import from all four scripts. Thanks for spotting that.

ludwigschwardt · 2026-07-23T10:26:41Z

Thanks for getting your agent to clean up after itself 😅🙏🏼

It would be instructive to compare the performance of katcp-python to aiokatcp on this front to see whether both have the same issues or if aiokatcp potentially has a better solution.

katcore's DeviceHandler instrumentation cannot see this cost. callback_request() is @make_threadsafe, so when called off the ioloop thread it only does ioloop.add_callback() and returns; serialising the forwarded message happens here afterwards, inside the interval that instrumentation reports as the device round trip. On a 4096-channel wide-gain request that encode is far from free -- 9.88 ms under Python 2.7 on unpatched katcp-python -- so attributing it to the device is misleading. Gated on KATCP_LATENCY_LOG_REQUESTS (comma-separated request names), empty by default, matching KATCORE_LATENCY_LOG_REQUESTS in katcore and emitting the same [LATENCY] line format. When disabled the cost is one frozenset membership test per outgoing message.

MiniProxy.request_wide_gain had no docstring, and DeviceServer's metaclass asserts that every request_* handler has one at class-creation time. The script therefore raised AssertionError at import and has never run since the commit that added it.

zaydosman-sarao

Thanks for working on this. I commented some suggestions below. I also created a branch that incorporates most of your optimisations, slightly improves on them and adds further optimisations.

It seems to improve performance compared to your initial changes. The branch is user/zosman/MT-7273/optimise-katcp-codec. For the test script and configuration we're using and on my devbox, I saw a ~42% improvement to the CBF+ proxy overhead latency for the "gain" command using your branch, and ~54% using the branch I shared.

zaydosman-sarao · 2026-07-24T17:50:09Z

+    @classmethod
+    def _from_parsed(cls, mtype, name, arguments, mid):
+        """Construct a Message from pre-validated parts, bypassing __init__."""
+        msg = cls.__new__(cls)
+        msg.mtype = mtype
+        msg.name = name
+        msg.mid = mid
+        msg.arguments = arguments
+        return msg
+


Nice optimisation, makes sense to use in MessageParser.parse() and Message.copy() since the validation in Message.__init__() is redundant in those two places.

zaydosman-sarao · 2026-07-24T17:55:01Z

+            escape_match = self._escape_match
+            escaped_args = []
+            for x in self.arguments:
+                if search(x):


I'm not sure if the trade-off of doing a checking with re.search first is worth the impact on cases that do need escaping, since those cases do an re.search in addition to re.sub. Also when benchmarking this did you include overhead of the if-statement too? I don't think it's accurate to compare re.search and re.sub in isolation.

zaydosman-sarao · 2026-07-24T18:20:49Z

-        arguments = [self._parse_arg(x) for x in parts[1:]]
+        if b"\\" not in line:
+            match = self.SPECIAL_NO_WHITESPACE_RE.search(line, len(parts[0]))
+            if match:
+                raise KatcpSyntaxError(
+                    "Un-escaped special %r." % (match.group(),))
+            arguments = parts[1:]
+        else:
+            arguments = [self._parse_arg(x) for x in parts[1:]]


If you move the unescaped special character check across the entire line to an outer conditional I think you can remove the same check in _parse_arg():

match = self.SPECIAL_NO_WHITESPACE_RE.search(line, len(parts[0])) if match: raise KatcpSyntaxError("Un-escaped special %r." % (match.group(),)) if b"\\" not in line: arguments = parts[1:] else: arguments = [self._parse_arg(x) for x in parts[1:]] # _parse_arg() doesn't need to do the unescaped check here

I'm not sure if the trade-off of doing a checking with re.search first is worth the impact on cases that do need escaping, since those cases do an re.search in addition to re.sub. Also when benchmarking this did you include overhead of the if-statement too? I don't think it's accurate to compare re.search and re.sub in isolation.

Fair challenge, so I benchmarked it end-to-end on __bytes__ (including branch and call overhead, not just search vs sub in isolation) across Python 2.7 and Python 3.10:

Workload (4096 args) old Unconditional sub search pre-check

Typical traffic (no escaping needed) 1.81 ms 1.45 ms (-20%) 0.88 ms (-52%)

Worst case (all args escaped) 3.71 ms 3.47 ms (-6%) 4.72 ms (+27%)

The extra search call does cost ~0.2 µs per escaped argument when escaping is needed due to Python call overhead. However, the reason the search pre-check makes sense here:

Most frequent traffic path (wide-gain / MT-7273): Messages have zero escaped args. The pre-check yields a -52% time reduction (0.88 ms vs 1.45 ms for unconditional sub).

Realistic Escaped Messages (Sensor Informs): Typically carry ~5 args with a single large escaped value. A single early-exit search overhead is sub-microsecond noise compared to the sub that follows.

Worst-case scenario: A message with thousands of individually escaped arguments doesn't exist on this system's traffic profiles.

An unconditional sub approach guarantees a single pass and avoids performance degradation in the worst case, but it surrenders half the speedup on typical traffic (-20% vs -52%).

So, given our typical traffic profile, the search pre-check provides the biggest performance win. I am happy to switch to unconditional sub if we prefer prioritizing worst-case performance over common-case speed.

If you move the unescaped special character check across the entire line to an outer conditional I think you can remove the same check in _parse_arg():

match = self.SPECIAL_NO_WHITESPACE_RE.search(line, len(parts[0])) if match: raise KatcpSyntaxError("Un-escaped special %r." % (match.group(),)) if b"\\" not in line: arguments = parts[1:] else: arguments = [self._parse_arg(x) for x in parts[1:]] # _parse_arg() doesn't need to do the unescaped check here

Good idea, and it almost works. After the initial whitespace split, the arguments genuinely cannot contain space/tab, so the check inside _parse_arg() is indeed redundant from parse()'s perspective.

The blocker is error precedence on doubly-malformed input: moving the check upfront changes which exception wins when a line contains multiple defects.

Malformed line master & current branch raise Outer-conditional structure raises

?foo \x <ESC> Invalid escape character 'x'. Un-escaped special '\x1b'.

?foo a\ <NUL>b Escape slash at end of argument. Un-escaped special '\x00'.

The current structure (and master) reports whichever error is encountered first while processing arguments left to right, whereas checking the entire line upfront always reports unescaped special characters first.

Since this PR relies on strict comparison testing against master (verifying zero mismatches in exception types and messages across 600k generated inputs), this restructuring would fail that test suite.

I would prefer to keep this PR strictly backward-compatible to keep our tests passing. If we want to adopt the new error-ordering behavior (which is arguably cleaner), we can do that in a follow-up PR where updating the expected test baselines is the explicit goal.

Most frequent traffic path (wide-gain / MT-7273): Messages have zero escaped args. The pre-check yields a -52% time reduction (0.88 ms vs 1.45 ms for unconditional sub).

Why do you consider this the most frequent traffic path? The benchmark scenario we've been using is not necessarily representative of all traffic that this library is used for.

Since this PR relies on strict comparison testing against master (verifying zero mismatches in exception types and messages across 600k generated inputs), this restructuring would fail that test suite.

I would prefer to keep this PR strictly backward-compatible to keep our tests passing. If we want to adopt the new error-ordering behavior (which is arguably cleaner), we can do that in a follow-up PR where updating the expected test baselines is the explicit goal.

Which tests would fail? Existing tests in the repo or new tests you've added in this PR?

rishadebrahim · 2026-07-27T07:33:05Z

The benchmarking methodology used here is too specific to the ticket and targets the gain request. The most significant change in this PR is changing the parser to skip reinitialisation of message objects to skip revalidation of message strings that are already parsed.

A simple benchmark that tests the parsing behaviour under different message types could probably be more meaningful than trying to emulate the gain requests in katcp servers/clients, since it is the parsing behaviour thats really under test. In my opinion the targeted benchmarks that emulate gain request flow should probably be removed from the PR.

zaydosman-sarao · 2026-07-27T07:34:28Z

+        if b"\\" not in arg:
+            return arg
+        if b"\\\\" not in arg:
+            # If there are no escaped backslashes (\\), escape sequences don't overlap.
+            # We can unescape using simple string replacement, which is much faster
+            # than running a regex with Python callback functions.
+            unescaped = arg
+            for sequence, char in self.ESCAPE_SEQUENCES:
+                unescaped = unescaped.replace(sequence, char)
+            if b"\\" not in unescaped:
+                return unescaped
+
+            # If a backslash remains, the escape sequence was invalid or incomplete.
+            # Fall back to regex parsing so we raise the expected error message.


I think this is optimising too much for very specific scenarios.

rishadebrahim · 2026-07-27T07:47:20Z

+# Request names for which the outgoing encode is timed, taken from the
+# KATCP_LATENCY_LOG_REQUESTS environment variable as a comma-separated list
+# (e.g. "wide-gain"). Empty, the default, disables the instrumentation.
+#
+# This complements the proxying intervals logged by katcore's DeviceHandler.
+# Those cannot see this cost: callback_request() is @make_threadsafe, so off
+# the ioloop thread it only enqueues and returns, leaving the encode to run
+# here afterwards -- inside what that instrumentation reports as the device
+# round trip.
+LATENCY_LOG_REQUESTS = frozenset(
+    name.strip()
+    for name in os.environ.get("KATCP_LATENCY_LOG_REQUESTS", "").split(",")
+    if name.strip()
+)
+
+


This should be removed since it seems to be left over code from your benchmarking runs.
We don't typically configure environment variables in CAM environments so this has no place in this repo.

rishadebrahim · 2026-07-27T07:48:30Z

        """
        assert get_thread_ident() == self.ioloop_thread_id
-        data = bytes(msg) + b"\n"
+        if msg.name in LATENCY_LOG_REQUESTS:


Same as above. remove

rishadebrahim · 2026-07-27T08:06:12Z

+import logging
+import signal
+
+import aiokatcp


I don't think this script belongs in this repo because it uses aiokatcp which is python3. This repo is py2/py3. Furthermore, it is a targeted benchmark for gains requests and not testing generic message parsing functionality of katcp-python. Should be stored in another repo.

rishadebrahim · 2026-07-27T08:13:59Z

@sipho-sarao would be good to include in your PR how you came to find out the parsing at the katcp level seems to be the bottleneck for gain requests to give a bit more context. It doesn't have to be detailed. Since there are many layers for gain request in the real system (katcorelib?->katproxy->katcore->katcp) I am curious to see how you managed to isolate the issue and the test methodology that was used, and it will provide future readers with context.

MT-7273: Optimize Message parsing, copying and encoding for large mes…

77eb0f8

…sages

sipho-sarao self-assigned this Jul 21, 2026

Pin coverage<5 so CI works without the sqlite3 stdlib module

9381af8

sipho-sarao added 4 commits July 21, 2026 16:26

Add verification tools for the message fast paths

8d3fe46

Fix redundant line and missing last line

e978cea

Add EOF line

18473bf

Fix flake8 findings in the new bench/ scripts

450d8f0

sipho-sarao requested review from bngcebetsha, lanceWilliams, ludwigschwardt, rishadebrahim and zaydosman-sarao July 21, 2026 15:48

ludwigschwardt reviewed Jul 21, 2026

View reviewed changes

MT-7273: Remove fastkatcp monkeypatch hooks from bench scripts

5d50d50

sipho-sarao requested a review from ludwigschwardt July 22, 2026 05:08

sipho-sarao added 5 commits July 23, 2026 13:56

Add bench/test_latency_target.py for proxy-vs-product gain timing

eb01f55

MT-7273: Make inbound-message debug log lazy

039fb66

MT-7273: Fix flake8 issues

2d3d093

zaydosman-sarao reviewed Jul 24, 2026

View reviewed changes

MT-7273: Unescape message arguments without a per-escape Python callback

80a6f82

zaydosman-sarao reviewed Jul 27, 2026

View reviewed changes

rishadebrahim reviewed Jul 27, 2026

View reviewed changes

Workload (4096 args)	`old`	Unconditional `sub`	`search` pre-check
Typical traffic (no escaping needed)	1.81 ms	1.45 ms (-20%)	0.88 ms (-52%)
Worst case (all args escaped)	3.71 ms	3.47 ms (-6%)	4.72 ms (+27%)

Malformed line	`master` & current branch raise	Outer-conditional structure raises
`?foo \x <ESC>`	`Invalid escape character 'x'.`	`Un-escaped special '\x1b'.`
`?foo a\ <NUL>b`	`Escape slash at end of argument.`	`Un-escaped special '\x00'.`

Uh oh!

Conversation

sipho-sarao commented Jul 21, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

MT-7273: Optimize Message parsing, copying and encoding for wide messages

Problem

Changes (katcp/core.py)

Verification & Benchmarks

Testing Instructions

Uh oh!

ludwigschwardt commented Jul 21, 2026

Uh oh!

sipho-sarao commented Jul 21, 2026

Uh oh!

ludwigschwardt left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ludwigschwardt commented Jul 23, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

zaydosman-sarao left a comment • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

zaydosman-sarao Jul 27, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

rishadebrahim commented Jul 27, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

rishadebrahim commented Jul 27, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

sipho-sarao commented Jul 21, 2026 •

edited

Loading

Changes (`katcp/core.py`)

ludwigschwardt commented Jul 23, 2026 •

edited

Loading

zaydosman-sarao left a comment •

edited

Loading

zaydosman-sarao Jul 27, 2026 •

edited

Loading

rishadebrahim commented Jul 27, 2026 •

edited

Loading

rishadebrahim commented Jul 27, 2026 •

edited

Loading