signal-bot/signal_bot/analytics/probe.py
Krzysztof kuhy Rudnicki 4af32f8bd5 Handle frames side by side, and budget the bot's own share of a reply
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>
2026-09-04 21:35:34 +02:00

132 lines
4.6 KiB
Python

# Copyright (c) 2026 Krzysztof Rudnicki. MIT licence.
"""What one running command did, collected without changing any signature.
Timing a command means knowing things the handler learns and the dispatcher
records: how long the upstream fetch took, how long the send took, which
item was served. Threading that back would mean a return value or an extra
argument on every handler, every fetcher method and every reply helper.
A ``ContextVar`` avoids all of it. The dispatcher opens a probe around the
handler call; anything running underneath finds it and notes what it did.
``contextvars`` is stdlib, so the runtime stays at exactly six dependencies.
``Bot.listen`` runs every frame in a task of its own (``inflight.py``), and
a task starts with a *copy* of the context, so frames handled side by side
cannot see each other's probe: each ``probing()`` sets the variable in its
own copy, and the reset in one task cannot be undone by another. The same
holds for a handler that spawns a task of its own -- the copy's notes land
in that handler's probe, nowhere else.
Every ``note_*`` is a no-op when nothing is probing. That branch lives here,
once, so no caller needs to ask whether it is being measured -- which is
what keeps ``http_client`` and ``context`` free of analytics conditionals.
"""
from __future__ import annotations
import contextlib
import time
from contextvars import ContextVar
from dataclasses import dataclass, field
from typing import TYPE_CHECKING, Final
if TYPE_CHECKING:
from collections.abc import AsyncIterator, Iterator
# No default sentinel object: None is the whole vocabulary, and the helpers
# below are the only readers.
CURRENT: ContextVar[Probe | None] = ContextVar("command_probe", default=None)
# A request that never got an answer at all -- DNS, connect, timeout. Kept
# distinct from a 5xx, which is upstream answering and answering badly; the
# two mean different things when a command starts failing.
NO_RESPONSE: Final = 0
MS_PER_SECOND: Final = 1000
@dataclass(frozen=True, slots=True)
class UpstreamCall:
"""One outbound HTTP request made while serving a command."""
host: str
status: int
ms: int
@dataclass(slots=True)
class Probe:
"""The mutable notes one invocation accumulates.
Upstream calls are *buffered* rather than written as they happen: they
belong to a ``command_events`` row that does not exist yet, because the
outcome and the duration are only known once the handler has returned.
"""
send_ms: int = 0
item_id: str | None = None
calls: list[UpstreamCall] = field(default_factory=list)
@contextlib.contextmanager
def probing() -> Iterator[Probe]:
"""Open a probe for the duration of one command, and always close it."""
active = Probe()
token = CURRENT.set(active)
try:
yield active
finally:
CURRENT.reset(token)
def note_send(ms: int) -> None:
"""Add the cost of one outbound Signal send.
Accumulated rather than assigned: a handler may send twice, and
``!pułapka`` does -- a picture and then its description.
"""
active = CURRENT.get()
if active is not None:
active.send_ms += ms
@contextlib.asynccontextmanager
async def timed_send() -> AsyncIterator[None]:
"""Time one outbound send and note it, whether or not it succeeds.
``DOCS-latency.md`` measured ``POST /v2/send`` at 2.65 s of a 3.7 s
reply -- 72% of the wall clock, none of it this repository's code -- by
reading three log lines by hand, once. This makes that measurement
continuous, which is what the document's own rule asks for: an upstream
latency claim gets measured before it gets designed around.
"""
started = time.perf_counter()
try:
yield
finally:
note_send(round((time.perf_counter() - started) * MS_PER_SECOND))
def note_upstream(host: str, status: int, ms: int) -> None:
"""Add one upstream request. Host only -- never the URL.
A URL carries identifiers, and some of them are the ones ``item_id``
exists to govern. A hostname cannot carry anything.
"""
active = CURRENT.get()
if active is not None:
active.calls.append(UpstreamCall(host=host, status=status, ms=ms))
def note_item(item_id: str) -> None:
"""Record which item was served, as a public identifier.
A Wikidata QID, a Commons page id, a Wolne Lektury slug, a pseudonym
key, a content-addressed filename. Never a title, a caption or a name:
this is what makes "the pope pool feels repetitive" a number instead of
an impression, and an identifier cannot carry a person.
"""
active = CURRENT.get()
if active is not None:
active.item_id = item_id