What “under 100 ms” actually means in an event-execution system

§ 01Where the clock starts and where it stops

The execution engine in the market digital-twin project is described as taking a public event to a signed transaction in under 100 ms, under selected conditions. The first decision behind that sentence was which instant is t0. It is not the timestamp the source writes inside its own message: that clock is not mine, and it usually marks when the source generated the event, not when it let anyone see it. t0 is the moment the bytes carrying the event become visible to my process: the first monotonic read after the frame comes off the socket, with the kernel receive stamp kept alongside to show how long the process took to wake.

From there the event crosses a series of boundaries and each one gets a stamp: decoded, validated and matched to a market, decided, built and signed, written to the RPC node. The figure I am willing to talk about ends at the last of those, when the transaction has left the process. What happens afterwards, propagation, inclusion in a block, the reorganisation risk after inclusion, runs on other people's clocks and is measured separately (§ 05). Collapsing both into a single number is how a system ends up claiming a latency it does not control.

§ 02Why p50 hides everything

The distribution of these durations is not symmetric. Most of the mass sits in a narrow band and a thin tail stretches out to tens or hundreds of milliseconds: a garbage collection, a socket buffer that filled, a node that answered slowly, a burst of events that arrived together. The median lives in the narrow band, so p50 barely moves when the tail grows. But the tail is where the money goes: a decision that arrives at 400 ms is not a slow success, it is a position taken after the price moved. So the number I quote is p95, I watch p99, and I know how many samples sit behind each. A p99 estimated from 200 events rests on two observations; that is a rumour, not a percentile.

The other trap is coordinated omission¹. If the harness only measures events that were processed, and never counts the ones that queued while a pause was in progress, the histogram flatters the system exactly during the pauses it should be exposing. The fix is to stamp queue entry as its own boundary and to count queue wait as latency, not as something that happened before the clock started. The second event of a burst carries the first one's cost, and the record has to say so.

§ 03A latency budget

A budget is a table of allowances, one per stage, that adds up to less than the target with slack left over. It is a design instrument, not a measurement: when the end-to-end histogram is worse than the target, it says which stage's histogram to open first. The figures below are a worked budget under stated assumptions: the process and the reverse proxy on the same host, the RPC node in the same region with a round trip under 20 ms, a warm process with no cold imports and no first-call compilation, a single event rather than a burst, and Python with the allocation-heavy paths pre-warmed. The system's own numbers stay inside the system; this is the shape of the exercise.

The slack is nearly half the target on purpose. A budget with no slack is one that is met at the median and missed at p95, because the tail events are precisely the ones where two stages go slow together. The largest single allowance is the RPC round trip, which is also the stage I own least: I can choose the node, the region and the transport, but not what the node does with the bytes. That is why the last row is measured on its own and never computed from the others.

§ 04The measurement harness

Three rules make the measurement worth trusting. Use a monotonic clock for every duration: time.monotonic_ns() in Python, CLOCK_MONOTONIC underneath, never time.time(), which NTP is free to step backwards. Carry the stamps with the event, in the same object, so a stage cannot forget to record and no lookup adds jitter of its own. And record every duration into a histogram with fixed precision, not into a running average and not into a list to be summarised later. HdrHistogram keeps three significant figures from microseconds to a minute in fixed memory, and reads any percentile back without storing samples². The same discipline, jitter bounded and measured, the measurement kept in the record, is what makes high-frequency acquisition defensible; here the price of a wrong timestamp is a position rather than a sample.

import time
from dataclasses import dataclass, field
from hdrh.histogram import HdrHistogram

STAGES = ("queue", "decode", "match", "decide", "sign", "submit")
# 1 µs .. 60 s, 3 significant figures; one histogram per stage plus end-to-end
H = {s: HdrHistogram(1_000, 60_000_000_000, 3) for s in STAGES + ("e2e",)}

@dataclass
class Trace:
    t0: int                          # monotonic ns, taken right after the socket read
    rx_kernel_ns: int | None = None  # SO_TIMESTAMPING stamp, converted to the monotonic base
    marks: list = field(default_factory=list)

    def mark(self, stage: str) -> None:
        self.marks.append((stage, time.monotonic_ns()))

    def close(self) -> None:
        prev = self.t0
        for stage, t in self.marks:
            H[stage].record_value(t - prev)
            prev = t
        H["e2e"].record_value(prev - self.t0)

# in the pipeline: every boundary is one line, and the trace travels with the event
def handle(frame: bytes, t0: int) -> None:
    tr = Trace(t0)
    ev = decode(frame);              tr.mark("decode")
    mk = validate_and_match(ev);     tr.mark("match")
    order = decide(ev, mk)
    tr.mark("decide")
    if order is None:
        return                       # abstentions are recorded too, up to "decide"
    raw = build_and_sign(order);     tr.mark("sign")
    tx_hash = rpc.send_raw(raw);     tr.mark("submit")
    tr.close()
    tracker.submitted(tx_hash, wall_ns=time.time_ns())

Two details in that block matter more than they look. The kernel receive stamp arrives on CLOCK_REALTIME, so it is converted with an offset between the two clocks read back to back at start-up before it is compared with anything monotonic. And the queue stage is real: when a burst arrives, the second frame waits for the first, and that wait is stamped as latency of the second event, not silently dropped. The report that comes out of the histograms is deliberately dull, and it refuses to print a percentile it cannot support.

