Krzysztof kuhy Rudnicki
4af32f8bd5
Bot.listen awaited every frame to completion, so one Commons fetch or one attachment upload held up every text reply behind it (DOCS-latency.md). Each frame now runs in its own task, never more than LIMIT at once; the reader waits for a slot before spawning, so a burst applies back-pressure at the websocket instead of fanning out upstream. One person's commands stay serialised (user_lock.py): two quick !kot would otherwise both pass the cooldown gate before either recorded a use. Every served command reports its timings split into the bot's own time and everybody else's (served.py); /_selftest carries that block and tool/latency.py holds own_ms to 100 ms at p95, with the command's cooldown switched off for the run and put back afterwards. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
3.7 KiB
Latency: where the 3.7 seconds actually go
Measured on the live bot, 2026-08-29, for one real !cat in the production
group. Every number here came from journalctl --user -u signal-bot.service,
not from a model of the system.
22:59:37.984 running command cat
22:59:38.370 GET api.thecatapi.com/…/search 200 386 ms
22:59:39.054 GET s3…/MjA2MDgxMA.jpg 200 684 ms
22:59:41.702 POST localhost:9922/v2/send 201 2648 ms
Fetching the picture — the JSON lookup plus the download — is 1.07 s of the
3.7 s. POST /v2/send on its own is 2.65 s, and that is the
signal-cli-rest-api container uploading the attachment to Signal. It is 72% of
the wall clock and none of it is this repo's code.
The consequence for the latency release
The plan proposed an image prefetch pool as "the single biggest win": keep N pre-fetched, pre-base64'd images per command in memory so a command costs one send instead of fetch JSON → download → encode. The measurement says that buys 3.7 s → about 2.7 s. Worth having, but it is not the biggest win and it does not get anywhere near a sub-second reply, because the send is untouched.
Do not design the latency release on the plan's assumption. Before building anything, measure these two separately:
- A text-only reply, end to end. That isolates
POST /v2/sendwithout an attachment and says how much of the 2.65 s is upload versus fixed overhead. - Whether signal-cli can reuse an already-uploaded attachment id, so a repeated image costs a reference rather than a fresh upload. If it can, that is the real win and it makes the prefetch pool far more valuable, because the pool could hold ids instead of bytes.
Head-of-line blocking: fixed
This one was confirmed without re-measuring: bot.py awaited each frame to
completion, so one slow upstream fetch delayed every message behind it. Now
every frame runs in a task of its own (signal_bot/inflight.py), never more
than LIMIT at once. The reader waits for a slot before spawning, so a
burst applies back-pressure at the websocket instead of fanning out into a
hundred upstream connections. The one thing that must not run side by side
is one person's own commands -- two quick !kot would both pass the cooldown
gate before either had recorded a use -- so signal_bot/user_lock.py
serialises per sender, and nobody else waits.
The bot's own share, measured and budgeted
Every measurement above is a measurement of somebody else. To say anything
about this code, each served command now reports its timings split into
the bot's own time and everybody else's (signal_bot/served.py):
| field | what it covers |
|---|---|
queue_ms |
frame read → a slot free: waiting behind other frames |
dispatch_ms |
slot → handler: parse, scope, tally, resolve, sender lock |
handler_ms |
the handler, wall clock |
send_ms |
of which: POST /v2/send and friends |
upstream_ms |
of which: Commons, the cat API, and the like |
own_ms |
queue + dispatch + handler - send - upstream |
POST /_selftest answers with that block, and tool/latency.py holds it to
the budget: own_ms ≤ OWN_BUDGET_MS (100 ms) at p95, over N replies of
a text-only command in a test group, with the command's cooldown switched off
for the run and put back afterwards. Exit 1 when over. The whole reply is
bounded by the container and reported (round_trip_ms), not budgeted.
tool/latency.py testbot # 20 x !pomoc
tool/latency.py testbot --text '!ja' --times 50
Rule
An upstream latency claim gets measured before it gets designed around. The prefetch-pool assumption survived a whole planning pass and was wrong by more than a factor of two in the direction that mattered.