def report(window_s: int) -> None:
    for stage, h in H.items():
        n = h.get_total_count()
        p = lambda q: h.get_value_at_percentile(q) / 1e6   # ns -> ms
        line = f"{stage:7s} n={n:6d} p50={p(50):7.2f} p95={p(95):7.2f} max={h.get_max_value()/1e6:7.2f}"
        if n >= 1000:
            line += f" p99={p(99):7.2f}"
        else:
            line += "  p99: not quoted, n < 1000"
        print(line)
        h.reset()          # one window, one histogram; the export keeps the encoded copy

# the same window on the wall side, kept by the tracker (§ 05):
#   submitted -> included   wall seconds, per transaction, own histogram
#   included  -> final      blocks, and how many were reorganised out

§ 05Submission is not confirmation

t5 is when one node returned a hash. All that proves is that one node accepted the bytes into its mempool. The transaction still has to propagate, be picked by a block producer, be included, and then survive long enough that its block is not replaced. On the chain the market settles on, the block interval is on the order of seconds, so inclusion sits an order of magnitude beyond the 100 ms budget, and it is measured on wall clock and block numbers, not on the segment clock. That is why the project page times blockchain confirmation separately: the budget is about being early; confirmation is about being right about what happened.

The state that tracks a transaction after t5 is keyed by block hash, not by block number, because a number can be reused by a competing block after a reorganisation. A transaction moves pending → included → final, and can move back from included to pending if the block that held it leaves the canonical chain, or to dropped if the mempool discards it. Until final, the position record does not claim a fill. The same reorg logic, applied in the other direction, is what the reconstruction side of The markets project needs to read public logs honestly (N.07).

PENDING, INCLUDED, FINAL, DROPPED = "pending", "included", "final", "dropped"

class TxTracker:
    def __init__(self, k_final: int, ttl_blocks: int):
        self.k, self.ttl = k_final, ttl_blocks
        self.txs = {}          # hash -> {state, block_hash, number, sub_wall_ns, sub_block}

    def submitted(self, h, wall_ns, head):
        self.txs[h] = dict(state=PENDING, block_hash=None, number=None,
                           sub_wall_ns=wall_ns, sub_block=head)

    def on_block(self, blk):   # blk: number, hash, parent_hash, tx_hashes, ts_wall_ns
        for h in blk.tx_hashes:
            tx = self.txs.get(h)
            if tx and tx["state"] == PENDING:
                tx.update(state=INCLUDED, block_hash=blk.hash, number=blk.number)
                H_INCL.record_value(blk.ts_wall_ns - tx["sub_wall_ns"])
        for h, tx in self.txs.items():
            if tx["state"] == INCLUDED and blk.number - tx["number"] >= self.k:
                tx["state"] = FINAL
            elif tx["state"] == PENDING and blk.number - tx["sub_block"] > self.ttl:
                tx["state"] = DROPPED         # and the position record is told

    def on_reorg(self, removed_hashes: set):
        # every tx whose block left the canonical chain goes back to pending;
        # it will be re-seen if the new chain includes it, or expire into DROPPED
        for tx in self.txs.values():
            if tx["state"] == INCLUDED and tx["block_hash"] in removed_hashes:
                tx.update(state=PENDING, block_hash=None, number=None)
                REORGS.inc()

§ 06Failure modes

Garbage collection. Python's cyclic collector runs when allocation counters trip, and a generation-2 pass over a large heap costs tens of milliseconds, which is most of the budget. Three things help: freezing the long-lived heap after warm-up with gc.freeze(), keeping the hot path free of allocations that create cycles, and registering gc.callbacks so that every pause is stamped into its own histogram. A pause that appears in the record is a fact; one that only appears as a fatter tail is a mystery.

Node lag. The RPC node I submit through can fall behind the head of the chain. Then a transaction is built against a stale nonce or a market that has already resolved, and the node's eth_sendRawTransaction latency, which is its own histogram, quietly doubles. I compare the node's head against a second source and treat drift beyond a couple of blocks as an outage, not a slow day.

Mempool. A transaction priced below what producers are accepting sits, and a nonce gap holds every transaction behind it. The policy is written down: a bounded fee bump on replacement, and a deadline in blocks after which the intent is cancelled and the position record is told the order did not fill. Reorganisations are the same problem seen later: a fill that was true at block n is not true if block n is replaced, which is what § 05 exists for.

Silence. A websocket feed can stop without closing. A heartbeat with a deadline, resubscription, and deduplication by event id on reconnect keep the stream honest, and the length of every silence is a metric. Bursts turn latency into queueing, which the queue stage exposes. And clocks: a source's timestamp compared with my wall clock measures nothing unless both are disciplined, and even then it is a different figure from the monotonic segment and is labelled as such. Most of these are host questions as much as code questions, which is why the engine runs on a controlled Linux environment (N.09).

§ 07What the number is allowed to claim

So the sentence on the project page reads the way it does. Under selected conditions means: this class of event from this kind of source, a warm process, no burst, the RPC node in-region. Under 100 ms means the p95 of t0 → t5 over a window with enough samples for p95 to be stable, read off the histogram, not the mean, with the sample count next to it. And separately, on their own clocks: wall-clock time to inclusion, the finality depth used, and the fraction of submitted transactions that were dropped or reorganised out. A latency figure that comes with those attachments can be checked against the record. One that does not is a mood.