From bbc1b4f2a85025c41e370ddbe6dcd14bce7743bf Mon Sep 17 00:00:00 2001 From: Dhruv Kumar Singh Date: Sat, 1 Aug 2026 16:05:09 +0530 Subject: [PATCH 1/8] Attribute trace events to hosts and record deliveries --- docs/design.md | 7 +- src/simloop/_loop.py | 37 ++++-- src/simloop/_net.py | 37 +++++- src/simloop/_trace.py | 43 +++++-- tests/test_trace.py | 276 +++++++++++++++++++++++++++++++++++++++++- 5 files changed, 375 insertions(+), 25 deletions(-) diff --git a/docs/design.md b/docs/design.md index 3ccaba1..6b6222d 100644 --- a/docs/design.md +++ b/docs/design.md @@ -99,10 +99,11 @@ properties are load-bearing: - **Completeness.** Even a *cancelled* handle's draw is recorded — the draw consumed PRNG state, so it is a scheduling decision, and a replay that made a different set of draws must produce a different hash. -- **Injectivity.** Events serialize as `kind|when|seq|label` lines into a +- **Injectivity.** Events serialize as `kind|when|seq|host|label` lines into a SHA-256. Labels are qualified callback names or network labels built from - validated host names, and host names may not contain `|`, `>` or newline — - so two distinct event streams cannot collide onto one byte sequence. + validated host names, the host field is a validated host name itself, and + host names may not contain `|`, `>` or newline — so two distinct event + streams cannot collide onto one byte sequence. Hash equality is therefore a cheap, sufficient check that a replay was *exact*, not merely same-outcome. It is asserted all over the test suite and diff --git a/src/simloop/_loop.py b/src/simloop/_loop.py index a48a303..2d3ab0d 100644 --- a/src/simloop/_loop.py +++ b/src/simloop/_loop.py @@ -17,7 +17,7 @@ if TYPE_CHECKING: from asyncio.events import _TaskFactory -from simloop._net import SimNetwork +from simloop._net import DRIVER, SimNetwork, _current_host from simloop._policy import ( CHOICE_TYPECODE, MAX_CHOICE, @@ -72,6 +72,23 @@ def _label(callback: Callable[..., object]) -> str: return type(callback).__name__ +def _host_of(handle: asyncio.Handle) -> str: + """The simulated machine whose code this handle will run. + + asyncio copies the scheduling context into every handle, and a task hands + its own context to each of its steps, so the pinned host travels with the + callback rather than with whoever happened to wake it: a task woken by a + packet from another machine is still attributed to its own. Reading it + here rather than at scheduling time is what makes that true. + + ``Context.get`` looks up what was *set* in that context and never falls + back to the ContextVar's own default, so callbacks scheduled outside any + host — the test driver's — have to be named explicitly. + """ + host: str = handle.get_context().get(_current_host, DRIVER) + return host + + class SimLoop(asyncio.AbstractEventLoop): """An event loop where time is virtual and execution order is seeded. @@ -211,7 +228,10 @@ def call_soon( self._next_seq += 1 label = _label(callback) self._ready.append((seq, label, handle)) - self._recorder.record("schedule", self._now, seq, label) + # A schedule event names the host that *asked* for the callback, which + # is not always the one that will run it: that difference is exactly + # how a wakeup crossing machines shows up in the trace. + self._recorder.record("schedule", self._now, seq, label, _current_host.get()) return handle def call_later( @@ -269,7 +289,7 @@ def _call_at_true( self._next_seq += 1 label = _label(callback) heapq.heappush(self._timers, (when, seq, label, timer)) - self._recorder.record("schedule", self._now, seq, label) + self._recorder.record("schedule", self._now, seq, label, _current_host.get()) return timer def _step(self) -> None: @@ -282,18 +302,19 @@ def _step(self) -> None: assert index <= MAX_CHOICE, "ready queue outgrew the choice log" self._choice_log.append(index) seq, label, handle = self._ready.pop(index) + host = _host_of(handle) if handle.cancelled(): # The draw itself is a scheduling decision, so a skipped handle # must appear in the trace for the replay proof to stay complete. - self._recorder.record("cancel", self._now, seq, label) + self._recorder.record("cancel", self._now, seq, label, host) return - self._recorder.record("run", self._now, seq, label) + self._recorder.record("run", self._now, seq, label, host) handle._run() def _advance_clock(self) -> None: while self._timers and self._timers[0][3].cancelled(): - _, seq, label, _timer = heapq.heappop(self._timers) - self._recorder.record("cancel", self._now, seq, label) + _, seq, label, timer = heapq.heappop(self._timers) + self._recorder.record("cancel", self._now, seq, label, _host_of(timer)) if not self._timers: raise SimulationDeadlockError( "nothing left to run: no ready callbacks and no pending timers" @@ -303,7 +324,7 @@ def _advance_clock(self) -> None: while self._timers and self._timers[0][0] <= self._now: _, seq, label, timer = heapq.heappop(self._timers) if timer.cancelled(): - self._recorder.record("cancel", self._now, seq, label) + self._recorder.record("cancel", self._now, seq, label, _host_of(timer)) else: self._ready.append((seq, label, timer)) diff --git a/src/simloop/_net.py b/src/simloop/_net.py index 9dd4299..f5ba09a 100644 --- a/src/simloop/_net.py +++ b/src/simloop/_net.py @@ -12,7 +12,7 @@ import random import socket from collections.abc import Iterable, Iterator, MutableMapping -from contextvars import ContextVar +from contextvars import Context, ContextVar, copy_context from dataclasses import dataclass from typing import TYPE_CHECKING, Any @@ -25,6 +25,13 @@ DRIVER = "driver" +# What runs under no machine at all: the network's own delivery step, which +# belongs to the wire between two hosts rather than to either of them. No +# registered host can be named this (``SimNetwork.host`` rejects an empty +# name), so it can never be confused with one, and it is exactly what an empty +# host field means in the trace. +WIRE = "" + _current_host: ContextVar[str] = ContextVar("simloop_current_host", default=DRIVER) # Host names appear inside trace labels, whose hash serialization relies on @@ -55,6 +62,23 @@ def _format_address(index: int) -> str: return ".".join(str((packed >> shift) & 0xFF) for shift in (24, 16, 8, 0)) +def _wire_context() -> Context: + """A context in which no machine owns the running callback. + + A delivery is scheduled by whichever machine sent the packet, so a handle + left to copy the ambient context would make the trace read as if the + sender ran the delivery step. It did not: crossing the wire is the + simulation's work, and ``_deliver`` pins the *receiving* host itself before + handing the packet up. Everything else the caller's context carries is + copied through untouched. + """ + token = _current_host.set(WIRE) + try: + return copy_context() + finally: + _current_host.reset(token) + + def _gaierror(what: Any) -> socket.gaierror: # EAI_NONAME is what a real resolver returns for a name that does not # exist, so callers that special-case it keep working under simulation. @@ -549,7 +573,10 @@ def _transmit(self, packet: _Packet) -> None: def _schedule(self, packet: _Packet, latency: tuple[float, float]) -> None: self._trace("send", packet) delay = self._rng.uniform(latency[0], latency[1]) - self._loop.call_later(delay, self._deliver, packet) + # The schedule event still names the sender — call_later reads the live + # context, which the wire context is built and discarded around — while + # the delivery step itself is attributed to no machine. + self._loop.call_later(delay, self._deliver, packet, context=_wire_context()) def _deliver(self, packet: _Packet) -> None: if not (self._alive[packet.src] and self._alive[packet.dst]): @@ -559,6 +586,12 @@ def _deliver(self, packet: _Packet) -> None: # The cut appeared while this packet was in flight. self._blackhole(packet) return + # The packet reached the destination machine: every "send" that is not + # answered by a drop, hold or loss is answered by exactly this, which + # is what turns the packet log into a set of arrows with two ends. + # What the machine then does with it — hand it to a socket, discard it + # for want of one, hold it for an earlier sequence — is its own affair. + self._trace("deliver", packet) # Anything the receiving protocol schedules (including tasks spawned # from connection_made or datagram_received) must be pinned to the # receiving host, not to whichever context sent the packet. diff --git a/src/simloop/_trace.py b/src/simloop/_trace.py index 6de7a7c..43f80c8 100644 --- a/src/simloop/_trace.py +++ b/src/simloop/_trace.py @@ -7,26 +7,43 @@ from __future__ import annotations import hashlib -from dataclasses import dataclass -from typing import Literal +from typing import Literal, NamedTuple EventKind = Literal["schedule", "run", "advance", "cancel", "net"] -@dataclass(frozen=True, slots=True) -class TraceEvent: +class TraceEvent(NamedTuple): + """One decision, immutable, named. + + A named tuple rather than a frozen dataclass because one of these is built + for every callback the simulation ever schedules and runs: a frozen + dataclass assigns each field through ``object.__setattr__``, which costs + more than twice as much per event and is paid on the hottest path in the + package. Immutability, attribute access and equality are unchanged. + """ + kind: EventKind when: float seq: int label: str + # The simulated machine whose code this event belongs to, for the + # scheduling kinds that have one. Empty for events that belong to the + # simulation rather than to a machine: a clock advance is global, a packet + # event belongs to a link whose ends its label already names, and the + # network's own delivery step belongs to the wire. No registered host can + # be named "" (SimNetwork.host rejects an empty name), so it is never + # mistakable for one. + host: str = "" class TraceRecorder: def __init__(self) -> None: self._events: list[TraceEvent] = [] - def record(self, kind: EventKind, when: float, seq: int, label: str) -> None: - self._events.append(TraceEvent(kind, when, seq, label)) + def record( + self, kind: EventKind, when: float, seq: int, label: str, host: str = "" + ) -> None: + self._events.append(TraceEvent(kind, when, seq, label, host)) def __len__(self) -> int: # How many events so far, without building the snapshot tuple that @@ -42,10 +59,14 @@ def hash(self) -> str: digest = hashlib.sha256() for event in self._events: # Labels are qualified callback names or network labels built from - # validated host names, so they cannot contain the "|" field - # separator or a newline. That keeps this delimiter-based - # serialization injective: two distinct event streams can never - # collide onto the same byte sequence. - line = f"{event.kind}|{event.when!r}|{event.seq}|{event.label}\n" + # validated host names, and a host field is a validated host name + # itself, so neither can contain the "|" field separator or a + # newline (host names reject both — _net.py:33). That keeps this + # delimiter-based serialization injective: every field is + # recoverable from the line, so two distinct event streams can + # never collide onto the same byte sequence. + line = ( + f"{event.kind}|{event.when!r}|{event.seq}|{event.host}|{event.label}\n" + ) digest.update(line.encode("utf-8")) return digest.hexdigest() diff --git a/tests/test_trace.py b/tests/test_trace.py index 134fff8..35aec9b 100644 --- a/tests/test_trace.py +++ b/tests/test_trace.py @@ -1,4 +1,13 @@ -from simloop._trace import TraceRecorder +"""The trace record: ordering, host attribution and hash injectivity.""" + +from __future__ import annotations + +import asyncio + +import pytest + +from simloop import SimLoop +from simloop._trace import TraceEvent, TraceRecorder def test_events_are_recorded_in_order() -> None: @@ -35,3 +44,268 @@ def test_cancel_events_change_the_hash() -> None: second.record("run", 0.0, 0, "f") second.record("cancel", 0.0, 1, "g") assert first.hash() != second.hash() + + +def test_events_are_immutable_and_hostless_by_default() -> None: + event = TraceEvent("run", 0.0, 0, "f") + assert event.host == "" + assert TraceEvent._fields == ("kind", "when", "seq", "label", "host") + assert not hasattr(event, "__dict__") + with pytest.raises(AttributeError): + event.host = "alpha" # type: ignore[misc] + + +def test_the_host_field_is_part_of_the_hash() -> None: + first, second = TraceRecorder(), TraceRecorder() + first.record("run", 0.0, 0, "f", host="alpha") + second.record("run", 0.0, 0, "f", host="beta") + assert first.hash() != second.hash() + assert first.events[0].host == "alpha" + + +def test_the_host_field_is_delimited_from_the_label() -> None: + # Without a separator between the two fields, "ab" + "" and "a" + "b" + # would serialize to the same bytes; the delimiter is what keeps the + # serialization injective. + first, second = TraceRecorder(), TraceRecorder() + first.record("run", 0.0, 0, "", host="ab") + second.record("run", 0.0, 0, "b", host="a") + assert first.hash() != second.hash() + + +# ---------------------------------------------------------------------- +# Attribution and delivery under a real run +# ---------------------------------------------------------------------- + + +async def _echo_once( + reader: asyncio.StreamReader, writer: asyncio.StreamWriter +) -> None: + writer.write((await reader.readline()).upper()) + await writer.drain() + writer.close() + await writer.wait_closed() + + +def _run_stream_exchange(seed: int = 0) -> SimLoop: + loop = SimLoop(seed=seed) + loop.net.host("server") + loop.net.host("client") + loop.net.set_defaults(latency=(0.01, 0.02)) + + async def serve() -> None: + server = await asyncio.start_server(_echo_once, "0.0.0.0", 9000) + async with server: + await asyncio.sleep(10.0) + + async def request() -> bytes: + reader, writer = await asyncio.open_connection("server", 9000) + writer.write(b"ping\n") + await writer.drain() + reply = await reader.readline() + writer.close() + await writer.wait_closed() + return reply + + async def main() -> bytes: + serve_task = loop.net.host("server").create_task(serve()) + await asyncio.sleep(0.01) + reply: bytes = await loop.net.host("client").create_task(request()) + serve_task.cancel() + try: + await serve_task + except asyncio.CancelledError: + pass + # Let the teardown packets land: a packet still in flight when the run + # ends has been sent and not yet delivered, which is honest but says + # nothing about whether deliveries are recorded. + await asyncio.sleep(0.5) + return reply + + try: + assert loop.run_until_complete(main()) == b"PING\n" + finally: + loop.close() + return loop + + +class _Collector(asyncio.DatagramProtocol): + def __init__(self) -> None: + self.received: list[bytes] = [] + + def datagram_received(self, data: bytes, addr: tuple[str, int]) -> None: + self.received.append(data) + + +def _run_datagram_exchange(seed: int, *, drop: float, count: int) -> SimLoop: + loop = SimLoop(seed=seed) + alpha = loop.net.host("alpha") + beta = loop.net.host("beta") + loop.net.set_defaults(latency=(0.01, 0.02)) + loop.net.set_link("beta", "alpha", drop=drop) + + async def bind(port: int) -> tuple[asyncio.DatagramTransport, _Collector]: + endpoint: tuple[asyncio.DatagramTransport, _Collector] = ( + await asyncio.get_running_loop().create_datagram_endpoint( + _Collector, local_addr=("0.0.0.0", port) + ) + ) + return endpoint + + async def main() -> None: + receiver, _ = await alpha.create_task(bind(7000)) + sender, _ = await beta.create_task(bind(7001)) + + async def send_all() -> None: + for number in range(count): + sender.sendto(f"ping{number}".encode(), ("alpha", 7000)) + await asyncio.sleep(0.05) + + await beta.create_task(send_all()) + await asyncio.sleep(1.0) + receiver.close() + sender.close() + await asyncio.sleep(0.01) + + try: + loop.run_until_complete(main()) + finally: + loop.close() + return loop + + +def _verbs_by_uid(loop: SimLoop) -> dict[int, list[str]]: + verbs: dict[int, list[str]] = {} + for event in loop.trace: + if event.kind == "net": + verbs.setdefault(event.seq, []).append(event.label.split(" ", 1)[0]) + return verbs + + +def test_run_events_are_attributed_to_the_executing_host() -> None: + loop = _run_stream_exchange() + run_hosts = {event.host for event in loop.trace if event.kind == "run"} + assert {"client", "server"} <= run_hosts + + +def test_network_and_clock_events_carry_no_host() -> None: + # A packet event belongs to a link, not a machine: its label already + # names both ends, and a clock advance belongs to the whole simulation. + loop = _run_stream_exchange() + assert [event for event in loop.trace if event.kind == "net"] + assert all( + event.host == "" for event in loop.trace if event.kind in ("net", "advance") + ) + + +def test_delivery_steps_belong_to_the_wire_not_the_sender() -> None: + # Crossing the wire is the simulation's work: the sender asked for it (so + # the schedule event names it), but no machine's code is what runs. + loop = _run_stream_exchange() + deliveries = [event for event in loop.trace if event.label == "SimNetwork._deliver"] + runs = [event for event in deliveries if event.kind in ("run", "cancel")] + schedules = [event for event in deliveries if event.kind == "schedule"] + assert runs and schedules + assert {event.host for event in runs} == {""} + assert {"client", "server"} <= {event.host for event in schedules} + + +def test_scheduling_events_name_the_host_that_scheduled_them() -> None: + loop = _run_stream_exchange() + schedule_hosts = {event.host for event in loop.trace if event.kind == "schedule"} + assert {"client", "server", "driver"} <= schedule_hosts + + +def test_every_arriving_packet_is_recorded_as_delivered() -> None: + loop = _run_stream_exchange() + labels = [event.label for event in loop.trace if event.kind == "net"] + assert "deliver client>server" in labels + assert "deliver server>client" in labels + verbs = _verbs_by_uid(loop) + assert verbs + for uid, seen in verbs.items(): + if "send" not in seen: + continue + assert seen.count("deliver") == 1, (uid, seen) + + +def test_held_stream_packets_are_sent_again_and_delivered_once() -> None: + # The two shapes a partition produces, and the reason a reader cannot + # assume one "send" per uid: a packet already in flight when the cut lands + # is sent, held on arrival, then sent a second time after the heal; a + # packet written while the cut stands never leaves, so it is held with no + # "send" at all. Both end in exactly one "deliver". + loop = SimLoop(seed=0) + server = loop.net.host("server") + client = loop.net.host("client") + loop.net.set_defaults(latency=(0.05, 0.05)) + lines: list[bytes] = [] + + async def collect( + reader: asyncio.StreamReader, writer: asyncio.StreamWriter + ) -> None: + while line := await reader.readline(): + lines.append(line) + writer.close() + + async def serve() -> None: + listener = await asyncio.start_server(collect, "0.0.0.0", 9000) + async with listener: + await asyncio.sleep(10.0) + + async def connect() -> asyncio.StreamWriter: + _, writer = await asyncio.open_connection("server", 9000) + return writer + + async def main() -> None: + serve_task = server.create_task(serve()) + await asyncio.sleep(0.01) + # Writes carry the transport's own host as their source, so the driver + # can drive both ends of the exchange from here. + writer: asyncio.StreamWriter = await client.create_task(connect()) + writer.write(b"first\n") + await asyncio.sleep(0.01) # still in flight: latency is 0.05 + loop.net.partition({"client"}, {"server"}) + await asyncio.sleep(0.2) # its delivery lands on the cut and is held + writer.write(b"second\n") # never leaves: held at transmission + await asyncio.sleep(0.2) + loop.net.heal() + await asyncio.sleep(0.5) + writer.close() + await asyncio.sleep(0.3) + serve_task.cancel() + try: + await serve_task + except asyncio.CancelledError: + pass + await asyncio.sleep(0.5) + + try: + loop.run_until_complete(main()) + finally: + loop.close() + + assert lines == [b"first\n", b"second\n"] + verbs = _verbs_by_uid(loop) + held = [seen for seen in verbs.values() if "hold" in seen] + assert held == [ + ["send", "hold", "release", "send", "deliver"], + ["hold", "release", "send", "deliver"], + ] + for uid, seen in verbs.items(): + assert seen.count("deliver") <= 1, (uid, seen) + + +def test_dropped_datagrams_are_never_delivered() -> None: + loop = _run_datagram_exchange(seed=0, drop=0.5, count=12) + verbs = _verbs_by_uid(loop) + dropped = [uid for uid, seen in verbs.items() if "drop" in seen] + delivered = [uid for uid, seen in verbs.items() if "deliver" in seen] + assert dropped and delivered + for uid in dropped: + assert "send" not in verbs[uid] + assert "deliver" not in verbs[uid] + for uid, seen in verbs.items(): + if "send" not in seen or {"drop", "lost", "hold", "dup"} & set(seen): + continue + assert seen.count("deliver") == 1, (uid, seen) From 5fcc2bc1c4872552a29a92a0f87ecca09f5321e1 Mon Sep 17 00:00:00 2001 From: Dhruv Kumar Singh Date: Sat, 1 Aug 2026 17:17:50 +0530 Subject: [PATCH 2/8] Show scheduling policies who is ready, not just how many --- src/simloop/_loop.py | 130 +++++++++++++++++++--- src/simloop/_policy.py | 45 ++++++-- src/simloop/_shrink.py | 4 +- tests/test_policy.py | 243 +++++++++++++++++++++++++++++++++++++++-- 4 files changed, 386 insertions(+), 36 deletions(-) diff --git a/src/simloop/_loop.py b/src/simloop/_loop.py index 2d3ab0d..d219304 100644 --- a/src/simloop/_loop.py +++ b/src/simloop/_loop.py @@ -8,11 +8,12 @@ import random import socket import sys +import weakref from array import array from asyncio import events from collections.abc import Callable, Iterable, Sequence from contextvars import Context -from typing import TYPE_CHECKING, Any, NoReturn, TypeVarTuple, Unpack +from typing import TYPE_CHECKING, Any, NoReturn, TypeVarTuple, Unpack, overload if TYPE_CHECKING: from asyncio.events import _TaskFactory @@ -21,6 +22,7 @@ from simloop._policy import ( CHOICE_TYPECODE, MAX_CHOICE, + ReadyView, SchedulingPolicy, ScriptedPolicy, SeededPolicy, @@ -89,6 +91,70 @@ def _host_of(handle: asyncio.Handle) -> str: return host +# What the loop remembers about one runnable callback: its seq, the label the +# trace records, the handle that runs it, and the callback itself — kept +# because that is where a task step says which task it belongs to, and a +# handle's callback is private to asyncio. +_ReadyEntry = tuple[int, str, asyncio.Handle, Callable[..., object]] + + +class _ReadyViews(Sequence[ReadyView]): + """The ready queue as a policy sees it, named only where it looks. + + Naming the owner of a callback costs a lookup, and the two policies that + ship with simloop — the seeded default and the scripted replay — decide + on the length of the queue alone. So nothing is built up front: ``len`` + is the queue's length and only an entry that is actually indexed pays for + its view. A policy that reads every entry, as a priority policy does, + pays exactly what an eagerly built list would have cost. + + One instance serves the whole loop, over the live ready queue rather than + a copy, so a step costs no allocation at all. The consequence is that the + sequence describes the queue *now*: it is meant to be read inside + ``choose`` and is not a snapshot to keep. + + Views are recomputed rather than cached, which is safe because computing + one has no side effect — the owner numbers are handed out in + ``create_task``, long before anything here looks at them — so indexing an + entry twice simply returns equal tuples. + """ + + __slots__ = ("_entries", "_owners") + + def __init__( + self, + entries: list[_ReadyEntry], + owners: weakref.WeakKeyDictionary[asyncio.Task[Any], int], + ) -> None: + self._entries = entries + self._owners = owners + + def __len__(self) -> int: + return len(self._entries) + + @overload + def __getitem__(self, index: int) -> ReadyView: ... + + @overload + def __getitem__(self, index: slice) -> Sequence[ReadyView]: ... + + def __getitem__(self, index: int | slice) -> ReadyView | Sequence[ReadyView]: + if isinstance(index, slice): + return [self[position] for position in range(*index.indices(len(self)))] + seq, label, _, callback = self._entries[index] + # A task drives every one of its steps through ``call_soon``, and the + # callback it passes is bound to the task, so ``__self__`` is where a + # step says whose work it is. Anything no task owns is named by its + # own seq, negated so the two kinds can never be confused and no two + # unowned callbacks ever share a number. + task = getattr(callback, "__self__", None) + if isinstance(task, asyncio.Task): + owner = self._owners.get(task) + if owner is not None: + return (owner, label) + return (-1 - seq, label) + + class SimLoop(asyncio.AbstractEventLoop): """An event loop where time is virtual and execution order is seeded. @@ -119,13 +185,29 @@ def __init__(self, seed: int = 0) -> None: self._user_random = random.Random(f"{seed}:random") self._uuid_random = random.Random(f"{seed}:uuid") self._now = 0.0 - # Ready entries are (seq, label, handle); seq is a global creation - # counter that gives every scheduled callback a stable identity. - self._ready: list[tuple[int, str, asyncio.Handle]] = [] - # Timer heap entries are (when, seq, label, handle). seq breaks ties - # between equal deadlines, so handles themselves are never compared. - self._timers: list[tuple[float, int, str, asyncio.TimerHandle]] = [] + # Ready entries are (seq, label, handle, callback); seq is a global + # creation counter that gives every scheduled callback a stable + # identity. + self._ready: list[_ReadyEntry] = [] + # Timer heap entries are (when, seq, label, handle, callback). seq + # breaks ties between equal deadlines, so nothing after it — handles + # and callbacks above all — is ever compared. + self._timers: list[ + tuple[float, int, str, asyncio.TimerHandle, Callable[..., object]] + ] = [] self._next_seq = 0 + # Which task each of this loop's tasks is, as a number a policy can + # compare: creation order, counted per loop so it is a property of + # the run and not of the process. Weakly keyed because a long + # campaign creates tasks by the million and this map must never be + # the reason one of them stays alive. + self._task_owners: weakref.WeakKeyDictionary[asyncio.Task[Any], int] = ( + weakref.WeakKeyDictionary() + ) + self._next_owner = 0 + # Built once and reused: it reads the queue in place, so handing it + # to the policy on every step costs nothing. + self._ready_views = _ReadyViews(self._ready, self._task_owners) self._recorder = TraceRecorder() self._running = False self._closed = False @@ -227,7 +309,7 @@ def call_soon( seq = self._next_seq self._next_seq += 1 label = _label(callback) - self._ready.append((seq, label, handle)) + self._ready.append((seq, label, handle, callback)) # A schedule event names the host that *asked* for the callback, which # is not always the one that will run it: that difference is exactly # how a wakeup crossing machines shows up in the trace. @@ -288,7 +370,7 @@ def _call_at_true( seq = self._next_seq self._next_seq += 1 label = _label(callback) - heapq.heappush(self._timers, (when, seq, label, timer)) + heapq.heappush(self._timers, (when, seq, label, timer, callback)) self._recorder.record("schedule", self._now, seq, label, _current_host.get()) return timer @@ -298,10 +380,15 @@ def _step(self) -> None: # The one ordering decision in the whole loop, and the policy owns it: # every scheduling decision flows through this call, which is seeded # by default and scriptable for replay. - index = self._policy.choose(len(self._ready)) + # + # This is the hottest call in the package, and the sequence handed + # over is a standing view of the ready queue rather than a list built + # here, so a policy that decides on the count alone — the default one + # does — costs a step nothing at all. + index = self._policy.choose(self._ready_views) assert index <= MAX_CHOICE, "ready queue outgrew the choice log" self._choice_log.append(index) - seq, label, handle = self._ready.pop(index) + seq, label, handle, _ = self._ready.pop(index) host = _host_of(handle) if handle.cancelled(): # The draw itself is a scheduling decision, so a skipped handle @@ -313,7 +400,7 @@ def _step(self) -> None: def _advance_clock(self) -> None: while self._timers and self._timers[0][3].cancelled(): - _, seq, label, timer = heapq.heappop(self._timers) + _, seq, label, timer, _ = heapq.heappop(self._timers) self._recorder.record("cancel", self._now, seq, label, _host_of(timer)) if not self._timers: raise SimulationDeadlockError( @@ -322,11 +409,11 @@ def _advance_clock(self) -> None: self._now = max(self._now, self._timers[0][0]) self._recorder.record("advance", self._now, -1, "") while self._timers and self._timers[0][0] <= self._now: - _, seq, label, timer = heapq.heappop(self._timers) + _, seq, label, timer, callback = heapq.heappop(self._timers) if timer.cancelled(): self._recorder.record("cancel", self._now, seq, label, _host_of(timer)) else: - self._ready.append((seq, label, timer)) + self._ready.append((seq, label, timer, callback)) # ------------------------------------------------------------------ # Running @@ -444,9 +531,24 @@ def create_task( set_name = getattr(task, "set_name", None) if set_name is not None: set_name(name) + # The task queued its own first step from its constructor, but no + # policy can have looked at the ready queue since — the loop is not + # running here — so numbering it now still names that first step. + self._task_owners[task] = self._next_owner + self._next_owner += 1 self._net._register_task(task) return task + def _task_owner(self, task: asyncio.Task[Any]) -> int: + """Which task this is, counted in creation order on this loop. + + The number a policy sees in the ready view of every step ``task`` + takes. Only tasks this loop created have one: a bare + ``asyncio.Task(coro)`` never passes through here, and its steps are + named individually instead, as any other unowned callback is. + """ + return self._task_owners[task] + async def create_datagram_endpoint( self, protocol_factory: Any, diff --git a/src/simloop/_policy.py b/src/simloop/_policy.py index 1703166..f4c34d5 100644 --- a/src/simloop/_policy.py +++ b/src/simloop/_policy.py @@ -11,7 +11,7 @@ import random from array import array -from collections.abc import Iterable +from collections.abc import Iterable, Sequence from typing import Protocol # One choice per step adds up over a long run, so choice lists are stored as @@ -21,13 +21,34 @@ CHOICE_TYPECODE = "L" MAX_CHOICE = 2 ** (8 * array(CHOICE_TYPECODE).itemsize) - 1 +ReadyView = tuple[int, str] +"""What a policy is told about one runnable callback: ``(owner, label)``. + +``owner`` names who the callback belongs to. Every step of a task carries +that task's creation index on this loop, a non-negative number that is the +same at every step the task takes, so a policy can tell "this task again" +from "a different task". A callback no task owns — a bare ``call_soon``, a +timer, a protocol callback — gets a negative number unique to it, which is +never equal to another entry's and never mistakable for a task. + +``label`` is the same qualified callback name the trace records. + +Deliberately a plain tuple and not the handle: a policy decides order, and +handing it something it could *run* would make that a matter of trust rather +than of construction. +""" + class SchedulingPolicy(Protocol): - """Chooses which of ``ready`` runnable callbacks runs next.""" + """Chooses which of the ``ready`` runnable callbacks runs next. + + The return value indexes ``ready``. Policies are free to ignore the views + and decide on the count alone — the two shipped here do. + """ diverged_at: int | None - def choose(self, ready: int) -> int: ... + def choose(self, ready: Sequence[ReadyView]) -> int: ... class SeededPolicy: @@ -35,20 +56,26 @@ class SeededPolicy: Built from the seed value the loop was given and drawing with ``randrange``, so the sequence of draws — and therefore the trace hash — - is what the loop produced when it owned the PRNG itself. + is what the loop produced when it owned the PRNG itself. The ready views + are deliberately unread: a uniform draw over the queue is defined by its + length, and consulting anything else would move every recorded trace. """ def __init__(self, seed: int) -> None: self._rng = random.Random(seed) self.diverged_at: int | None = None # a seeded run has nothing to diverge from - def choose(self, ready: int) -> int: - return self._rng.randrange(ready) + def choose(self, ready: Sequence[ReadyView]) -> int: + return self._rng.randrange(len(ready)) class ScriptedPolicy: """Replays a recorded sequence of scheduler choices. + Only the length of the ready queue is read, never the views: a recording + is a list of indices, and an index means what it meant when it was + recorded only if nothing else enters the decision. + Drift is tolerated rather than fatal. A choice list edited by hand, or replayed against a run that took a different turn, can name an index the ready queue no longer has: that clamps to the last ready callback, and a @@ -69,16 +96,16 @@ def __init__(self, choices: Iterable[int]) -> None: self._step = 0 self.diverged_at: int | None = None - def choose(self, ready: int) -> int: + def choose(self, ready: Sequence[ReadyView]) -> int: step = self._step self._step += 1 if step >= len(self._choices): self._diverge(step) return 0 choice = self._choices[step] - if choice >= ready: + if choice >= len(ready): self._diverge(step) - return ready - 1 + return len(ready) - 1 return choice def _diverge(self, step: int) -> None: diff --git a/src/simloop/_shrink.py b/src/simloop/_shrink.py index dba8cb2..8d36084 100644 --- a/src/simloop/_shrink.py +++ b/src/simloop/_shrink.py @@ -22,7 +22,7 @@ from dataclasses import dataclass from simloop._loop import SimLoop -from simloop._policy import SchedulingPolicy +from simloop._policy import ReadyView, SchedulingPolicy from simloop._run import Workload, finish, run_once from simloop._trace import TraceRecorder @@ -299,7 +299,7 @@ def __init__(self, inner: SchedulingPolicy, recorder: TraceRecorder) -> None: self.diverged_at: int | None = None self.at: list[int] = [] - def choose(self, ready: int) -> int: + def choose(self, ready: Sequence[ReadyView]) -> int: self.at.append(len(self._recorder)) choice = self._inner.choose(ready) self.diverged_at = self._inner.diverged_at diff --git a/tests/test_policy.py b/tests/test_policy.py index 1fe6045..7d0eaba 100644 --- a/tests/test_policy.py +++ b/tests/test_policy.py @@ -1,11 +1,22 @@ import asyncio +import gc import random -from collections.abc import Callable +import weakref +from collections.abc import Callable, Sequence import pytest from simloop import Host, SimLoop -from simloop._policy import MAX_CHOICE, ScriptedPolicy, SeededPolicy +from simloop._policy import MAX_CHOICE, ReadyView, ScriptedPolicy, SeededPolicy + + +def _ready(count: int) -> list[ReadyView]: + """A ready queue of ``count`` views, contents deliberately arbitrary. + + The count-only policies must not read owners or labels, so the values + here are noise: any policy that looks at them is looking at nonsense. + """ + return [(-1 - index, f"callback{index}") for index in range(count)] def test_seeded_policy_matches_a_bare_random_stream() -> None: @@ -14,48 +25,68 @@ def test_seeded_policy_matches_a_bare_random_stream() -> None: sizes = [1, 2, 3, 7, 2, 64, 5, 1, 12, 3, 9] reference = random.Random(41) policy = SeededPolicy(41) - assert [policy.choose(n) for n in sizes] == [ + assert [policy.choose(_ready(n)) for n in sizes] == [ reference.randrange(n) for n in sizes ] +def test_seeded_policy_ignores_everything_but_the_ready_count() -> None: + # The property the whole schedule-identity guarantee rests on: widening + # the protocol gave the default policy more to look at, and it looks at + # none of it. Same lengths, wildly different views, identical draws. + sizes = [3, 1, 8, 2, 5, 5, 13] + plain = SeededPolicy(41) + exotic = SeededPolicy(41) + assert [plain.choose(_ready(n)) for n in sizes] == [ + exotic.choose([(7, "Task.task_wakeup")] * n) for n in sizes + ] + + def test_seeded_policy_never_diverges() -> None: policy = SeededPolicy(0) for _ in range(10): - policy.choose(4) + policy.choose(_ready(4)) assert policy.diverged_at is None def test_scripted_policy_replays_its_recording() -> None: policy = ScriptedPolicy([2, 0, 1]) - assert [policy.choose(3), policy.choose(4), policy.choose(2)] == [2, 0, 1] + assert [ + policy.choose(_ready(3)), + policy.choose(_ready(4)), + policy.choose(_ready(2)), + ] == [2, 0, 1] assert policy.diverged_at is None def test_scripted_policy_clamps_choices_past_the_ready_queue() -> None: policy = ScriptedPolicy([5, 1]) - assert policy.choose(3) == 2 + assert policy.choose(_ready(3)) == 2 assert policy.diverged_at == 0 - assert policy.choose(2) == 1 + assert policy.choose(_ready(2)) == 1 def test_scripted_policy_marks_only_the_first_divergence() -> None: policy = ScriptedPolicy([0, 9, 9]) - assert [policy.choose(4), policy.choose(2), policy.choose(2)] == [0, 1, 1] + assert [ + policy.choose(_ready(4)), + policy.choose(_ready(2)), + policy.choose(_ready(2)), + ] == [0, 1, 1] assert policy.diverged_at == 1 def test_exhausted_scripted_policy_falls_back_to_fifo() -> None: policy = ScriptedPolicy([1]) - assert policy.choose(3) == 1 + assert policy.choose(_ready(3)) == 1 assert policy.diverged_at is None - assert [policy.choose(3), policy.choose(3)] == [0, 0] + assert [policy.choose(_ready(3)), policy.choose(_ready(3))] == [0, 0] assert policy.diverged_at == 1 def test_empty_recording_is_pure_fifo() -> None: policy = ScriptedPolicy([]) - assert policy.choose(5) == 0 + assert policy.choose(_ready(5)) == 0 assert policy.diverged_at == 0 @@ -66,6 +97,196 @@ def test_scripted_policy_rejects_impossible_choices() -> None: ScriptedPolicy([MAX_CHOICE + 1]) +# ---------------------------------------------------------------------- +# What the loop shows the policy +# ---------------------------------------------------------------------- + + +class _Recording: + """Keeps every ready view the loop offers, then takes the oldest. + + FIFO rather than a draw, because what is under test is the view the loop + builds and not the order a policy picks from it. + """ + + def __init__(self) -> None: + self.diverged_at: int | None = None + self.steps: list[tuple[ReadyView, ...]] = [] + + def choose(self, ready: Sequence[ReadyView]) -> int: + self.steps.append(tuple(ready)) + return 0 + + +# One step's worth of probing: the count, the whole thing iterated, the first +# entry, the first entry again, the last entry, and a slice of all of it. +_Read = tuple[int, list[ReadyView], ReadyView, ReadyView, ReadyView, list[ReadyView]] + + +class _Probing: + """Reads the ready sequence every way a policy might, and keeps what it saw.""" + + def __init__(self) -> None: + self.diverged_at: int | None = None + self.reads: list[_Read] = [] + + def choose(self, ready: Sequence[ReadyView]) -> int: + self.reads.append( + ( + len(ready), + list(ready), # iteration + ready[0], + ready[0], # the same entry a second time + ready[-1], # counted from the end + list(ready[:]), # a slice + ) + ) + return 0 + + +async def _two_workers_and_two_callbacks() -> list[str]: + """Two tasks taking several steps each, alongside two bare callbacks.""" + loop = asyncio.get_running_loop() + log: list[str] = [] + loop.call_soon(log.append, "bare:first") + loop.call_soon(log.append, "bare:second") + + async def worker(name: str) -> None: + for number in range(3): + await asyncio.sleep(0) + log.append(f"{name}:{number}") + + first = asyncio.create_task(worker("one"), name="one") + second = asyncio.create_task(worker("two"), name="two") + await first + await second + return log + + +def _run_recorded() -> tuple[SimLoop, _Recording]: + loop = SimLoop(seed=3) + policy = _Recording() + loop._policy = policy + try: + loop.run_until_complete(_two_workers_and_two_callbacks()) + finally: + loop.close() + return loop, policy + + +def test_the_views_line_up_with_the_ready_queue() -> None: + loop, policy = _run_recorded() + ran = [event.label for event in loop.trace if event.kind == "run"] + assert not any(event.kind == "cancel" for event in loop.trace) + # The index a policy returns indexes the views it was handed, so the view + # at that index must describe the callback the step actually ran. This + # policy always takes the first, so the first view of every step names + # what ran — position for position, in step order. + assert [step[0][1] for step in policy.steps] == ran + assert all(len(step) > 0 for step in policy.steps) + + +def test_the_ready_sequence_reads_the_way_a_sequence_should() -> None: + # Views are built only where a policy looks, so every way of looking has + # to agree — and looking twice has to give the same answer. + loop = SimLoop(seed=3) + policy = _Probing() + loop._policy = policy + try: + loop.run_until_complete(_two_workers_and_two_callbacks()) + finally: + loop.close() + assert any(count > 1 for count, *_ in policy.reads) # not all queues of one + for count, iterated, first, again, last, sliced in policy.reads: + assert len(iterated) == count + assert first == iterated[0] + assert again == first + assert last == iterated[-1] + assert sliced == iterated + + +def test_the_ready_sequence_follows_the_live_queue() -> None: + loop = SimLoop(seed=3) + views = loop._ready_views + assert len(views) == 0 + # One sequence serves every step, reading the queue in place rather than + # copying it, which is what makes a step cost no allocation. + handle = loop.call_soon(print) + assert len(views) == 1 + assert views[0][1] == "print" + with pytest.raises(IndexError): + views[1] # what stops the Sequence mixin's iteration + handle.cancel() + loop.close() + + +def test_every_step_of_a_task_carries_that_task_s_id() -> None: + _, policy = _run_recorded() + owners = {owner for step in policy.steps for owner, _ in step if owner >= 0} + # The task run_until_complete wrapped the coroutine in, plus the two + # workers. An id that changed between a task's own steps would show up + # here as a fourth, and one shared between tasks as a second. + assert owners == {0, 1, 2} + assert sum(1 for step in policy.steps for owner, _ in step if owner >= 0) > 10 + + +def test_a_callback_no_task_owns_gets_a_negative_id_of_its_own() -> None: + _, policy = _run_recorded() + bare = { + (owner, label) + for step in policy.steps + for owner, label in step + if label == "list.append" + } + assert len(bare) == 2 # one per call_soon, each with an id of its own + assert all(owner < 0 for owner, _ in bare) + + +def test_the_loop_numbers_tasks_in_creation_order() -> None: + loop = SimLoop(seed=3) + tasks: list[asyncio.Task[None]] = [] + + async def main() -> None: + async def noop() -> None: + pass + + tasks.extend(asyncio.create_task(noop()) for _ in range(3)) + for task in tasks: + await task + + try: + loop.run_until_complete(main()) + finally: + loop.close() + # 0 went to the task run_until_complete wrapped the coroutine in. + assert [loop._task_owner(task) for task in tasks] == [1, 2, 3] + + +def test_the_owner_map_does_not_keep_a_finished_task_alive() -> None: + loop = SimLoop(seed=3) + watched: list[weakref.ref[asyncio.Task[None]]] = [] + + async def main() -> None: + async def noop() -> None: + pass + + for _ in range(4): + task: asyncio.Task[None] = asyncio.create_task(noop()) + watched.append(weakref.ref(task)) + await task + await asyncio.sleep(0) # let the last task's done callbacks run + + try: + loop.run_until_complete(main()) + finally: + loop.close() + gc.collect() + # A campaign runs millions of tasks through one loop at a time, so the + # map that names them must never be the thing keeping one alive. + assert [reference() for reference in watched] == [None] * 4 + assert len(loop._task_owners) == 1 # the awaited task, still referenced here + + # ---------------------------------------------------------------------- # Loop integration # ---------------------------------------------------------------------- From 4359eb64516933eb8c88950f62b018ac4fef6875 Mon Sep 17 00:00:00 2001 From: Dhruv Kumar Singh Date: Sat, 1 Aug 2026 18:11:17 +0530 Subject: [PATCH 3/8] Add priority-based schedule exploration --- src/simloop/_loop.py | 4 +- src/simloop/_policy.py | 90 +++++++++++++++++++++- tests/test_policy.py | 168 ++++++++++++++++++++++++++++++++++++++++- 3 files changed, 256 insertions(+), 6 deletions(-) diff --git a/src/simloop/_loop.py b/src/simloop/_loop.py index d219304..118bb03 100644 --- a/src/simloop/_loop.py +++ b/src/simloop/_loop.py @@ -116,7 +116,9 @@ class _ReadyViews(Sequence[ReadyView]): Views are recomputed rather than cached, which is safe because computing one has no side effect — the owner numbers are handed out in ``create_task``, long before anything here looks at them — so indexing an - entry twice simply returns equal tuples. + entry twice simply returns equal tuples, the one caveat being that + naming an owner reads ``__self__`` off the callback, which only a + callable with a side-effecting ``__getattr__`` could notice. """ __slots__ = ("_entries", "_owners") diff --git a/src/simloop/_policy.py b/src/simloop/_policy.py index f4c34d5..4f880ab 100644 --- a/src/simloop/_policy.py +++ b/src/simloop/_policy.py @@ -27,9 +27,12 @@ ``owner`` names who the callback belongs to. Every step of a task carries that task's creation index on this loop, a non-negative number that is the same at every step the task takes, so a policy can tell "this task again" -from "a different task". A callback no task owns — a bare ``call_soon``, a -timer, a protocol callback — gets a negative number unique to it, which is -never equal to another entry's and never mistakable for a task. +from "a different task". Anything else — a timer, a protocol callback, a +plain function — gets a negative number unique to it, never equal to +another entry's and never mistakable for a task. Ownership is read off the +callback, so a callback that is a bound method of a live task is that +task's work whoever queued it; only callbacks with no task behind them +land on the negative side. ``label`` is the same qualified callback name the trace records. @@ -113,3 +116,84 @@ def _diverge(self, step: int) -> None: # replays a schedule the recording never described anyway. if self.diverged_at is None: self.diverged_at = step + + +class PCTPolicy: + """Priority-based exploration with provable bug-finding odds. + + Burckhardt et al.'s PCT (ASPLOS 2010): give every chain of work a + distinct random priority, always run the highest-priority ready entry, + and lower the leader's priority at ``depth - 1`` random steps. Any bug + needing ``depth`` ordered scheduling constraints is hit with probability + at least 1/(n * horizon**(depth-1)) per run — a guarantee uniform random + draws cannot make. Owners unseen so far draw a fresh priority on first + sight, the standard adaptation for tasks that are created as the run + goes. A callback no task owns carries an id unique to that callback, so + each such entry is a chain of its own that draws once and runs once; + that is what PCT does with a one-shot event, not an accident of the + numbering. It does mean a change point that lands on a one-shot winner + spends a demotion level on a chain with no future — demoting something + that was never going to run again changes nothing — so read the depth-d + bound as a statement about schedules where owned chains do the deciding, + and expect it to be optimistic where one-shot callbacks dominate the + ready queue. + + ``horizon`` is a guess at how many steps the run will take, and the odds + are only as good as the guess. Change points are sampled without + replacement from ``range(horizon)``: a run that ends early passes only + some of them and gets fewer than ``depth - 1`` demotions, and a run that + overruns spends all of them in its first ``horizon`` steps, after which + no change point can fall — the tail runs at fixed priorities and the + bound above says nothing about bugs that live there. Both schedules are + legal; neither is the one the guarantee describes. + """ + + def __init__(self, seed: int, depth: int = 3, horizon: int = 10_000) -> None: + if depth < 1: + raise ValueError(f"depth must be >= 1, got {depth}") + if horizon < 1: + raise ValueError(f"horizon must be >= 1, got {horizon}") + if depth - 1 > horizon: + raise ValueError( + f"horizon must leave room for depth - 1 change points: " + f"depth {depth} needs horizon >= {depth - 1}, got {horizon}" + ) + # Seeded off a string rather than the bare number so a PCT run and a + # seeded run of the same seed do not walk the same stream of draws. + self._rng = random.Random(f"{seed}:pct") + self._priorities: dict[int, float] = {} + self._floor = 0.0 # change-point demotions go ever lower + # Sampled without replacement: two change points on the same step + # would collapse into one demotion and quietly cost a level of the + # depth the caller asked for. + self._change_points = frozenset(self._rng.sample(range(horizon), depth - 1)) + self._step_count = 0 + self.diverged_at: int | None = None # nothing to replay, nothing to depart from + + def _priority(self, owner: int) -> float: + # Priorities live in [1, 2) and demotions strictly below 1, so a + # demoted owner loses to every owner still holding its first draw. + # The map grows with owners *seen* and is never pruned. Tasks + # contribute one entry each however many steps they take, but every + # unowned callback is an owner of its own, so the real bound is one + # entry per distinct entry the policy was shown — the length of the + # run, not the number of tasks in it. It is still bounded by a single + # run and freed with the policy, which is why nothing prunes it. + prio = self._priorities.get(owner) + if prio is None: + prio = self._priorities[owner] = self._rng.random() + 1.0 + return prio + + def choose(self, ready: Sequence[ReadyView]) -> int: + step = self._step_count + self._step_count += 1 + # Every entry is read, so every owner in the queue is priced before + # the comparison — first sight of an owner draws here, in queue + # order, which is what makes the draws reproducible. Two owners can + # in principle draw equal floats; ``max`` keeps the earliest index, + # so even then the choice is defined rather than arbitrary. + index = max(range(len(ready)), key=lambda i: self._priority(ready[i][0])) + if step in self._change_points: + self._floor -= 1.0 + self._priorities[ready[index][0]] = self._floor + return index diff --git a/tests/test_policy.py b/tests/test_policy.py index 7d0eaba..e2e97cd 100644 --- a/tests/test_policy.py +++ b/tests/test_policy.py @@ -7,7 +7,14 @@ import pytest from simloop import Host, SimLoop -from simloop._policy import MAX_CHOICE, ReadyView, ScriptedPolicy, SeededPolicy +from simloop._policy import ( + MAX_CHOICE, + PCTPolicy, + ReadyView, + SchedulingPolicy, + ScriptedPolicy, + SeededPolicy, +) def _ready(count: int) -> list[ReadyView]: @@ -97,6 +104,163 @@ def test_scripted_policy_rejects_impossible_choices() -> None: ScriptedPolicy([MAX_CHOICE + 1]) +# ---------------------------------------------------------------------- +# Priority-based exploration +# ---------------------------------------------------------------------- + + +def _owned(*owners: int) -> list[ReadyView]: + """A ready queue owned by ``owners``, in that order.""" + return [(owner, f"task{owner}.step") for owner in owners] + + +# Queue shapes with owners appearing, vanishing and coming back, so a run +# over them exercises more than one queue length and more than one position. +_SCRIPT = [ + _owned(0, 1, 2), + _owned(1, 2), + _owned(0, 2, 3, 4), + _owned(4, 0), + _owned(2, 3, 0, 1), + _owned(5), + _owned(5, 1, 0), + _owned(3, 4, 5, 0, 1, 2), +] + + +def _drive(policy: PCTPolicy) -> list[int]: + return [policy.choose(views) for views in _SCRIPT] + + +def test_pct_policy_repeats_itself_for_the_same_configuration() -> None: + # Determinism is the whole premise: a campaign that reports a seed must + # be able to hand that seed back and get the identical schedule. + first = _drive(PCTPolicy(seed=41, depth=3, horizon=64)) + second = _drive(PCTPolicy(seed=41, depth=3, horizon=64)) + assert first == second + assert len(set(first)) > 1 # not a constant sequence dressed up as agreement + + +def test_pct_policy_explores_differently_under_different_seeds() -> None: + # Priorities come from the seed, so seeds are what make a campaign cover + # more than one schedule. One differing run is enough to prove it. + baseline = _drive(PCTPolicy(seed=0, depth=3, horizon=64)) + assert any( + _drive(PCTPolicy(seed=seed, depth=3, horizon=64)) != baseline + for seed in range(1, 12) + ) + + +def test_pct_policy_keeps_running_the_same_owner_when_nothing_demotes_it() -> None: + # The property that separates PCT from a uniform draw: priorities are + # drawn once and held, so with no change points one owner runs and runs. + # depth=1 means zero demotions, which makes "held" checkable exactly. + policy = PCTPolicy(seed=7, depth=1, horizon=16) + queue = _owned(11, 22) + winners = [queue[policy.choose(queue)][0] for _ in range(12)] + assert winners == [winners[0]] * 12 + assert winners[0] in (11, 22) + + +def test_pct_policy_demotes_the_leader_at_a_change_point() -> None: + # depth=2, horizon=4 puts the single change point inside the first four + # steps, so a twelve-step run must contain the handover. + policy = PCTPolicy(seed=3, depth=2, horizon=4) + queue = _owned(11, 22) + winners = [queue[policy.choose(queue)][0] for _ in range(12)] + assert len(set(winners)) == 2, winners + handover = next(step for step, w in enumerate(winners) if w != winners[0]) + # Demotion is permanent: the old leader sits below every fresh priority + # and below every later demotion, so it never leads again. + assert winners[handover:] == [winners[handover]] * (12 - handover) + + +def test_pct_policy_lowers_each_demotion_below_the_last() -> None: + # depth=3, horizon=3 puts two distinct change points inside the first + # three steps, so a six-step run actually reaches both and builds a + # ladder rather than a single step down. + policy = PCTPolicy(seed=2, depth=3, horizon=3) + queue = _owned(11, 22, 33) + winners = [queue[policy.choose(queue)][0] for _ in range(6)] + # A demoted owner cannot lead again, so each change point hands the + # queue to someone new: three owners, three reigns, in demotion order. + leaders = list(dict.fromkeys(winners)) + assert len(leaders) == 3, winners + first_demoted, second_demoted, _ = leaders + # The owner pushed off first must still outrank the one pushed off + # second — that is what the descending floor buys. Asked in the order + # that makes the answer mean something: a policy that dropped both to + # one shared floor would tie, and a tie takes index 0. + probe = _owned(second_demoted, first_demoted) + assert probe[policy.choose(probe)][0] == first_demoted + + +def test_pct_policy_gives_a_newcomer_a_priority_that_competes() -> None: + # Tasks are created mid-run, so an owner seen for the first time has to + # be dealt in — with a priority drawn from the same range as everyone + # else's, which means it sometimes wins immediately and sometimes loses. + established = _owned(11, 22) + joined = _owned(11, 22, 33) + newcomer_wins = 0 + for seed in range(24): + policy = PCTPolicy(seed=seed, depth=1, horizon=16) + for _ in range(5): + policy.choose(established) + leader = established[policy.choose(established)][0] + winner = joined[policy.choose(joined)][0] + # Nothing about the newcomer may reorder the owners already ranked. + assert winner in (leader, 33) + newcomer_wins += winner == 33 + assert 0 < newcomer_wins < 24 + + +def test_pct_policy_draws_a_fresh_priority_for_every_unowned_callback() -> None: + # Unowned entries carry an id unique to the callback — the loop hands + # out a fresh one per queued callback, never a repeat — so under PCT + # each is its own one-step chain: a fresh draw, a fresh chance to run + # first. A queue of them therefore reshuffles instead of settling. + policy = PCTPolicy(seed=5, depth=1, horizon=16) + seq = iter(range(1000)) + choices = [ + policy.choose([(-1 - next(seq), "callback") for _ in range(4)]) + for _ in range(16) + ] + assert len(set(choices)) > 1 + + +def test_pct_policy_is_a_scheduling_policy() -> None: + # The loop only ever holds a policy through the protocol, so the binding + # below is the assertion: it is mypy that has to accept it. + policy: SchedulingPolicy = PCTPolicy(seed=0) + assert policy.choose(_owned(4, 9)) in (0, 1) + assert policy.diverged_at is None + + +def test_pct_policy_never_diverges() -> None: + # Divergence describes a replay that stopped matching its recording; + # a policy that generates its own schedule has nothing to depart from. + policy = PCTPolicy(seed=1, depth=3, horizon=64) + _drive(policy) + assert policy.diverged_at is None + + +def test_pct_policy_rejects_a_degenerate_configuration() -> None: + with pytest.raises(ValueError, match="depth"): + PCTPolicy(seed=1, depth=0) + with pytest.raises(ValueError, match="depth"): + PCTPolicy(seed=1, depth=-2) + with pytest.raises(ValueError, match="horizon"): + PCTPolicy(seed=1, horizon=0) + with pytest.raises(ValueError, match="horizon"): + PCTPolicy(seed=1, horizon=-5) + # Change points are distinct, so a horizon with fewer steps than the + # depth needs cannot deliver the depth that was asked for. Saying so + # beats silently scheduling at a shallower depth than the caller thinks. + with pytest.raises(ValueError, match="change points"): + PCTPolicy(seed=1, depth=5, horizon=3) + PCTPolicy(seed=1, depth=4, horizon=3) # exactly enough room is enough + + # ---------------------------------------------------------------------- # What the loop shows the policy # ---------------------------------------------------------------------- @@ -284,7 +448,7 @@ async def noop() -> None: # A campaign runs millions of tasks through one loop at a time, so the # map that names them must never be the thing keeping one alive. assert [reference() for reference in watched] == [None] * 4 - assert len(loop._task_owners) == 1 # the awaited task, still referenced here + assert len(loop._task_owners) == 1 # the wrapper task run_until_complete holds # ---------------------------------------------------------------------- From d29e2f597c5895a77e27d489def961ca567551e2 Mon Sep 17 00:00:00 2001 From: Dhruv Kumar Singh Date: Sat, 1 Aug 2026 19:22:46 +0530 Subject: [PATCH 4/8] Explore schedules by priority from the seed runner --- src/simloop/_explore.py | 201 +++++++++++++++++++++++-- src/simloop/_pytest_plugin.py | 29 ++++ tests/test_explore.py | 276 +++++++++++++++++++++++++++++++++- tests/test_pytest_plugin.py | 58 +++++++ 4 files changed, 554 insertions(+), 10 deletions(-) diff --git a/src/simloop/_explore.py b/src/simloop/_explore.py index 4f28424..3435bf3 100644 --- a/src/simloop/_explore.py +++ b/src/simloop/_explore.py @@ -10,6 +10,7 @@ import functools import inspect +import math import os from collections.abc import Callable, Coroutine, Iterable from dataclasses import dataclass, replace @@ -21,10 +22,28 @@ check_reproduced, find_lowest_failure, ) +from simloop._policy import PCTPolicy, SchedulingPolicy from simloop._run import Workload, finish, run_once from simloop._shrink import DEFAULT_BUDGET, ShrinkResult, shrink_schedule from simloop._trace import EventKind, TraceEvent +# How the scheduler may be driven while exploring: seeded uniform draws, or +# PCT's priorities. +POLICIES = ("random", "pct") +# Ordering constraints PCT aims to hit; the paper's own default. +DEFAULT_PCT_DEPTH = 3 +# The seed whose run measures the workload for PCT. Fixed rather than "the +# first seed asked for", so that the horizon depends on the workload alone: +# replaying one found seed on its own has to size the horizon exactly as the +# search that found it did, or the replay runs a different schedule. +_CALIBRATION_SEED = 0 +# Room left above the measured step count, so that a run a little longer than +# the measured one still has change points falling inside it. +_HORIZON_SLACK = 1.5 +# Below this, a horizon is too small to place change points with any spread, +# and the measurement is too short to be worth trusting anyway. +_MIN_HORIZON = 100 + # Events of context shown either side of the point two runs part ways. _CONTEXT = 5 # Below this much agreement the split point sits in the runs' opening @@ -70,6 +89,38 @@ class Divergence: failing_context: tuple[TraceEvent, ...] +@dataclass(frozen=True, slots=True) +class PolicyRun: + """Which scheduler drove one seed, when it was not the loop's own. + + Only ``"pct"`` reaches here today: the default policy is the loop's own + seeded draw, and a run under it carries no record at all, so nothing about + a default exploration changes. + + ``horizon`` is the step count PCT sized its change points against, and is + ``None`` for the seed the measurement is taken from — that seed runs the + seeded schedule, because a measurement of a PCT run would be a measurement + of a schedule chosen by the number it is supposed to produce. + """ + + name: str + depth: int + horizon: int | None = None + + def build(self, seed: int) -> SchedulingPolicy | None: + """The policy for ``seed``, or ``None`` to leave the loop's own in place.""" + if self.horizon is None: + return None + return PCTPolicy(seed, self.depth, self.horizon) + + def replay_options(self) -> str: + """The --simloop-* options a replay of this seed needs to match it.""" + options = f" --simloop-policy={self.name}" + if self.depth != DEFAULT_PCT_DEPTH: + options += f" --simloop-pct-depth={self.depth}" + return options + + @dataclass(frozen=True, slots=True) class SeedReport: """Everything known about the first failing seed.""" @@ -82,6 +133,7 @@ class SeedReport: pending: tuple[PendingTask, ...] divergence: Divergence | None = None shrunk: ShrinkResult | None = None + policy: PolicyRun | None = None def render(self, test_id: str | None = None) -> str: lines = [ @@ -89,9 +141,12 @@ def render(self, test_id: str | None = None) -> str: f"({self.seeds_passed} seeds passed first)" ] if test_id is not None: + options = self.policy.replay_options() if self.policy else "" lines.append( - f"replay: pytest '{test_id}' --simloop-replay={self.seed}" + f"replay: pytest '{test_id}' --simloop-replay={self.seed}{options}" ) + if self.policy is not None: + lines.append(_render_policy(self.policy)) if self.trace_events: lines.append("") lines.append(f"last {len(self.trace_events)} trace events:") @@ -113,12 +168,26 @@ def render(self, test_id: str | None = None) -> str: def _format_event(event: TraceEvent) -> str: + # The host goes in a column of its own ahead of the label, the way the + # pending-task block names machines. Events that belong to the simulation + # rather than to a machine — a clock advance, a packet on the wire — carry + # no host and keep the two-space gap they always had. + host = f"{event.host} " if event.host else "" return ( f" [t={event.when:.4f}] {event.kind:<8} " - f"seq={event.seq} {event.label}" + f"seq={event.seq} {host}{event.label}" ) +def _render_policy(policy: PolicyRun) -> str: + if policy.horizon is None: + return ( + f"policy: {policy.name} (depth {policy.depth}); this seed ran the " + "default schedule, which is what sized the horizon" + ) + return f"policy: {policy.name} (depth {policy.depth}, horizon {policy.horizon:,})" + + def _describe(event: TraceEvent | None, subject: str) -> str: if event is None: return f"{subject} ended" @@ -246,6 +315,8 @@ def explore( shrink: bool = False, shrink_budget: int = DEFAULT_BUDGET, jobs: int = 1, + policy: str = "random", + pct_depth: int = DEFAULT_PCT_DEPTH, ) -> SeedReport | None: """Run ``fn`` once per seed on a fresh SimLoop; stop at the first failure. @@ -269,9 +340,35 @@ def explore( would have stopped at, rebuilt by re-running that seed here — but the workload has to survive pickling to reach a worker at all, so it must be a module-level function or a partial of one. + + ``policy="pct"`` schedules by priority instead of drawing uniformly, + which buys a per-run probability bound on finding a bug that needs + ``pct_depth`` ordering constraints. It costs one extra run of the + workload: seed 0 runs the seeded schedule, and its step count is what the + priority policy's horizon is sized from. That seed is fixed rather than + "whichever seed came first", so the horizon describes the workload alone + — which is what lets one found seed, replayed on its own, run the very + schedule that found it. """ if jobs < 1: raise ValueError("jobs must be at least 1") + if policy not in POLICIES: + raise ValueError( + f"unknown scheduling policy {policy!r}: expected one of " + f"{', '.join(repr(name) for name in POLICIES)}" + ) + if policy == "pct": + if pct_depth < 1: + raise ValueError(f"pct_depth must be at least 1, got {pct_depth}") + if jobs > 1: + # Refused rather than quietly ignored: seed 0 sizes the horizon in + # this process, and the parallel search hands workers a seed and + # nothing else, so workers would explore uniformly while the report + # claimed PCT. + raise ValueError( + "policy='pct' explores sequentially, because the horizon it " + "sizes here does not reach worker processes: run it with jobs=1" + ) if jobs > 1: ordered = list(seeds) if len(ordered) > 1: @@ -286,8 +383,14 @@ def explore( # One seed is one run: worth no process pool at all. seeds = ordered passed = 0 + horizon: int | None = None last_pass: tuple[TraceEvent, ...] = () for seed in seeds: + if policy == "pct" and horizon is None and seed != _CALIBRATION_SEED: + # Measured on first need rather than up front, so that a caller + # who asked for no seeds — or only for the measuring seed, which + # measures itself — runs the workload exactly as often as asked. + horizon = _pct_horizon(_measure_steps(fn), pct_depth) report, events = _run_seed( fn, seed, @@ -296,6 +399,7 @@ def explore( trace_tail=trace_tail, shrink=shrink, shrink_budget=shrink_budget, + policy=_policy_for(policy, pct_depth, horizon, seed), ) if report is not None: return report @@ -304,6 +408,51 @@ def explore( return None +def _policy_for( + policy: str, depth: int, horizon: int | None, seed: int +) -> PolicyRun | None: + """How ``seed`` should be scheduled, or ``None`` for the loop's own draw.""" + if policy == "random": + return None + # The measuring seed keeps the seeded schedule, and says so by carrying no + # horizon: it is the run the horizon was read off, and it is explored like + # every other seed rather than being spent on measurement alone. + return PolicyRun( + policy, depth, None if seed == _CALIBRATION_SEED else horizon + ) + + +def _measure_steps(fn: Workload) -> int: + """How many scheduling steps the workload takes under the seeded schedule. + + One run of seed 0, whose outcome is deliberately dropped: this is a + measurement, not an exploration, and seed 0 is explored on its own account + when it is one of the seeds asked for. The choice log is one entry per + step, which is the unit a horizon is counted in; the trace is several + events per step and would size the horizon several times too large. + """ + loop = SimLoop(_CALIBRATION_SEED) + try: + run_once(loop, fn) + return len(loop._choices) + finally: + finish(loop) + + +def _pct_horizon(steps: int, depth: int) -> int: + """Size a PCT horizon from a measured step count. + + Slack above the measurement, then a floor, because a horizon shorter than + the run leaves its tail at fixed priorities and a horizon of a handful of + steps cannot spread change points at all. The last clamp is the one that + is not about tuning: PCT needs ``depth - 1`` distinct change points and + refuses to be built without room for them, so a deep search of a short + workload widens the horizon rather than failing. + """ + horizon = max(math.ceil(steps * _HORIZON_SLACK), _MIN_HORIZON) + return max(horizon, depth - 1) + + def _run_seed( fn: Workload, seed: int, @@ -313,6 +462,7 @@ def _run_seed( trace_tail: int, shrink: bool, shrink_budget: int, + policy: PolicyRun | None = None, ) -> tuple[SeedReport | None, tuple[TraceEvent, ...]]: """Run one seed; report it if it failed, and hand back its trace either way. @@ -320,6 +470,14 @@ def _run_seed( failure gets diffed against. """ loop = SimLoop(seed) + if policy is not None: + scheduler = policy.build(seed) + if scheduler is not None: + # Built by the seed, then scheduled by something else: the clock, + # the network faults and the user-facing entropy stay exactly what + # the seed put there, and only the order of the ready queue moves. + # This is the seam SimLoop._from_choices uses for replay. + loop._policy = scheduler try: failure = run_once(loop, fn) events = loop.trace @@ -333,6 +491,7 @@ def _run_seed( trace_hash=loop.trace_hash(), pending=_pending_tasks(loop), divergence=_diff_traces(last_pass, events), + policy=policy, ) choices = loop._choices finally: @@ -435,10 +594,15 @@ def _short_path(filename: str) -> str: class _Overrides: """Session state the pytest plugin writes; consulted by sim_test wrappers. - ``seeds``, ``replay``, ``shrink``, ``shrink_budget`` and ``jobs`` mirror - the --simloop-* options; ``node_id`` is the test currently running, so - reports can print an exact replay command. The counters feed the - plugin's terminal summary. + ``seeds``, ``replay``, ``shrink``, ``shrink_budget``, ``jobs``, + ``policy`` and ``pct_depth`` mirror the --simloop-* options; ``node_id`` + is the test currently running, so reports can print an exact replay + command. The counters feed the plugin's terminal summary. + + ``policy`` and ``pct_depth`` are ``None`` when the option was not given, + the way ``seeds`` is: an option nobody passed must leave a decorator's own + argument alone, while ``--simloop-policy=random`` is a decision and + overrides it. """ seeds: int | None = None @@ -446,6 +610,8 @@ class _Overrides: shrink: bool = False shrink_budget: int = DEFAULT_BUDGET jobs: int = 1 + policy: str | None = None + pct_depth: int | None = None node_id: str | None = None sim_tests: int = 0 seeds_explored: int = 0 @@ -488,7 +654,11 @@ def sim_test(fn: _TestFn, /) -> Callable[..., None]: ... @overload def sim_test( - *, seeds: int = ..., trace_tail: int = ... + *, + seeds: int = ..., + trace_tail: int = ..., + policy: str = ..., + pct_depth: int = ..., ) -> Callable[[_TestFn], Callable[..., None]]: ... @@ -498,6 +668,8 @@ def sim_test( *, seeds: int = 10, trace_tail: int = 20, + policy: str = "random", + pct_depth: int = DEFAULT_PCT_DEPTH, ) -> Callable[..., None] | Callable[[_TestFn], Callable[..., None]]: """Turn an ``async def`` test into a seed-exploring synchronous test. @@ -505,11 +677,18 @@ def sim_test( :func:`explore` and re-raises the first failure with the rendered report attached as an exception note. Under pytest, the --simloop-seeds and --simloop-replay options override the decorator's arguments, - --simloop-shrink adds a minimized schedule to the report, and - --simloop-jobs spreads the seeds over worker processes. + --simloop-shrink adds a minimized schedule to the report, + --simloop-jobs spreads the seeds over worker processes, and + --simloop-policy / --simloop-pct-depth override ``policy`` and + ``pct_depth``. """ if seeds < 1: raise ValueError("seeds must be at least 1") + if policy not in POLICIES: + raise ValueError( + f"unknown scheduling policy {policy!r}: expected one of " + f"{', '.join(repr(name) for name in POLICIES)}" + ) def decorate(test_fn: _TestFn) -> Callable[..., None]: @functools.wraps(test_fn) @@ -535,6 +714,10 @@ def wrapper(*args: Any, **kwargs: Any) -> None: shrink=overrides.shrink, shrink_budget=overrides.shrink_budget, jobs=jobs, + policy=policy if overrides.policy is None else overrides.policy, + pct_depth=( + pct_depth if overrides.pct_depth is None else overrides.pct_depth + ), ) overrides.sim_tests += 1 if report is None: diff --git a/src/simloop/_pytest_plugin.py b/src/simloop/_pytest_plugin.py index 0860115..94c7b39 100644 --- a/src/simloop/_pytest_plugin.py +++ b/src/simloop/_pytest_plugin.py @@ -10,6 +10,7 @@ import pytest from simloop import _explore +from simloop._explore import POLICIES from simloop._shrink import DEFAULT_BUDGET @@ -49,6 +50,19 @@ def pytest_addoption(parser: pytest.Parser) -> None: metavar="N", help="explore each @sim_test's seeds across N worker processes", ) + group.addoption( + "--simloop-policy", + choices=POLICIES, + default=None, + help="how the scheduler picks: seeded uniform draws, or PCT priorities", + ) + group.addoption( + "--simloop-pct-depth", + type=int, + default=None, + metavar="N", + help="ordering constraints PCT aims to hit (--simloop-policy=pct only)", + ) def pytest_configure(config: pytest.Config) -> None: @@ -65,6 +79,19 @@ def pytest_configure(config: pytest.Config) -> None: if jobs < 1: raise pytest.UsageError("--simloop-jobs must be at least 1") _explore.overrides.jobs = jobs + policy = config.getoption("--simloop-policy") + depth = config.getoption("--simloop-pct-depth") + if depth is not None and depth < 1: + raise pytest.UsageError("--simloop-pct-depth must be at least 1") + if policy == "pct" and jobs > 1: + # The horizon PCT works to is measured in this process and does not + # reach a worker, so the combination is refused here rather than at + # the first sim test that would have explored under it. + raise pytest.UsageError( + "--simloop-policy=pct explores sequentially: drop --simloop-jobs" + ) + _explore.overrides.policy = policy + _explore.overrides.pct_depth = depth _explore.overrides.sim_tests = 0 _explore.overrides.seeds_explored = 0 @@ -75,6 +102,8 @@ def pytest_unconfigure(config: pytest.Config) -> None: _explore.overrides.shrink = False _explore.overrides.shrink_budget = DEFAULT_BUDGET _explore.overrides.jobs = 1 + _explore.overrides.policy = None + _explore.overrides.pct_depth = None _explore.overrides.node_id = None diff --git a/tests/test_explore.py b/tests/test_explore.py index f451075..a965c69 100644 --- a/tests/test_explore.py +++ b/tests/test_explore.py @@ -8,7 +8,16 @@ import simloop from simloop import SeedReport, TraceEvent, sim_test -from simloop._explore import Divergence, _diff_traces, explore +from simloop._explore import ( + Divergence, + PolicyRun, + _diff_traces, + _format_event, + _pct_horizon, + explore, +) +from simloop._policy import PCTPolicy, SchedulingPolicy +from simloop._run import finish, run_once from simloop._trace import EventKind @@ -438,6 +447,271 @@ async def my_test() -> None: pass +# ---------------------------------------------------------------------- +# Priority-based exploration +# ---------------------------------------------------------------------- +# +# Measured on the race below, five disjoint blocks of 200 seeds (0-199, +# 200-399, ... 800-999): mean seeds to the first failing seed was 2.0 under +# policy="random" (blocks 1, 1, 1, 2, 5) and 92.75 under policy="pct" +# (blocks 9, 26, 146, 190 — block one is excluded because its first failure +# was seed 0, which always runs the seeded schedule to size the horizon and +# so says nothing about PCT); per-seed failure rate 474/1000 against +# 21/1000. Uniform draws win here and it is not close. The reason is not that PCT is doing +# something wrong: this race is two ordering constraints deep in a twelve-step +# run, which is the shape a uniform draw is already ideal for, while PCT runs +# one chain to completion — the schedule that passes — except where a change +# point falls, and its change points are spread over a horizon floored at 100 +# steps. Dropping that floor to the measured 18 steps narrows the gap to +# 103/1000 and does not change the verdict. What PCT buys on this workload is +# not a better hit rate but a floor under it: a stated per-run probability of +# hitting a depth-3 bug, which uniform draws cannot promise at any depth. + + +async def _bump(cell: list[int]) -> None: + """Read the counter, yield, then write back one more than it read.""" + seen = cell[0] + await asyncio.sleep(0) + cell[0] = seen + 1 + + +async def _lost_update() -> None: + """The canonical depth-2 race: two read-yield-write bumps of one counter. + + The assertion runs in a third task — the one ``run_until_complete`` wraps + this coroutine in — after both bumps have finished. The counter reaches 2 + only when one bump's write lands before the other's read. + """ + loop = asyncio.get_running_loop() + cell = [0] + bumps = [loop.create_task(_bump(cell)) for _ in range(2)] + await asyncio.gather(*bumps) + assert cell[0] == 2, f"lost update: counter is {cell[0]}" + + +def _run_race( + seed: int, policy: SchedulingPolicy | None = None +) -> tuple[Exception | None, str]: + """Run the race once at ``seed``, optionally under ``policy``.""" + loop = simloop.SimLoop(seed) + if policy is not None: + loop._policy = policy + try: + failure = run_once(loop, _lost_update) + return failure, loop.trace_hash() + finally: + finish(loop) + + +def test_pct_finds_the_race_and_names_the_policy() -> None: + report = explore(lambda: _lost_update(), range(1, 100), policy="pct") + assert report is not None + assert isinstance(report.exception, AssertionError) + assert "lost update" in str(report.exception) + assert report.seeds_passed == report.seed - 1 # every seed below it passed + assert report.policy == PolicyRun("pct", depth=3, horizon=100) + assert "policy: pct (depth 3, horizon 100)" in report.render() + + +def test_pct_schedules_a_seed_differently_from_the_seeded_draw() -> None: + report = explore(lambda: _lost_update(), range(1, 100), policy="pct") + assert report is not None and report.policy is not None + horizon = report.policy.horizon + assert horizon is not None + failure, pct_hash = _run_race(report.seed, PCTPolicy(report.seed, 3, horizon)) + # The explorer ran exactly this policy: same failure, same trace. + assert failure is not None + assert pct_hash == report.trace_hash + assert _run_race(report.seed)[1] != pct_hash + + +def test_a_pct_failure_replays_at_its_own_seed() -> None: + found = explore(lambda: _lost_update(), range(1, 100), policy="pct") + assert found is not None + # What --simloop-replay does: the one seed, the same options. The horizon + # is measured off seed 0 whatever seeds were asked for, so the replay runs + # the schedule that found the failure rather than a differently sized one. + again = explore(lambda: _lost_update(), [found.seed], policy="pct") + assert again is not None + assert again.seed == found.seed + assert again.seeds_passed == 0 + assert again.trace_hash == found.trace_hash + assert str(again.exception) == str(found.exception) + assert again.policy == found.policy + + +def test_a_pct_run_records_choices_that_replay_under_the_scripted_policy() -> None: + found = explore(lambda: _lost_update(), range(1, 100), policy="pct") + assert found is not None and found.policy is not None + horizon = found.policy.horizon + assert horizon is not None + loop = simloop.SimLoop(found.seed) + loop._policy = PCTPolicy(found.seed, found.policy.depth, horizon) + try: + failure = run_once(loop, _lost_update) + choices = loop._choices + recorded_hash = loop.trace_hash() + finally: + finish(loop) + assert failure is not None + assert len(choices) > 0 # PCT runs record their choices like any other run + replay = simloop.SimLoop._from_choices(choices, found.seed) + try: + repeated = run_once(replay, _lost_update) + replay_hash = replay.trace_hash() + finally: + finish(replay) + assert repeated is not None + assert type(repeated) is type(failure) + assert str(repeated) == str(failure) + assert replay_hash == recorded_hash + assert replay._diverged_at is None + + +def test_seed_zero_sizes_the_horizon_under_the_default_schedule() -> None: + # Seed 0 is what the horizon is measured from, so it runs the seeded + # schedule under every policy — and it explores like any other seed. + report = explore(lambda: _lost_update(), range(4), policy="pct") + assert report is not None + assert report.seed == 0 + assert report.policy == PolicyRun("pct", depth=3, horizon=None) + assert report.trace_hash == _run_race(0)[1] + assert "policy: pct (depth 3); this seed ran the default schedule" in ( + report.render() + ) + + +def test_random_policy_is_the_default_and_renders_no_policy_line() -> None: + default = explore(lambda: _interleaves(3), range(10)) + named = explore(lambda: _interleaves(3), range(10), policy="random") + assert default is not None and named is not None + assert default.policy is None and named.policy is None + assert default.trace_hash == named.trace_hash + text = default.render("tests/test_demo.py::test_x") + assert named.render("tests/test_demo.py::test_x") == text + assert "policy:" not in text + assert text.splitlines()[1] == ( + "replay: pytest 'tests/test_demo.py::test_x' --simloop-replay=3" + ) + + +def test_pct_report_replays_with_the_policy_options() -> None: + report = explore(lambda: _lost_update(), range(1, 100), policy="pct") + assert report is not None + line = report.render("tests/test_demo.py::test_x").splitlines()[1] + assert line == ( + f"replay: pytest 'tests/test_demo.py::test_x' " + f"--simloop-replay={report.seed} --simloop-policy=pct" + ) + deep = explore(lambda: _lost_update(), range(1, 100), policy="pct", pct_depth=4) + assert deep is not None + assert "--simloop-pct-depth=4" in deep.render("tests/test_demo.py::test_x") + + +def test_horizon_is_measured_floored_and_left_room_for_the_depth() -> None: + assert _pct_horizon(1000, 3) == 1500 # step count x 1.5, rounded up + assert _pct_horizon(1001, 3) == 1502 + assert _pct_horizon(12, 3) == 100 # short runs take the floor + # A depth deeper than the measured horizon would be a construction error + # in PCTPolicy, so the horizon makes room for its change points instead. + assert _pct_horizon(12, 200) == 199 + assert _pct_horizon(12, 101) == 100 + + +def test_a_deep_pct_depth_still_runs() -> None: + # 200 change points do not fit in the horizon this twelve-step workload + # measures, and PCTPolicy refuses depth - 1 > horizon: the widened horizon + # is what keeps a deep search of a short workload from being a crash. + report = explore(lambda: _lost_update(), range(1, 6), policy="pct", pct_depth=200) + assert report is not None + assert report.policy == PolicyRun("pct", 200, 199) + + +def test_explore_rejects_an_unknown_policy() -> None: + with pytest.raises(ValueError, match="unknown scheduling policy 'greedy'"): + explore(lambda: _fails_at(0), range(1), policy="greedy") + + +def test_explore_rejects_a_pct_depth_below_one() -> None: + with pytest.raises(ValueError, match="pct_depth must be at least 1"): + explore(lambda: _fails_at(0), range(1), policy="pct", pct_depth=0) + + +def test_explore_refuses_pct_across_worker_processes() -> None: + with pytest.raises(ValueError, match="sequential"): + explore(lambda: _fails_at(0), range(4), policy="pct", jobs=2) + + +def test_sim_test_takes_a_policy() -> None: + @sim_test(seeds=100, policy="pct") + async def my_test() -> None: + await _lost_update() + + with pytest.raises(AssertionError) as excinfo: + my_test() + notes = getattr(excinfo.value, "__notes__", []) + assert any("policy: pct (depth 3" in note for note in notes) + + +def test_sim_test_respects_the_policy_overrides() -> None: + from simloop._explore import overrides + + @sim_test(seeds=100, policy="pct") + async def my_test() -> None: + await _lost_update() + + overrides.policy = "random" + try: + with pytest.raises(AssertionError) as excinfo: + my_test() + finally: + overrides.policy = None + notes = getattr(excinfo.value, "__notes__", []) + assert not any("policy:" in note for note in notes) + + overrides.policy = "pct" + overrides.pct_depth = 5 + try: + with pytest.raises(AssertionError) as deep: + my_test() + finally: + overrides.policy = None + overrides.pct_depth = None + deep_notes = getattr(deep.value, "__notes__", []) + assert any("policy: pct (depth 5" in note for note in deep_notes) + + +def test_sim_test_rejects_an_unknown_policy() -> None: + with pytest.raises(ValueError, match="unknown scheduling policy 'greedy'"): + + @sim_test(policy="greedy") + async def my_test() -> None: + pass + + +def test_format_event_names_the_host_when_there_is_one() -> None: + on_a_host = TraceEvent("run", 1.0, 7, "Worker.step", "node1") + assert _format_event(on_a_host) == " [t=1.0000] run seq=7 node1 Worker.step" + # An event that belongs to the simulation rather than to a machine keeps + # the format it always had. + assert _format_event(TraceEvent("advance", 1.0, -1, "")) == ( + " [t=1.0000] advance seq=-1 " + ) + + +def test_render_attributes_trace_events_to_their_hosts() -> None: + report = explore(lambda: _leaves_a_pending_task(), range(1), trace_tail=20) + assert report is not None + text = report.render() + # Trace lines only: the pending-task block names hosts of its own. + hosted = [ + line + for line in text.splitlines() + if line.startswith(" [t=") and " node1 " in line + ] + assert hosted, text + + def test_public_exports() -> None: assert simloop.sim_test is sim_test assert simloop.SeedReport is SeedReport diff --git a/tests/test_pytest_plugin.py b/tests/test_pytest_plugin.py index bdd6a89..67a9103 100644 --- a/tests/test_pytest_plugin.py +++ b/tests/test_pytest_plugin.py @@ -234,6 +234,64 @@ def test_jobs_flag_rejects_a_job_count_below_one(pytester: pytest.Pytester) -> N result.stderr.fnmatch_lines(["*--simloop-jobs must be at least 1*"]) +def test_policy_flag_explores_under_pct(pytester: pytest.Pytester) -> None: + pytester.makepyfile(test_demo=_FLAKY) + result = pytester.runpytest_subprocess("--simloop-policy=pct") + result.assert_outcomes(failed=1) + result.stdout.fnmatch_lines( + [ + "*simloop: failed at seed 3 (3 seeds passed first)*", + "*replay: pytest 'test_demo.py::test_flaky' --simloop-replay=3 " + "--simloop-policy=pct*", + "*policy: pct (depth 3, horizon *)*", + ] + ) + + +def test_pct_depth_flag_reaches_the_policy(pytester: pytest.Pytester) -> None: + pytester.makepyfile(test_demo=_FLAKY) + result = pytester.runpytest_subprocess( + "--simloop-policy=pct", "--simloop-pct-depth=5" + ) + result.assert_outcomes(failed=1) + result.stdout.fnmatch_lines( + [ + "*--simloop-replay=3 --simloop-policy=pct --simloop-pct-depth=5*", + "*policy: pct (depth 5, horizon *)*", + ] + ) + + +def test_no_policy_line_by_default(pytester: pytest.Pytester) -> None: + pytester.makepyfile(test_demo=_FLAKY) + result = pytester.runpytest_subprocess() + result.assert_outcomes(failed=1) + result.stdout.no_fnmatch_line("*policy:*") + + +def test_policy_flag_rejects_an_unknown_policy(pytester: pytest.Pytester) -> None: + pytester.makepyfile(test_demo=_FLAKY) + result = pytester.runpytest_subprocess("--simloop-policy=greedy") + assert result.ret != 0 + result.stderr.fnmatch_lines(["*--simloop-policy*invalid choice*"]) + + +def test_pct_depth_flag_rejects_a_depth_below_one(pytester: pytest.Pytester) -> None: + pytester.makepyfile(test_demo=_FLAKY) + result = pytester.runpytest_subprocess("--simloop-pct-depth=0") + assert result.ret != 0 + result.stderr.fnmatch_lines(["*--simloop-pct-depth must be at least 1*"]) + + +def test_pct_refuses_worker_processes(pytester: pytest.Pytester) -> None: + pytester.makepyfile(test_demo=_FLAKY) + result = pytester.runpytest_subprocess("--simloop-policy=pct", "--simloop-jobs=2") + assert result.ret != 0 + result.stderr.fnmatch_lines( + ["*--simloop-policy=pct explores sequentially*--simloop-jobs*"] + ) + + def test_replay_flag_runs_exactly_one_seed(pytester: pytest.Pytester) -> None: pytester.makepyfile(test_demo=_FLAKY) result = pytester.runpytest_subprocess("--simloop-replay=3") From 1b94d95e64c178ce1f171b8d96a8e6b83ec1b368 Mon Sep 17 00:00:00 2001 From: Dhruv Kumar Singh Date: Sat, 1 Aug 2026 19:58:30 +0530 Subject: [PATCH 5/8] Draw a run's trace as a host timeline --- src/simloop/__init__.py | 2 + src/simloop/_explore.py | 75 ++++- src/simloop/_pytest_plugin.py | 55 ++++ src/simloop/_timeline.py | 581 ++++++++++++++++++++++++++++++++++ tests/test_explore.py | 25 ++ tests/test_pytest_plugin.py | 142 +++++++++ tests/test_timeline.py | 360 +++++++++++++++++++++ 7 files changed, 1230 insertions(+), 10 deletions(-) create mode 100644 src/simloop/_timeline.py create mode 100644 tests/test_timeline.py diff --git a/src/simloop/__init__.py b/src/simloop/__init__.py index 7dfb91d..b24c5ce 100644 --- a/src/simloop/__init__.py +++ b/src/simloop/__init__.py @@ -4,6 +4,7 @@ from simloop._loop import SimLoop, SimulationDeadlockError, SimulationFenceError from simloop._net import Host, SimDisk, SimNetwork from simloop._sim import Sim, sim +from simloop._timeline import timeline_html from simloop._trace import TraceEvent __version__ = "0.1.0" @@ -22,4 +23,5 @@ "explore", "sim", "sim_test", + "timeline_html", ] diff --git a/src/simloop/_explore.py b/src/simloop/_explore.py index 3435bf3..aa62697 100644 --- a/src/simloop/_explore.py +++ b/src/simloop/_explore.py @@ -13,7 +13,7 @@ import math import os from collections.abc import Callable, Coroutine, Iterable -from dataclasses import dataclass, replace +from dataclasses import dataclass, field, replace from typing import Any, overload from simloop._loop import SimLoop @@ -25,6 +25,7 @@ from simloop._policy import PCTPolicy, SchedulingPolicy from simloop._run import Workload, finish, run_once from simloop._shrink import DEFAULT_BUDGET, ShrinkResult, shrink_schedule +from simloop._timeline import timeline_html from simloop._trace import EventKind, TraceEvent # How the scheduler may be driven while exploring: seeded uniform draws, or @@ -123,7 +124,16 @@ def replay_options(self) -> str: @dataclass(frozen=True, slots=True) class SeedReport: - """Everything known about the first failing seed.""" + """Everything known about the first failing seed. + + ``trace_events`` is the tail the rendered report prints; ``trace`` is + every event the failing run recorded, which is what a timeline draws. The + tail is a slice of the same run, so the two agree by construction. + + ``trace`` stays out of the repr: it can hold tens of thousands of events, + and this object is reachable from a failing test's traceback, where a + dataclass repr would print the whole run into the terminal. + """ seed: int seeds_passed: int @@ -134,8 +144,15 @@ class SeedReport: divergence: Divergence | None = None shrunk: ShrinkResult | None = None policy: PolicyRun | None = None - - def render(self, test_id: str | None = None) -> str: + trace: tuple[TraceEvent, ...] = field(default=(), repr=False) + + def render( + self, + test_id: str | None = None, + *, + timeline: str | None = None, + timeline_error: str | None = None, + ) -> str: lines = [ f"simloop: failed at seed {self.seed} " f"({self.seeds_passed} seeds passed first)" @@ -145,6 +162,13 @@ def render(self, test_id: str | None = None) -> str: lines.append( f"replay: pytest '{test_id}' --simloop-replay={self.seed}{options}" ) + if timeline is not None: + lines.append(f"timeline: {timeline}") + elif timeline_error is not None: + # The page was asked for and could not be written. That is worth + # saying, and worth saying here rather than by raising: the + # failure this report describes is the one the user is chasing. + lines.append(f"timeline not written: {timeline_error}") if self.policy is not None: lines.append(_render_policy(self.policy)) if self.trace_events: @@ -492,6 +516,7 @@ def _run_seed( pending=_pending_tasks(loop), divergence=_diff_traces(last_pass, events), policy=policy, + trace=events, ) choices = loop._choices finally: @@ -583,6 +608,20 @@ def _pending_tasks(loop: SimLoop) -> tuple[PendingTask, ...]: return tuple(found) +def write_timeline(report: SeedReport, directory: str) -> str: + """Draw the failing seed's trace into ``directory``; return the path. + + One page per failing seed, named after it, so that a session that failed + several sim tests at several seeds leaves one artifact per failure rather + than one that the last failure overwrote. + """ + os.makedirs(directory, exist_ok=True) + path = os.path.join(directory, f"simloop-timeline-seed{report.seed}.html") + with open(path, "w", encoding="utf-8") as page: + page.write(timeline_html(report.trace)) + return _short_path(os.path.abspath(path)) + + def _short_path(filename: str) -> str: cwd = os.getcwd() if filename.startswith(cwd + os.sep): @@ -595,9 +634,9 @@ class _Overrides: """Session state the pytest plugin writes; consulted by sim_test wrappers. ``seeds``, ``replay``, ``shrink``, ``shrink_budget``, ``jobs``, - ``policy`` and ``pct_depth`` mirror the --simloop-* options; ``node_id`` - is the test currently running, so reports can print an exact replay - command. The counters feed the plugin's terminal summary. + ``policy``, ``pct_depth`` and ``timeline_dir`` mirror the --simloop-* + options; ``node_id`` is the test currently running, so reports can print + an exact replay command. The counters feed the plugin's terminal summary. ``policy`` and ``pct_depth`` are ``None`` when the option was not given, the way ``seeds`` is: an option nobody passed must leave a decorator's own @@ -612,6 +651,7 @@ class _Overrides: jobs: int = 1 policy: str | None = None pct_depth: int | None = None + timeline_dir: str | None = None node_id: str | None = None sim_tests: int = 0 seeds_explored: int = 0 @@ -678,9 +718,10 @@ def sim_test( report attached as an exception note. Under pytest, the --simloop-seeds and --simloop-replay options override the decorator's arguments, --simloop-shrink adds a minimized schedule to the report, - --simloop-jobs spreads the seeds over worker processes, and + --simloop-jobs spreads the seeds over worker processes, --simloop-policy / --simloop-pct-depth override ``policy`` and - ``pct_depth``. + ``pct_depth``, and --simloop-timeline draws the failing seed's trace to + an HTML page named in the report. """ if seeds < 1: raise ValueError("seeds must be at least 1") @@ -724,7 +765,21 @@ def wrapper(*args: Any, **kwargs: Any) -> None: overrides.seeds_explored += len(seed_set) return overrides.seeds_explored += report.seeds_passed + 1 - report.exception.add_note(report.render(overrides.node_id)) + timeline, timeline_error = None, None + if overrides.timeline_dir is not None: + try: + timeline = write_timeline(report, overrides.timeline_dir) + except OSError as unwritable: + # A drawing that cannot be saved must not cost the user + # the report of the failure it was drawing. + timeline_error = str(unwritable) + report.exception.add_note( + report.render( + overrides.node_id, + timeline=timeline, + timeline_error=timeline_error, + ) + ) raise report.exception return wrapper diff --git a/src/simloop/_pytest_plugin.py b/src/simloop/_pytest_plugin.py index 94c7b39..1b7d13d 100644 --- a/src/simloop/_pytest_plugin.py +++ b/src/simloop/_pytest_plugin.py @@ -7,6 +7,9 @@ from __future__ import annotations +import fnmatch +import os + import pytest from simloop import _explore @@ -63,6 +66,15 @@ def pytest_addoption(parser: pytest.Parser) -> None: metavar="N", help="ordering constraints PCT aims to hit (--simloop-policy=pct only)", ) + group.addoption( + "--simloop-timeline", + nargs="?", + const="", + default=None, + metavar="DIR", + help="draw each failing seed's trace to an HTML page, in DIR if given " + "(as --simloop-timeline=DIR) or where pytest was invoked", + ) def pytest_configure(config: pytest.Config) -> None: @@ -92,10 +104,52 @@ def pytest_configure(config: pytest.Config) -> None: ) _explore.overrides.policy = policy _explore.overrides.pct_depth = depth + _explore.overrides.timeline_dir = _timeline_dir(config) _explore.overrides.sim_tests = 0 _explore.overrides.seeds_explored = 0 +def _is_test_path(value: str, config: pytest.Config) -> bool: + """Would pytest have collected this argument, had we not eaten it? + + A node id or an existing file is one. A directory is one only if there is + something to collect under it — an empty ``artifacts/`` a user made for + the pages themselves is a directory and nothing more. + """ + if "::" in value: + return True + if os.path.isfile(value): + return True + if not os.path.isdir(value): + return False + patterns = config.getini("python_files") + for _, _, files in os.walk(value): + if any(fnmatch.fnmatch(name, pattern) for name in files for pattern in patterns): + return True + return False + + +def _timeline_dir(config: pytest.Config) -> str | None: + """Where failing seeds' timelines go, or ``None`` when nobody asked. + + The directory is optional, which means argparse would otherwise read the + next argument as one: ``pytest --simloop-timeline tests/`` would collect + nothing it was told to, run the whole suite instead, and drop the pages + into the test tree. An argument pytest would have collected is refused. + """ + directory: str | None = config.getoption("--simloop-timeline") + if directory is None: + return None + if directory and _is_test_path(directory, config): + raise pytest.UsageError( + f"--simloop-timeline wants a directory, and {directory!r} is a " + "test path: write the directory as --simloop-timeline=DIR" + ) + # Written where the run was started from, which is where pytest's own + # artifacts land and what a relative path in the report is relative to. + return directory or str(config.invocation_params.dir) + + def pytest_unconfigure(config: pytest.Config) -> None: _explore.overrides.seeds = None _explore.overrides.replay = None @@ -104,6 +158,7 @@ def pytest_unconfigure(config: pytest.Config) -> None: _explore.overrides.jobs = 1 _explore.overrides.policy = None _explore.overrides.pct_depth = None + _explore.overrides.timeline_dir = None _explore.overrides.node_id = None diff --git a/src/simloop/_timeline.py b/src/simloop/_timeline.py new file mode 100644 index 0000000..da7f669 --- /dev/null +++ b/src/simloop/_timeline.py @@ -0,0 +1,581 @@ +"""Draw a recorded trace as a host timeline, as one self-contained page. + +The page is a single HTML file with its CSS, its script and its SVG inline: +it opens from disk, from a CI artifact store or from an attachment, and it +never asks the network for anything. That is a deliberate constraint — a +failure artifact that needs a CDN to render is not an artifact — and it is +what rules out a plotting library here. + +The reading is: one lane per simulated machine, virtual time running left to +right, a dot for every scheduling decision that machine made, and an arrow +for every packet that crossed from one machine to another. A packet that was +sent and never arrived leaves a stub pointing nowhere, which is what a drop, +a loss and a partition all look like from the sender's side. Crashes, +restarts and packets held at transmission mark the lane they happened on. +""" + +from __future__ import annotations + +import html +from collections.abc import Callable, Iterable, Sequence +from dataclasses import dataclass + +from simloop._trace import TraceEvent + +# Events rendered by default. A 50,000-step campaign trace is a multi-megabyte +# page that stalls a browser, and the tail is the part a failure is in; +# ``limit=None`` renders everything for a caller who knows what they are +# asking for. +DEFAULT_LIMIT = 5000 + +# The verbs that name two ends of a link ("send a>b"). Anything else with a +# ">" in it is treated the same way, so a verb added later still draws. +_SEND = "send" +_DELIVER = "deliver" +# Verbs that end a packet's journey short: the sender's send becomes a stub. +_FATES = frozenset({"drop", "lost", "hold"}) +# What happens to a machine rather than to a packet. These get the loud lane +# mark; everything else that marks a lane is a packet's small misfortune, and +# a run that drops a thousand datagrams must not look like a thousand crashes. +_MACHINE_FATES = frozenset({"crash", "restart"}) +# A packet is only ever "lost" where it was going: the network records it when +# a packet reaches a machine that is gone or that has nothing bound to take it +# (SimNetwork._deliver, SimNetwork.crash). Every other fate — dropped at +# transmission, held by a standing cut, duplicated, released — happens at the +# sending end, so it marks the sender's lane. +_ARRIVAL_FATES = frozenset({"lost"}) + +# Layout, in user units of the SVG viewBox. The page is zoomable, so these +# are proportions rather than a promise about pixels. +_GUTTER = 160.0 # lane names live left of the plot +_PLOT = 1120.0 +_RIGHT = 48.0 +_HEAD = 56.0 # the time axis band +_FOOT = 40.0 +_LANE = 64.0 +# Dots are nudged off the lane's centre line by kind, so that a callback's +# scheduling and its running are two rows rather than one overprinted dot. +_KIND_OFFSET = {"schedule": -13.0, "run": 0.0, "cancel": 13.0, "advance": 0.0} +_DOT_RADIUS = 3.0 +_MARK_REACH = 17.0 # half-height of a machine mark's tick +_FATE_REACH = 6.0 # half-height of a packet mark's much quieter tick +_STUB_REACH = 30.0 # how far a stub travels before it stops +_ARROW_INSET = 9.0 # gap between a lane's centre line and an arrow's end +_TICKS = 8 + + +@dataclass(frozen=True, slots=True) +class _Packet: + """One uid's journey: an arrow when it landed, a stub when it did not.""" + + uid: int + src: str + dst: str + start: float + end: float + fate: str + + @property + def delivered(self) -> bool: + return self.fate == _DELIVER + + +@dataclass(frozen=True, slots=True) +class _Mark: + """Something that happened to one machine at one instant.""" + + host: str + verb: str + when: float + label: str + + +@dataclass(frozen=True, slots=True) +class _Scene: + """Everything the renderer needs, with no TraceEvent left unbucketed.""" + + hosts: tuple[str, ...] + dots: dict[str, tuple[TraceEvent, ...]] + marks: dict[str, tuple[_Mark, ...]] + packets: tuple[_Packet, ...] + start: float + end: float + shown: int + + +def timeline_html( + events: Iterable[TraceEvent], *, limit: int | None = DEFAULT_LIMIT +) -> str: + """Render ``events`` as a standalone HTML timeline. + + Returns the whole document, ready to write to a ``.html`` file. Only the + last ``limit`` events are drawn — the page says so when it dropped any — + and ``limit=None`` draws all of them. + """ + ordered = list(events) + total = len(ordered) + if limit is not None: + if limit < 1: + raise ValueError(f"limit must be at least 1, got {limit}") + ordered = ordered[-limit:] + return _render(_bucket(ordered), total) + + +# ---------------------------------------------------------------------- +# Bucketing: pure functions from events to what gets drawn +# ---------------------------------------------------------------------- + + +def _ends(label: str) -> tuple[str, str, str]: + """A net label as ``(verb, src, dst)``; ``dst`` is "" for a lane event. + + ``"send a>b"`` names a link, ``"crash b"`` names a machine, and a label + with neither shape names nothing at all. + """ + verb, _, rest = label.partition(" ") + src, link, dst = rest.partition(">") + return (verb, src, dst if link else "") + + +def _lane_hosts(events: Sequence[TraceEvent]) -> tuple[str, ...]: + """Which lanes to draw, in the order the events first mention them. + + Both ends of every packet get a lane even if that machine ran nothing in + the window: an arrow needs somewhere to land. The simulation's own + hostless work — clock advances, the network's delivery steps, and any + network label that names no machine at all — gets one lane of its own, + last, so that no event goes undrawn. + """ + order: dict[str, None] = {} + hostless = False + for event in events: + if event.kind == "net": + _, src, dst = _ends(event.label) + named = [name for name in (src, dst) if name] + for name in named: + order.setdefault(name, None) + hostless = hostless or not named + elif event.host: + order.setdefault(event.host, None) + else: + hostless = True + names = list(order) + if hostless: + names.append("") + return tuple(names) + + +def _packets(events: Sequence[TraceEvent]) -> tuple[list[_Packet], list[_Mark]]: + """Pair sends with deliveries per uid; everything unpaired still draws. + + One uid can be sent twice — a duplicated datagram is two sends and two + deliveries, and a packet held by a partition is sent again after the heal + — so sends queue per uid and the oldest one answers the next delivery. + That pairs a re-sent packet's arrow with the send that actually crossed, + and leaves the first send as a stub. A send that nothing ever answered is + a packet still in flight when the run ended. + """ + queued: dict[int, list[tuple[float, str, str]]] = {} + packets: list[_Packet] = [] + marks: list[_Mark] = [] + for event in events: + if event.kind != "net": + continue + verb, src, dst = _ends(event.label) + if not dst: + # Something that happened to one machine — a crash, a restart — + # or, when the label names nobody, to the simulation at large. + marks.append(_Mark(src, verb, event.when, event.label)) + continue + queue = queued.setdefault(event.seq, []) + if verb == _SEND: + queue.append((event.when, src, dst)) + elif verb == _DELIVER: + start = queue.pop(0)[0] if queue else event.when + packets.append( + _Packet(event.seq, src, dst, start, event.when, _DELIVER) + ) + elif verb in _FATES and queue: + packets.append( + _Packet(event.seq, src, dst, queue.pop(0)[0], event.when, verb) + ) + else: + # A fate that struck before the packet was ever put on the wire + # (held while the cut stood), a loss discovered at the far end + # after the packet had already been drawn as delivered, or a verb + # about a packet rather than about its journey. Where it happened + # decides whose lane says so. + where = dst if verb in _ARRIVAL_FATES else src + marks.append(_Mark(where, verb, event.when, event.label)) + for uid, queue in queued.items(): + for when, src, dst in queue: + packets.append(_Packet(uid, src, dst, when, when, "inflight")) + packets.sort(key=lambda packet: (packet.start, packet.end, packet.uid)) + return packets, marks + + +def _bucket(events: Sequence[TraceEvent]) -> _Scene: + hosts = _lane_hosts(events) + packets, marks = _packets(events) + dots: dict[str, list[TraceEvent]] = {host: [] for host in hosts} + for event in events: + if event.kind != "net": + dots.setdefault(event.host, []).append(event) + grouped: dict[str, list[_Mark]] = {host: [] for host in hosts} + for mark in marks: + grouped.setdefault(mark.host, []).append(mark) + moments = [event.when for event in events] + return _Scene( + hosts=hosts, + dots={host: tuple(found) for host, found in dots.items()}, + marks={host: tuple(found) for host, found in grouped.items()}, + packets=tuple(packets), + start=min(moments, default=0.0), + end=max(moments, default=0.0), + shown=len(events), + ) + + +# ---------------------------------------------------------------------- +# Rendering +# ---------------------------------------------------------------------- + + +def _esc(text: str) -> str: + return html.escape(text) + + +def _num(value: float) -> str: + return f"{value:.2f}" + + +def _clock(when: float) -> str: + return f"{when:.4f}" + + +def _name_of(host: str) -> str: + # A display name for the lane holding what belongs to no machine. A host + # could in principle be registered under this very name — host names + # refuse only "|", ">" and newline — so the lane's identity is its empty + # ``data-host``, which no machine can have, and never this label. + return host if host else "the simulation" + + +def _title(*parts: str) -> str: + body = " ".join(part for part in parts if part) + return f"{_esc(body)}" + + +def _render(scene: _Scene, total: int) -> str: + width = _GUTTER + _PLOT + _RIGHT + height = _HEAD + len(scene.hosts) * _LANE + _FOOT + span = scene.end - scene.start + + def x_of(when: float) -> float: + if span <= 0: + # One instant, or none: the events all sit on the same line, and + # a scale would be a division by zero either way. + return _GUTTER + _PLOT / 2 + return _GUTTER + (when - scene.start) / span * _PLOT + + rows = { + host: _HEAD + index * _LANE + _LANE / 2 + for index, host in enumerate(scene.hosts) + } + parts = [ + "", + '', + "", + '', + '', + "simloop timeline", + f"", + "", + "", + "
", + "

simloop timeline

", + f'

{_meta(scene)}

', + ] + if scene.shown < total: + parts.append( + f'" + ) + parts.append(_LEGEND) + parts.append("
") + parts.append( + f'' + ) + parts.append( + '' + '' + ) + parts.extend(_axis(scene, height, x_of)) + for index, host in enumerate(scene.hosts): + parts.extend(_lane(scene, host, index, rows[host], width, x_of)) + parts.append('') + parts.extend(_packet(packet, rows, x_of) for packet in scene.packets) + parts.append("") + parts.append("") + if not scene.shown: + parts.append('

no events: nothing was recorded

') + parts.append(f"") + parts.append("") + parts.append("") + return "\n".join(parts) + "\n" + + +def _meta(scene: _Scene) -> str: + lanes = len(scene.hosts) + events = "event" if scene.shown == 1 else "events" + noun = "lane" if lanes == 1 else "lanes" + arrows = sum(1 for packet in scene.packets if packet.delivered) + return _esc( + f"{scene.shown:,} {events} across {lanes} {noun}, " + f"{arrows:,} delivered, " + f"virtual time {_clock(scene.start)} to {_clock(scene.end)}" + ) + + +def _axis(scene: _Scene, height: float, x_of: Callable[[float], float]) -> list[str]: + span = scene.end - scene.start + parts = [''] + for step in range(_TICKS + 1): + when = scene.start + span * step / _TICKS + x = x_of(when) + parts.append( + f'' + ) + parts.append( + f'' + f"t={_clock(when)}" + ) + parts.append("") + return parts + + +def _lane( + scene: _Scene, + host: str, + index: int, + row: float, + width: float, + x_of: Callable[[float], float], +) -> list[str]: + shade = " lane-odd" if index % 2 else "" + sim = " lane-sim" if not host else "" + parts = [ + f'', + f'', + f'', + f'' + f"{_esc(_name_of(host))}", + ] + for event in scene.dots.get(host, ()): + y = row + _KIND_OFFSET.get(event.kind, 0.0) + x = x_of(event.when) + when = f"t={_clock(event.when)}" + parts.append( + f'' + f"{_title(when, event.kind, host, event.label)}" + "" + ) + for mark in scene.marks.get(host, ()): + x = x_of(mark.when) + machine = mark.verb in _MACHINE_FATES + # A machine's fate and a packet's fate are different news, so they are + # different marks: a full-height tick for a crash or a restart, and a + # small quiet one for a packet that was dropped, held or duplicated. + css, reach = ("mark", _MARK_REACH) if machine else ("fate", _FATE_REACH) + parts.append( + f'' + f"{_title(f't={_clock(mark.when)}', mark.label)}" + ) + parts.append("") + return parts + + +def _packet( + packet: _Packet, rows: dict[str, float], x_of: Callable[[float], float] +) -> str: + src = rows.get(packet.src, 0.0) + dst = rows.get(packet.dst, src) + # Down the page, up the page, or — a machine talking to itself — neither. + heading = (dst > src) - (dst < src) + left = x_of(packet.start) + link = f"{packet.src}>{packet.dst}" + common = ( + f'data-uid="{packet.uid}" data-src="{_esc(packet.src)}" ' + f'data-dst="{_esc(packet.dst)}" data-start="{packet.start!r}" ' + f'data-end="{packet.end!r}"' + ) + when = f"t={_clock(packet.start)}" + if packet.delivered: + # Both ends stop short of the lane lines, so that an arrowhead does + # not land on top of the dots it arrived among. A self-addressed + # packet has no lane to travel to, and hops above its own instead. + inset = _ARROW_INSET * heading if heading else -_ARROW_INSET + return ( + f'' + f"{_title(when, link, f'delivered t={_clock(packet.end)}')}" + ) + fate = ( + "still in flight when the run ended" + if packet.fate == "inflight" + else f"{packet.fate} t={_clock(packet.end)}" + ) + drift = _STUB_REACH / 2 * (heading if heading else -1) + return ( + f'' + f"{_title(when, link, fate)}" + ) + + +_LEGEND = ( + '
    ' + '
  • scheduled
  • ' + '
  • ran
  • ' + '
  • cancelled
  • ' + '
  • packet delivered
  • ' + '
  • sent, never arrived
  • ' + '
  • packet dropped, held, ' + "duplicated or lost
  • " + '
  • machine crashed or restarted
  • ' + "
" + '

wheel to zoom, drag to pan, double-click to reset; ' + "hover any element for its label and time

" +) + +_CSS = """ +:root { + --bg: #fbfbfd; --panel: #fff; --ink: #1c1f26; --muted: #6b7280; + --rule: #e2e5ec; --band: #f3f5f9; --sim: #eef1f6; + --run: #2563eb; --schedule: #93a3bd; --cancel: #b91c1c; + --arrow: #0f766e; --stub: #d97706; --mark: #7c3aed; +} +@media (prefers-color-scheme: dark) { + :root { + --bg: #14161c; --panel: #191c24; --ink: #e8eaf0; --muted: #97a0b3; + --rule: #2b303c; --band: #1e222b; --sim: #232833; + --run: #7aa2f7; --schedule: #5c6b8a; --cancel: #f7768e; + --arrow: #4bc4b4; --stub: #e0a35c; --mark: #bb9af7; + } +} +* { box-sizing: border-box; } +body { + margin: 0; padding: 20px 24px 40px; background: var(--bg); color: var(--ink); + font: 14px/1.5 ui-sans-serif, system-ui, -apple-system, "Segoe UI", sans-serif; +} +h1 { font-size: 17px; margin: 0 0 4px; letter-spacing: 0.01em; } +.meta, .hint, .empty { color: var(--muted); margin: 0 0 6px; font-size: 13px; } +.banner { + margin: 8px 0; padding: 8px 12px; border-radius: 6px; + border: 1px solid var(--stub); color: var(--ink); background: var(--band); + font-size: 13px; +} +.legend { display: flex; flex-wrap: wrap; gap: 14px; list-style: none; + margin: 10px 0 6px; padding: 0; font-size: 12px; color: var(--muted); } +.legend li { display: flex; align-items: center; gap: 6px; } +.key { display: inline-block; width: 12px; height: 12px; border-radius: 50%; } +.key-schedule { background: var(--schedule); } +.key-run { background: var(--run); } +.key-cancel { background: var(--cancel); } +.key-arrow { height: 0; border-top: 2px solid var(--arrow); border-radius: 0; } +.key-stub { height: 0; border-top: 2px dashed var(--stub); border-radius: 0; } +.key-mark { width: 3px; height: 14px; border-radius: 1px; background: var(--mark); } +.key-fate { width: 3px; height: 7px; border-radius: 1px; background: var(--stub); } +svg { + display: block; width: 100%; height: auto; margin-top: 6px; + background: var(--panel); border: 1px solid var(--rule); border-radius: 8px; + touch-action: none; cursor: grab; +} +svg.dragging { cursor: grabbing; } +.lane-bg { fill: var(--panel); } +.lane-odd { fill: var(--band); } +.lane-sim { fill: var(--sim); } +.lane-line { stroke: var(--rule); stroke-width: 1; } +.lane-name { + fill: var(--ink); font-size: 13px; font-weight: 600; + font-family: ui-monospace, "SF Mono", Menlo, monospace; +} +.grid { stroke: var(--rule); stroke-width: 1; stroke-dasharray: 2 4; } +.tick { + fill: var(--muted); font-size: 11px; text-anchor: middle; + font-family: ui-monospace, "SF Mono", Menlo, monospace; +} +.dot { fill: var(--run); } +.dot[data-kind="schedule"] { fill: var(--schedule); } +.dot[data-kind="cancel"] { fill: var(--cancel); } +.dot[data-kind="advance"] { fill: none; stroke: var(--muted); stroke-width: 1.5; } +.arrow { stroke: var(--arrow); stroke-width: 1.6; } +.stub { stroke: var(--stub); stroke-width: 1.6; stroke-dasharray: 3 3; } +.mark { stroke: var(--mark); stroke-width: 2.5; } +.mark[data-mark="restart"] { stroke-dasharray: 3 3; } +.fate { stroke: var(--stub); stroke-width: 1.4; } +.fate[data-mark="dup"], .fate[data-mark="release"] { stroke: var(--muted); } +marker path { fill: var(--arrow); } +""" + +_JS = """ +(function () { + var svg = document.getElementById("sl-view"); + if (!svg) { return; } + var home = svg.getAttribute("viewBox").split(" ").map(Number); + var view = home.slice(); + var grabbed = null; + function apply() { svg.setAttribute("viewBox", view.join(" ")); } + function at(event) { + var box = svg.getBoundingClientRect(); + return [ + view[0] + (event.clientX - box.left) / box.width * view[2], + view[1] + (event.clientY - box.top) / box.height * view[3] + ]; + } + svg.addEventListener("wheel", function (event) { + event.preventDefault(); + var factor = event.deltaY < 0 ? 0.85 : 1.18; + var width = view[2] * factor; + if (width > home[2] * 3 || width < home[2] / 400) { return; } + var spot = at(event); + view[0] = spot[0] - (spot[0] - view[0]) * factor; + view[1] = spot[1] - (spot[1] - view[1]) * factor; + view[2] = width; + view[3] = view[3] * factor; + apply(); + }, { passive: false }); + svg.addEventListener("pointerdown", function (event) { + grabbed = at(event); + svg.setPointerCapture(event.pointerId); + svg.classList.add("dragging"); + }); + svg.addEventListener("pointermove", function (event) { + if (!grabbed) { return; } + var spot = at(event); + view[0] -= spot[0] - grabbed[0]; + view[1] -= spot[1] - grabbed[1]; + apply(); + }); + function release() { grabbed = null; svg.classList.remove("dragging"); } + svg.addEventListener("pointerup", release); + svg.addEventListener("pointercancel", release); + svg.addEventListener("dblclick", function () { + view = home.slice(); + apply(); + }); +})(); +""" diff --git a/tests/test_explore.py b/tests/test_explore.py index a965c69..5584654 100644 --- a/tests/test_explore.py +++ b/tests/test_explore.py @@ -369,6 +369,31 @@ def _report_with(divergence: Divergence) -> SeedReport: ) +def test_report_repr_does_not_dump_the_whole_trace() -> None: + # The report is reachable from a failing test's traceback, and it now + # carries every event of the failing run for the timeline to draw. A + # dataclass repr would print all of them into the terminal. + def tick() -> None: + pass + + async def churns_at(bad_seed: int) -> None: + loop = asyncio.get_running_loop() + assert isinstance(loop, simloop.SimLoop) + for _ in range(100): + loop.call_soon(tick) + await asyncio.sleep(0) + if loop.seed == bad_seed: + raise RuntimeError("boom") + + report = explore(lambda: churns_at(1), range(4), trace_tail=2) + assert report is not None + assert len(report.trace) > 200 + text = repr(report) + assert len(text) < 1_000 + assert "trace=" not in text + assert "trace_events=" in text + + def test_sim_test_reraises_with_report_note() -> None: @sim_test(seeds=10) async def my_test() -> None: diff --git a/tests/test_pytest_plugin.py b/tests/test_pytest_plugin.py index 67a9103..ec8c0c0 100644 --- a/tests/test_pytest_plugin.py +++ b/tests/test_pytest_plugin.py @@ -292,6 +292,148 @@ def test_pct_refuses_worker_processes(pytester: pytest.Pytester) -> None: ) +_TWO_HOSTS = """ +import asyncio +from simloop import sim_test + + +async def wait(): + await asyncio.sleep(0.5) + + +@sim_test(seeds=10) +async def test_flaky(): + loop = asyncio.get_running_loop() + alpha = loop.net.host("alpha") + beta = loop.net.host("beta") + await alpha.create_task(wait()) + await beta.create_task(wait()) + assert loop.seed != 3 +""" + + +def test_timeline_flag_writes_a_page_for_the_failing_seed( + pytester: pytest.Pytester, +) -> None: + pytester.makepyfile(test_demo=_TWO_HOSTS) + result = pytester.runpytest_subprocess("--simloop-timeline") + result.assert_outcomes(failed=1) + result.stdout.fnmatch_lines(["*timeline: *simloop-timeline-seed3.html*"]) + written = pytester.path / "simloop-timeline-seed3.html" + page = written.read_text(encoding="utf-8") + assert page.startswith("") + assert 'data-host="alpha"' in page + + +def test_timeline_flag_takes_a_directory(pytester: pytest.Pytester) -> None: + pytester.makepyfile(test_demo=_TWO_HOSTS) + result = pytester.runpytest_subprocess("--simloop-timeline=artifacts/runs") + result.assert_outcomes(failed=1) + written = pytester.path / "artifacts" / "runs" / "simloop-timeline-seed3.html" + assert written.exists() + result.stdout.fnmatch_lines(["*timeline: *artifacts?runs?simloop-timeline-seed3*"]) + + +def test_timeline_flag_does_not_swallow_a_test_path(pytester: pytest.Pytester) -> None: + # The directory is optional, so argparse would happily read the next + # argument as one; a test path is refused rather than quietly running the + # whole suite and writing the pages into the test tree. + pytester.makepyfile(test_demo=_FLAKY) + suite = pytester.path / "suite" + suite.mkdir() + (suite / "test_inner.py").write_text("def test_ok():\n pass\n") + for swallowed in ("test_demo.py", "suite", "test_demo.py::test_flaky"): + result = pytester.runpytest_subprocess("--simloop-timeline", swallowed) + assert result.ret != 0, swallowed + result.stderr.fnmatch_lines(["*--simloop-timeline=DIR*"]) + + +def test_timeline_flag_accepts_a_directory_holding_no_tests( + pytester: pytest.Pytester, +) -> None: + # The guard must not refuse the ordinary case: an artifacts directory the + # user made earlier, which is a directory and nothing more. + pytester.makepyfile(test_demo=_TWO_HOSTS) + (pytester.path / "artifacts").mkdir() + result = pytester.runpytest_subprocess("--simloop-timeline", "artifacts") + result.assert_outcomes(failed=1) + assert (pytester.path / "artifacts" / "simloop-timeline-seed3.html").exists() + + +def test_a_timeline_that_cannot_be_written_keeps_the_report( + pytester: pytest.Pytester, +) -> None: + # A drawing that cannot be saved must not cost the user the failure it was + # drawing: the report still names the seed and the replay command, and the + # exception is still the assertion that failed. + pytester.makepyfile(test_demo=_TWO_HOSTS) + (pytester.path / "blocked").write_text("not a directory\n") + result = pytester.runpytest_subprocess("--simloop-timeline=blocked/pages") + result.assert_outcomes(failed=1) + result.stdout.fnmatch_lines( + [ + "*simloop: failed at seed 3 (3 seeds passed first)*", + "*replay: pytest 'test_demo.py::test_flaky' --simloop-replay=3*", + "*timeline not written: *blocked*", + "*last * trace events:*", + ] + ) + + +def test_no_timeline_without_the_flag(pytester: pytest.Pytester) -> None: + pytester.makepyfile(test_demo=_FLAKY) + result = pytester.runpytest_subprocess() + result.assert_outcomes(failed=1) + result.stdout.no_fnmatch_line("*timeline:*") + assert not list(pytester.path.glob("simloop-timeline-*.html")) + + +def test_no_timeline_for_a_passing_test(pytester: pytest.Pytester) -> None: + pytester.makepyfile( + test_demo=""" +import asyncio +from simloop import sim_test + + +@sim_test(seeds=3) +async def test_clean(): + await asyncio.sleep(0.1) +""" + ) + result = pytester.runpytest_subprocess("--simloop-timeline") + result.assert_outcomes(passed=1) + assert not list(pytester.path.glob("simloop-timeline-*.html")) + + +def test_timeline_covers_the_whole_run_not_just_the_report_tail( + pytester: pytest.Pytester, +) -> None: + # The failure report prints a tail of the trace; the page is the run. + pytester.makepyfile( + test_demo=""" +import asyncio +from simloop import sim_test + + +def tick(): + pass + + +@sim_test(seeds=10, trace_tail=5) +async def test_flaky(): + loop = asyncio.get_running_loop() + for _ in range(50): + loop.call_soon(tick) + await asyncio.sleep(0) + assert loop.seed != 3 +""" + ) + result = pytester.runpytest_subprocess("--simloop-timeline") + result.assert_outcomes(failed=1) + page = (pytester.path / "simloop-timeline-seed3.html").read_text(encoding="utf-8") + assert page.count('class="dot"') > 50 + + def test_replay_flag_runs_exactly_one_seed(pytester: pytest.Pytester) -> None: pytester.makepyfile(test_demo=_FLAKY) result = pytester.runpytest_subprocess("--simloop-replay=3") diff --git a/tests/test_timeline.py b/tests/test_timeline.py new file mode 100644 index 0000000..9e36ee4 --- /dev/null +++ b/tests/test_timeline.py @@ -0,0 +1,360 @@ +"""The HTML timeline: lanes, arrows, marks, truncation and self-containment.""" + +from __future__ import annotations + +import asyncio +import re + +import pytest + +from simloop import SimLoop, timeline_html +from simloop._trace import TraceEvent + +# ---------------------------------------------------------------------- +# A real two-host run whose invariant fails: beta sends three datagrams to +# alpha and only two arrive, because a partition lands while the third is in +# flight. The trace of that run is what most of these tests render. +# ---------------------------------------------------------------------- + + +class _Collector(asyncio.DatagramProtocol): + def __init__(self) -> None: + self.received: list[bytes] = [] + + def datagram_received(self, data: bytes, addr: tuple[str, int]) -> None: + self.received.append(data) + + +def _run_partitioned_exchange() -> tuple[SimLoop, list[bytes], list[bytes]]: + loop = SimLoop(seed=0) + alpha = loop.net.host("alpha") + beta = loop.net.host("beta") + loop.net.set_defaults(latency=(0.05, 0.05)) + + async def bind(port: int) -> tuple[asyncio.DatagramTransport, _Collector]: + endpoint: tuple[asyncio.DatagramTransport, _Collector] = ( + await asyncio.get_running_loop().create_datagram_endpoint( + _Collector, local_addr=("0.0.0.0", port) + ) + ) + return endpoint + + async def main() -> tuple[list[bytes], list[bytes]]: + receiver, at_alpha = await alpha.create_task(bind(7000)) + sender, at_beta = await beta.create_task(bind(7001)) + for number in range(2): + sender.sendto(f"ping{number}".encode(), ("alpha", 7000)) + await asyncio.sleep(0.2) + receiver.sendto(b"ack", ("beta", 7001)) + await asyncio.sleep(0.2) + sender.sendto(b"ping2", ("alpha", 7000)) + await asyncio.sleep(0.01) # still in flight: latency is 0.05 + loop.net.partition({"alpha"}, {"beta"}) + await asyncio.sleep(0.2) # its delivery lands on the cut and is dropped + loop.net.heal() + loop.net.crash("beta") + await asyncio.sleep(0.1) + loop.net.restart("beta") + await asyncio.sleep(0.1) + receiver.close() + await asyncio.sleep(0.01) + return at_alpha.received, at_beta.received + + try: + arrived, acked = loop.run_until_complete(main()) + finally: + loop.close() + return loop, arrived, acked + + +def _net_labels(loop: SimLoop) -> list[tuple[int, str]]: + return [ + (event.seq, event.label.split(" ", 1)[0]) + for event in loop.trace + if event.kind == "net" + ] + + +def _elements(document: str, css_class: str) -> list[dict[str, str]]: + """Every element opening tag with exactly this class, as attribute maps.""" + tags = re.findall(rf'<[a-z]+ class="{css_class}"[^>]*>', document) + return [dict(re.findall(r'([\w-]+)="([^"]*)"', tag)) for tag in tags] + + +# ---------------------------------------------------------------------- +# The page itself +# ---------------------------------------------------------------------- + + +def test_a_failing_two_host_run_renders_one_svg_page() -> None: + loop, arrived, _ = _run_partitioned_exchange() + # The failure the timeline is there to explain: the third datagram never + # arrived, because the partition landed while it was on the wire. + assert arrived == [b"ping0", b"ping1"] + document = timeline_html(loop.trace) + assert document.startswith("") + assert document.count("") + + +def test_the_page_fetches_nothing_from_anywhere() -> None: + loop, _, _ = _run_partitioned_exchange() + document = timeline_html(loop.trace) + assert "http://" not in document + assert "https://" not in document + # Bare src=/href= only; the arrows carry data-src attributes, which are + # not references to anything. + assert not re.search(r"(? None: + loop, _, _ = _run_partitioned_exchange() + document = timeline_html(loop.trace) + lanes = _elements(document, "lane") + hosts = [lane["data-host"] for lane in lanes] + # Every machine that ran or was named by a packet, plus one lane for the + # simulation's own hostless work (clock advances, wire steps). + assert set(hosts) == {"alpha", "beta", "driver", ""} + assert len(hosts) == len(set(hosts)) + assert ' None: + loop, _, _ = _run_partitioned_exchange() + document = timeline_html(loop.trace) + delivered = sorted(uid for uid, verb in _net_labels(loop) if verb == "deliver") + arrows = _elements(document, "arrow") + assert len(delivered) >= 3 + assert sorted(int(arrow["data-uid"]) for arrow in arrows) == delivered + both_ways = {(arrow["data-src"], arrow["data-dst"]) for arrow in arrows} + assert both_ways == {("beta", "alpha"), ("alpha", "beta")} + for arrow in arrows: + assert float(arrow["data-end"]) > float(arrow["data-start"]) + + +def test_a_dropped_datagram_leaves_a_stub() -> None: + loop, _, _ = _run_partitioned_exchange() + document = timeline_html(loop.trace) + dropped = [uid for uid, verb in _net_labels(loop) if verb == "drop"] + assert len(dropped) == 1 + stubs = _elements(document, "stub") + assert [int(stub["data-uid"]) for stub in stubs] == dropped + assert stubs[0]["data-fate"] == "drop" + assert stubs[0]["data-src"] == "beta" + + +def test_crash_and_restart_mark_the_lane() -> None: + loop, _, _ = _run_partitioned_exchange() + document = timeline_html(loop.trace) + marks = _elements(document, "mark") + by_verb = {mark["data-mark"]: mark for mark in marks} + # The loud lane mark is reserved for a machine's fate: nothing that merely + # happened to a packet is allowed to look like a crash. + assert set(by_verb) == {"crash", "restart"} + assert by_verb["crash"]["data-host"] == "beta" + assert by_verb["restart"]["data-host"] == "beta" + assert float(by_verb["restart"]["data-when"]) > float(by_verb["crash"]["data-when"]) + + +def test_scheduling_events_become_dots_on_their_host_lane() -> None: + loop, _, _ = _run_partitioned_exchange() + document = timeline_html(loop.trace) + dots = _elements(document, "dot") + scheduling = [event for event in loop.trace if event.kind != "net"] + assert len(dots) == len(scheduling) + assert {"schedule", "run", "advance"} <= {dot["data-kind"] for dot in dots} + # Hover text, which is the only way to read a dot's label. + assert "" in document + + +# ---------------------------------------------------------------------- +# Packet shapes the network really produces, pinned synthetically so the +# pairing rules are readable next to the assertion. +# ---------------------------------------------------------------------- + + +def _net(uid: int, when: float, label: str) -> TraceEvent: + return TraceEvent("net", when, uid, label) + + +def test_a_held_packet_pairs_its_arrow_to_the_second_send() -> None: + # The shape test_trace.py pins: a packet in flight when the cut lands is + # sent, held, released and sent again, and is delivered once. The arrow + # belongs to the send that actually crossed. + events = [ + _net(1, 0.0, "send a>b"), + _net(1, 0.05, "hold a>b"), + _net(1, 0.5, "release a>b"), + _net(1, 0.5, "send a>b"), + _net(1, 0.55, "deliver a>b"), + ] + document = timeline_html(events) + arrows = _elements(document, "arrow") + assert len(arrows) == 1 + assert float(arrows[0]["data-start"]) == pytest.approx(0.5) + assert float(arrows[0]["data-end"]) == pytest.approx(0.55) + # The first send did not reach anyone, and says so. + stubs = _elements(document, "stub") + assert [stub["data-fate"] for stub in stubs] == ["hold"] + assert float(stubs[0]["data-start"]) == pytest.approx(0.0) + + +def test_a_packet_held_before_it_was_ever_sent_marks_the_lane() -> None: + # The other shape: written while the cut stood, so it never left. There is + # no send to draw a stub from, and the hold still has to be visible. + events = [ + _net(2, 0.0, "hold a>b"), + _net(2, 0.5, "release a>b"), + _net(2, 0.5, "send a>b"), + _net(2, 0.55, "deliver a>b"), + ] + document = timeline_html(events) + assert len(_elements(document, "arrow")) == 1 + assert not _elements(document, "stub") + fates = _elements(document, "fate") + assert [fate["data-mark"] for fate in fates] == ["hold", "release"] + # Held at the sending end, so it is the sender's lane that says so. + assert fates[0]["data-host"] == "a" + assert not _elements(document, "mark") + + +def test_a_packets_fate_is_marked_apart_from_a_machines() -> None: + # A chaos run drops thousands of datagrams and crashes a handful of + # machines. If both drew the same tick, the crashes would be invisible. + events = [ + _net(5, 0.0, "drop a>b"), + _net(6, 0.1, "crash b"), + ] + document = timeline_html(events) + fate = _elements(document, "fate")[0] + mark = _elements(document, "mark")[0] + assert fate["data-mark"] == "drop" + assert mark["data-mark"] == "crash" + + def height(tick: dict[str, str]) -> float: + return abs(float(tick["y2"]) - float(tick["y1"])) + + assert height(fate) < height(mark) + assert "packet dropped" in document and "machine crashed" in document + + +def test_a_loss_marks_the_lane_the_packet_was_lost_on() -> None: + # A datagram that arrives at a live machine with nothing bound to take it + # is recorded as delivered and then lost. The loss happened where it + # landed, not where it was sent from. + events = [ + _net(7, 0.0, "send a>b"), + _net(7, 0.1, "deliver a>b"), + _net(7, 0.1, "lost a>b"), + ] + document = timeline_html(events) + assert len(_elements(document, "arrow")) == 1 + fates = _elements(document, "fate") + assert [(fate["data-mark"], fate["data-host"]) for fate in fates] == [("lost", "b")] + + +def test_a_net_label_naming_no_machine_lands_in_the_simulation_lane() -> None: + # Nothing records this today; a verb added later must still draw rather + # than vanish. + document = timeline_html([_net(8, 0.0, "quiesce")]) + assert '<g class="lane" data-host=""' in document + fates = _elements(document, "fate") + assert [(fate["data-mark"], fate["data-host"]) for fate in fates] == [ + ("quiesce", "") + ] + + +def test_a_duplicated_datagram_draws_both_arrows() -> None: + # A duplicate is one uid sent twice and delivered twice; each delivery is + # paired with its own send, oldest first. + events = [ + _net(3, 0.0, "dup a>b"), + _net(3, 0.0, "send a>b"), + _net(3, 0.0, "send a>b"), + _net(3, 0.1, "deliver a>b"), + _net(3, 0.2, "deliver a>b"), + ] + arrows = _elements(timeline_html(events), "arrow") + assert [float(arrow["data-end"]) for arrow in arrows] == [ + pytest.approx(0.1), + pytest.approx(0.2), + ] + + +def test_a_packet_still_in_flight_when_the_run_ended_is_a_stub() -> None: + events = [_net(4, 0.0, "send a>b")] + stubs = _elements(timeline_html(events), "stub") + assert [stub["data-fate"] for stub in stubs] == ["inflight"] + + +# ---------------------------------------------------------------------- +# Size guardrail +# ---------------------------------------------------------------------- + + +def _synthetic(count: int) -> list[TraceEvent]: + return [ + TraceEvent("run", index / 100, index, f"step_{index}", "alpha") + for index in range(count) + ] + + +def test_the_default_limit_keeps_the_last_events_and_says_so() -> None: + document = timeline_html(_synthetic(6000)) + assert 'data-events="5000"' in document + assert 'data-total="6000"' in document + assert "showing the last 5,000 of 6,000 events" in document + # Hover text ends with the label, so this pins which end was kept. + assert "step_5999<" in document + assert "step_999<" not in document + + +def test_no_banner_when_nothing_was_dropped() -> None: + document = timeline_html(_synthetic(10)) + assert 'data-events="10"' in document + assert "showing the last" not in document + + +def test_the_limit_can_be_lifted() -> None: + document = timeline_html(_synthetic(6000), limit=None) + assert 'data-events="6000"' in document + assert "showing the last" not in document + assert "step_0<" in document + + +def test_a_limit_below_one_is_refused() -> None: + with pytest.raises(ValueError, match="limit must be at least 1"): + timeline_html(_synthetic(10), limit=0) + + +# ---------------------------------------------------------------------- +# Escaping and empty input +# ---------------------------------------------------------------------- + + +def test_labels_and_hosts_are_escaped() -> None: + events = [ + TraceEvent("run", 0.0, 0, "<script>alert('x')</script>", "<b>&"), + ] + document = timeline_html(events) + assert "<script>alert" not in document + assert "<script>alert('x')</script>" in document + assert "<b>&" not in document + assert "<b>&" in document + + +def test_an_empty_trace_still_renders_a_page() -> None: + document = timeline_html([]) + assert document.startswith("<!doctype html>") + assert 'data-events="0"' in document + assert "no events" in document From 37cb0312138da43bbf1b874d277d16fcf36bd8b7 Mon Sep 17 00:00:00 2001 From: Dhruv Kumar Singh <singhdhruvk@gmail.com> Date: Sat, 1 Aug 2026 20:42:23 +0530 Subject: [PATCH 6/8] Document priority exploration and the trace timeline --- CHANGELOG.md | 67 ++++++++++++++++++---- README.md | 54 +++++++++++++++--- benchmarks/README.md | 33 +++++------ docs/design.md | 31 ++++++---- docs/supported-api.md | 129 ++++++++++++++++++++++++++++++++++++++++++ 5 files changed, 267 insertions(+), 47 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 96f6dc3..a530c67 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,15 +2,56 @@ ## 0.2.0 (unreleased) +- Traces now say *where*, and that changes every hash. Each scheduling event + carries the host it belongs to — the machine that asked for a callback on + `schedule`, the machine that owns it on `run` and `cancel`, and nothing at + all for the simulation's own work, like a clock advance or the network's + delivery step — and every packet that reaches a machine records a `deliver` + event pairing with its `send` by uid. Both are format changes, so **every + recorded trace hash differs from the one 0.1.0 produced**, whatever the + workload does. That subsumes the narrower disclosure this list used to + carry, when recording crashes was the only thing that moved a hash: there + is now no workload whose trace is byte-identical to 0.1.0's. What a hash + means inside a version is untouched — same seed, same code, same + interpreter, same hash, checked across processes and hash-randomization + seeds as before. +- `TraceEvent` is a `NamedTuple` rather than a frozen dataclass: one is built + for every callback the simulation schedules and runs, and a frozen + dataclass's per-field `object.__setattr__` cost more than twice as much on + the hottest path in the package. Fields, attribute access and immutability + are unchanged, and events now unpack and compare as plain tuples — but + `dataclasses.replace()` and `dataclasses.fields()` on an event raise + `TypeError` where they used to work. +- Schedules can be searched by priority instead of by luck: + `--simloop-policy=pct` (also `explore(policy="pct")` and + `@sim_test(policy="pct")`) runs Burckhardt et al.'s PCT (ASPLOS 2010) — + random priorities per chain of work, highest ready one runs, a few randomly + placed demotions — which buys a stated per-run probability of hitting a bug + that needs `--simloop-pct-depth` ordering constraints (default 3). The + horizon those demotions spread over is measured rather than guessed: seed 0 + runs the seeded schedule and its step count sizes it, which costs one extra + run of the workload and is what lets a found seed replay the schedule that + found it. PCT explores sequentially, so asking for it alongside + `--simloop-jobs` is refused rather than quietly ignored. It is a floor, not + a speed-up — on a shallow race uniform draws reach the bug some 46 times + sooner, and `docs/supported-api.md` publishes that measurement next to the + guarantee. +- A failing seed can draw itself: `--simloop-timeline[=DIR]` writes + `simloop-timeline-seed<N>.html` for each failing seed and names the file in + the report, and `simloop.timeline_html(events)` renders any trace the same + way. One lane per machine and one for the simulation, virtual time left to + right, a dot per scheduling decision, an arrow for every packet that + crossed and a stub for every one that did not, with crashes and restarts + marking the lane they struck. The page is self-contained — inline CSS, + script and SVG, nothing fetched — and draws the last 5,000 events by + default, saying so when it dropped any. - Crashed hosts can come back: `loop.net.restart(name)` (or `host.restart()`) revives a machine as a fresh incarnation. It restores liveness and nothing else — the old tasks stay cancelled and the listeners are gone, so the caller boots the machine again the way it booted it the first time. Traffic due while the host was dead is lost, leaving peers to notice the outage from their own timeouts. Crashes are - now recorded too: `crash()` writes a trace event and consumes a uid, so - a workload that crashes a host hashes differently than it did in 0.1.0 - (workloads that never crash stay byte-identical to 0.1.0). + recorded too: `crash()` writes a trace event and consumes a uid. - Every host now has `host.disk`, a mapping that survives its crashes: where state a real process would fsync belongs. Writes are atomic at assignment; there is no partial-write model. @@ -18,8 +59,9 @@ what that host's tasks read from `loop.time()`, and the deadlines they hand to `call_at` with it, while durations (`sleep`, `timeout`, `wait_for`, `call_later`) cost the same everywhere — which is what a - wrong wall clock does to a real machine. Traces stay on the true clock, - and runs that configure no offset are byte-identical to 0.1.0. + wrong wall clock does to a real machine. Traces stay on the true clock, so + skew never perturbs scheduling and a run that configures no offset makes + exactly the decisions it made without the feature. - A second flagship demo: `examples/raft/` is a teaching-sized Raft (leader election + log replication, plain asyncio on streams) tested only under simulation — four safety invariants checked over 50,000 chaos seeds, five @@ -27,10 +69,10 @@ schedules minimized toward FIFO — down to a single interesting step in the sharpest case. - Campaign evidence at scale, regenerable via `benchmarks/campaign.py`: - 100,000 seeds of jobqueue chaos green in six minutes on a laptop, every - ablation caught with its failure density recorded, and 20 sampled failing - seeds replaying with identical trace hashes across 100 re-runs apiece. - A small nightly CI sweep keeps the numbers honest. + 100,000 seeds of jobqueue chaos green in under six minutes on a laptop, + every ablation caught with its failure density recorded, and 20 sampled + failing seeds replaying with identical trace hashes across 100 re-runs + apiece. A small nightly CI sweep keeps the numbers honest. - Compatibility with third-party libraries is now measured instead of claimed: `probes/` drives aiohttp, anyio, websockets, httpx and the Redis wire protocol under a SimLoop, and `docs/compatibility.md` publishes what @@ -50,9 +92,10 @@ did at the first disagreement, and a window of context from both traces. On by default, costs one retained trace. - Every scheduling decision flows through a policy seam: seeded draws by - default (traces byte-identical to 0.1.0), with recorded choice lists that - can replay a schedule independently of its seed (internal, powers - shrinking). + default, making the same draws the loop made when it owned the PRNG itself, + with recorded choice lists that can replay a schedule independently of its + seed (internal, powers shrinking). Policies are shown who is ready, not + just how many, which is what a priority policy needs. - Seed exploration can use every core: `explore(fn, seeds, jobs=N)` and `--simloop-jobs=N` fan seed batches out over worker processes and report exactly what a sequential run would have — the earliest failing seed, with diff --git a/README.md b/README.md index a40ffb4..467edde 100644 --- a/README.md +++ b/README.md @@ -83,31 +83,46 @@ replay: pytest 'tests/test_counter.py::test_two_increments_both_count' --simloop last 20 trace events: [t=1.3944] run seq=58 SimNetwork._deliver + [t=1.3944] net seq=21 deliver counter>b + [t=1.3944] schedule seq=63 b Task.task_wakeup + [t=1.3944] run seq=63 b Task.task_wakeup [t=1.3944] net seq=23 send b>counter ... - [t=1.3944] run seq=70 SimLoop._stop_when_done + [t=1.3944] run seq=70 driver SimLoop._stop_when_done -runs agree for 38 events; passing then ran StreamReaderProtocol.connection_made.<locals>.callback, failing ran list.remove +runs agree for 41 events; passing then ran StreamReaderProtocol.connection_made.<locals>.callback, failing ran list.remove passing run: - [t=1.0944] schedule seq=13 SimNetwork._deliver + [t=1.0944] schedule seq=13 counter SimNetwork._deliver ... failing run: - [t=1.1224] schedule seq=13 SimNetwork._deliver + [t=1.1224] schedule seq=13 counter SimNetwork._deliver ... pending tasks by host: - counter Task 'Task-1026' awaiting serve at tests/test_counter.py:26 + counter Task 'Task-1026' awaiting serve at tests/test_counter.py:24 ``` The report names the failing seed, prints the exact command that replays it — same scheduling decisions, same fault decisions, same trace — and diffs the failing run against the last passing seed, so the first thing -the two runs did differently is one line of output. In CI, crank the -search without touching code: +the two runs did differently is one line of output. Trace lines name the +machine whose work they were; the ones naming none are the simulation's own +— the clock advancing, a packet crossing the wire. In CI, crank the search +without touching code: ``` pytest --simloop-seeds=1000 ``` +Seeds are not the only way to search. `--simloop-policy=pct` schedules by +priority instead of drawing uniformly — Burckhardt et al.'s PCT (ASPLOS +2010): every chain of work gets a random priority, the highest ready one +always runs, and a few randomly placed demotions shuffle the leader. That +buys a stated probability, on every single run, of hitting a bug that needs +`--simloop-pct-depth` scheduling constraints met in order. It is a floor, +not a speed-up: on shallow races uniform draws find the bug sooner, and the +[contract page](https://github.com/dhruvl/simloop/blob/main/docs/supported-api.md) +publishes the measurement that says so. + ## Shrink the schedule to the race Most steps of a failing schedule are noise. With `--simloop-shrink`, the @@ -153,6 +168,27 @@ so look at the fault timings, not the task order. Shrinking is off by default (it costs extra runs, capped by `--simloop-shrink-budget`, default 500) and experimental. +## Watch the run that failed + +A schedule is easier to read as a picture than as a wall of trace lines: + +``` +pytest --simloop-timeline=artifacts +``` + +Every failing seed leaves `artifacts/simloop-timeline-seed<N>.html`, named in +its failure report. The page is self-contained — inline CSS, inline script, +inline SVG, nothing fetched — so it opens from a CI artifact store or an +attachment as readily as from disk. It draws one lane per simulated machine +and one for the simulation itself, virtual time running left to right, a dot +for every scheduling decision on that machine, and an arrow for every packet +that crossed. A packet that was sent and never arrived leaves a stub pointing +nowhere, which is what a drop, a loss and a partition all look like from the +sender's side; crashes and restarts mark the lane they struck. The last 5,000 +events are drawn, and the page says so when there were more. +`simloop.timeline_html(events)` renders the same page from any trace you are +holding. + ## What the simulation gives you - **Seeded scheduling** — the ready queue's execution order comes from a @@ -213,8 +249,8 @@ Simulation is cheap: SimLoop schedules a task step in ~4.4 µs (trace recording included — about 3.6× faster than the stock loop, which pays a selector syscall per iteration), compresses sleep-heavy workloads ~2,000× against wall clock, and with `--simloop-jobs` fanning seeds across -processes, the full jobqueue chaos scenario sweeps 100,000 seeds in six -minutes (~280 seeds/second) on an M4 MacBook Air. Methodology, numbers, +processes, the full jobqueue chaos scenario sweeps 100,000 seeds in under +six minutes (~300 seeds/second) on an M4 MacBook Air. Methodology, numbers, and the campaign results: [benchmarks/README.md](https://github.com/dhruvl/simloop/blob/main/benchmarks/README.md). diff --git a/benchmarks/README.md b/benchmarks/README.md index 3232ba4..95df9ef 100644 --- a/benchmarks/README.md +++ b/benchmarks/README.md @@ -25,16 +25,17 @@ hand-off — no I/O, no timers. SimLoop comes out about **3.6× faster per scheduling step**, trace recording included, and the ratio holds from 10×2000 to 500×200 task/round shapes -(0.26–0.29× across the sweep). That is not because simloop is a faster event -loop in any general sense — it is because a simulated loop never touches the -OS. Profiling the stock run shows about half its time inside -`select.kqueue.control`: the real loop pays a selector syscall on every -iteration even when no I/O is pending, while SimLoop's iteration is pure -Python — pop the PRNG-chosen callback, run it, append a trace event. The -practical reading: replayable scheduling costs nothing at test time. (For -contrast, trio's experimental deterministic-scheduling hook measured ~15% -overhead on top of its normal loop — python-trio/trio#890; simloop sidesteps -the comparison by replacing the loop instead of instrumenting it.) +(0.26–0.30× across the sweep, widening with the task count). That is not +because simloop is a faster event loop in any general sense — it is because a +simulated loop never touches the OS. Profiling the stock run shows about half +its time inside `select.kqueue.control`: the real loop pays a selector +syscall on every iteration even when no I/O is pending, while SimLoop's +iteration is pure Python — pop the PRNG-chosen callback, run it, append a +trace event. The practical reading: replayable scheduling costs nothing at +test time. (For contrast, trio's experimental deterministic-scheduling hook +measured ~15% overhead on top of its normal loop — python-trio/trio#890; +simloop sidesteps the comparison by replacing the loop instead of +instrumenting it.) The stock-loop baseline is macOS/kqueue; an epoll or io_uring machine will price the syscall differently. @@ -51,7 +52,7 @@ of simulated time: | simulated | wall | compression | |---|---|---| -| 7164 s (1.99 h) | 3.55 s | **~2,000×** | +| 7164 s (1.99 h) | 3.60 s | **~2,000×** | Virtual time never sleeps: between timers the clock jumps, so a suite full of `await asyncio.sleep(300)` costs only its callback processing. This is what @@ -67,8 +68,8 @@ The jobqueue chaos campaign runs one full distributed scenario per seed — a broker, 3 workers, and 2 clients submitting 8 jobs (some poisoned) under randomized partitions and a worker crash, then settles for up to 600 simulated seconds and checks every invariant. 300 seeds complete in -**5.4–6.0 s**, about **55 seeds/second**. A thousand-seed overnight search is -a 20-second coffee break. +**5.0–5.2 s**, about **59 seeds/second**, in one process. A thousand-seed +overnight search is a 17-second coffee break. ## Campaigns @@ -109,9 +110,9 @@ Results, recorded 2026-08-01 on the M4 MacBook Air (10 jobs): | campaign | scale | result | |---|---|---| -| green | 100,000 seeds, 6.0 min, 279.6 seeds/s | green — no invariant violated | -| ablations | 6 mutations × 10,000 seeds, 2.6 min | every ablation caught, densities below | -| replay stability | 20 failing seeds × 100 re-runs | identical trace hash on every run | +| green | 100,000 seeds, 5.6 min, 300.1 seeds/s | green — no invariant violated | +| ablations | 6 mutations × 10,000 seeds, 2.5 min | every ablation caught, densities below | +| replay stability | 20 failing seeds × 100 re-runs, 13.5 s | identical trace hash on every run | Per-ablation failure density: diff --git a/docs/design.md b/docs/design.md index 6b6222d..d0e4f5c 100644 --- a/docs/design.md +++ b/docs/design.md @@ -259,15 +259,25 @@ ten lines of task startup. **The policy seam.** The loop has exactly one ordering decision — which ready callback runs next — and it now flows through a policy object: seeded -draws by default (byte-identical to owning the PRNG directly, held to that -by the determinism suite), or a scripted replay of a recorded choice list. -The recording makes a schedule *editable* where the seed only made it -*repeatable*: a seed is a name for one schedule, but a choice list can be -truncated, blanked to FIFO, or perturbed one decision at a time. Scripted -runs tolerate drift on purpose — an out-of-range choice clamps, an -exhausted recording falls back to FIFO — because an edited schedule that -crashes the replayer answers nothing, while one that runs to a verdict -answers the only question shrinking asks. +draws by default (making the same draws the loop made when it owned the PRNG +directly, held to that by the determinism suite), or a scripted replay of a +recorded choice list. The recording makes a schedule *editable* where the +seed only made it *repeatable*: a seed is a name for one schedule, but a +choice list can be truncated, blanked to FIFO, or perturbed one decision at +a time. Scripted runs tolerate drift on purpose — an out-of-range choice +clamps, an exhausted recording falls back to FIFO — because an edited +schedule that crashes the replayer answers nothing, while one that runs to a +verdict answers the only question shrinking asks. + +The seam later grew a third policy and a wider view to feed it. Policies are +handed the ready queue as `(owner, label)` views rather than a count, which +is what a priority scheduler needs and what the two original policies still +ignore; on top of that sits PCT (Burckhardt et al., ASPLOS 2010), reached by +`--simloop-policy=pct`, which prices each chain of work with a random +priority and demotes the leader at a few random steps to buy a stated per-run +probability of hitting a bug of a given ordering depth. The contract page +carries the guarantee, the calibration story and the measurement showing it +is a floor rather than a faster search. **Shrinking is delta debugging over choices, judged by the exception.** Three passes, cheapest first: truncate the recording past the failure @@ -303,7 +313,8 @@ so SimLoop schedules a task step in ~4.4 µs where the stock macOS loop spends ~16 µs — about half of that inside the per-iteration `kqueue` call — making the simulation roughly 3.6× faster per step *including* trace recording. Sleep-heavy workloads compress ~2,000× against wall clock, and -the full jobqueue chaos scenario explores ~55 seeds/second on a laptop. +the full jobqueue chaos scenario explores ~59 seeds/second in one process on +a laptop. The trio thread priced deterministic scheduling at ~15% overhead; replacing the loop instead of instrumenting it turned the overhead negative. diff --git a/docs/supported-api.md b/docs/supported-api.md index 9deb34c..6e6ba99 100644 --- a/docs/supported-api.md +++ b/docs/supported-api.md @@ -92,3 +92,132 @@ stays fenced outright: `sock_recv`, `sock_recv_into`, `sock_sendall`, `sock_sendto`, `sock_recvfrom`, `sock_recvfrom_into`, `sock_accept` and `sock_sendfile`. Client stacks do not need them: the socket they connect is upgraded into a transport instead of being read and written directly. + +## The trace + +Every scheduling decision and every network verdict is appended to a trace +whose SHA-256 is what proves a replay was exact. `simloop.TraceEvent` is a +`NamedTuple`, so an event compares and unpacks as `(kind, when, seq, label, +host)`: + +| field | what it holds | +|---|---| +| `kind` | `schedule`, `run`, `cancel`, `advance` or `net` | +| `when` | virtual time, always on the true clock — `set_clock` changes what a host reads, never what a trace records | +| `seq` | the scheduled handle's number; the packet's uid on a `net` event; `-1` on a clock advance | +| `label` | the qualified callback name, or a network verb and the link it crossed (`send a>b`) | +| `host` | the machine the event belongs to, or `""` for the simulation itself | + +A `schedule` event names the host that *asked* for the callback, while `run` +and `cancel` name the host the callback belongs to. The difference is the +point: a wakeup that crosses machines is a `schedule` on one host and a `run` +on another. An empty host means the event belongs to the simulation rather +than to any machine — a clock advance, which is global; the network's own +delivery step, which happens on the wire between two machines rather than on +either of them; and every `net` event, whose label already says which +machines it concerns. + +`send` is a packet going onto the wire and `deliver` is that same packet +arriving. Both carry the packet's uid in `seq`, so the two ends of one +crossing pair up. The other verbs are usually what happened instead: `drop` (a +lossy link, or a datagram meeting a partition), `hold` and `release` (a stream +packet parked by a partition, then put back on the wire when it heals), `dup` +(a duplicate on its way as well, under the same uid), and `lost` (it reached a +machine that was gone, or a port with nothing bound). "Usually", because the +second kind of loss follows a `deliver` rather than replacing it: the packet +did reach the machine, and only then found nothing to take it. `crash` and +`restart` name a machine instead of a link. + +Hashes are comparable within a version, not across versions: the host field +and the `deliver` events are new in 0.2.0, so every workload's trace hashes +differ from the ones 0.1.0 recorded — see the +[changelog](../CHANGELOG.md). What a hash promises is unchanged: same seed, +same code, same interpreter, same hash. + +`simloop.timeline_html(events, limit=5000)` renders a trace as a +self-contained HTML page — one lane per machine plus one for the simulation, +a dot per scheduling decision, an arrow for every `send` its `deliver` +answered, and a stub for every one that never arrived. Only the last `limit` +events are drawn, and the page says so when it dropped any; `limit=None` +draws the whole run. + +## Exploring schedules + +`@sim_test(seeds=N)` and `simloop.explore(fn, seeds)` run a workload once per +seed on a fresh loop and stop at the first failure. Under pytest these +options override what the decorator asked for: + +| option | effect | +|---|---| +| `--simloop-seeds=N` | run every `@sim_test` under seeds 0..N-1 | +| `--simloop-replay=SEED` | run every `@sim_test` at exactly this seed | +| `--simloop-jobs=N` | spread a test's seeds over N worker processes; the workload has to pickle | +| `--simloop-shrink`, `--simloop-shrink-budget=N` | minimize the failing schedule toward FIFO (experimental, costs runs) | +| `--simloop-policy=random\|pct` | how the scheduler picks the next ready callback | +| `--simloop-pct-depth=N` | ordering constraints PCT aims to hit (default 3) | +| `--simloop-timeline[=DIR]` | draw each failing seed's trace to `simloop-timeline-seed<N>.html`, in `DIR` if given and where pytest was invoked otherwise | + +The timeline is written per failing seed and named in the failure report. A +page that cannot be written says so in the report rather than replacing the +failure with its own. + +### Scheduling policies + +`random`, the default, is one seeded uniform draw over the ready queue per +step: the schedule the seed names, and the only policy a report says nothing +about. + +`pct` schedules by priority instead, after Burckhardt et al., *A Randomized +Scheduler with Probabilistic Guarantees of Finding Bugs* (ASPLOS 2010). Every +chain of work draws a distinct random priority, the highest-priority ready +entry always runs, and at `depth - 1` randomly chosen steps the running chain +is demoted below every chain still holding its first draw. What that buys is +a floor: a bug that needs `depth` scheduling constraints met in order is hit +with probability at least 1/(n · horizon^(depth-1)) on *every* run, where n +is the number of chains and the horizon is the step count the change points +are spread over. Chains are priced as they turn up — an owner nobody has seen +draws its priority on first sight, the standard adaptation for work created +while the run is going — so n is however many chains the run ended up +containing, not a count anyone knew in advance, and where tasks spawn tasks +the bound is best read per run and after the fact. Uniform draws promise +nothing at any depth. + +It is not a faster search, and the repository measures its own claim. On the +planted lost-update race in `tests/test_explore.py` — two ordering +constraints in a twelve-step run, searched at the default depth — uniform +draws reached the first failing seed after 2.0 seeds on average and PCT after +92.75, a failure rate of 474 seeds per 1,000 against 21. A shallow race in a +short run is the shape a uniform draw is already ideal for. PCT is for the +depth a uniform draw is unlikely to stumble into, and what it offers there is +the bound, not a speed-up. + +The rest of the honest print: + +- The guarantee is per run. Nothing here says how many runs a campaign needs, + and a lower bound on a probability is not a promise that a search finds + anything. +- `depth` is a guess about a bug nobody has seen yet. Too low and the change + points cannot express the interleaving; too high and they spread thinner + over the same run. +- The horizon is measured rather than assumed: seed 0 runs once under the + seeded schedule, and its step count times 1.5 — floored at 100, and widened + further if `depth - 1` change points need the room — is the horizon. That + measuring run is one extra run of the workload per exploration, unless seed + 0 is the only seed asked for: it runs the seeded schedule anyway, so there + is nothing left to size. Seed 0 is also explored on its own account, always + under the seeded schedule, because measuring a PCT run would measure the + number it is supposed to produce; the report says so when the failing seed + is that one. +- Fixing the calibration seed at 0 is what keeps a found seed replayable: + replaying it alone measures the same horizon, so it runs the same schedule. +- A run that ends before the horizon passes only some of its change points; a + run that overruns spends all of them in its first `horizon` steps and + finishes at fixed priorities. Both are legal schedules, and neither is the + one the bound describes. +- Callbacks no task owns — timers, protocol callbacks — are each a chain of + their own that draws once and runs once. A change point landing on one + spends a demotion on a chain with no future, so read the bound as a + statement about runs where task chains do the deciding. +- PCT explores sequentially. The horizon is measured in the process that + explores and never reaches a worker, so `--simloop-policy=pct` together + with `--simloop-jobs` above 1 is refused rather than quietly ignored. From 45eb365470678c8d17d402edf9b896c3aa8a51a2 Mon Sep 17 00:00:00 2001 From: Dhruv Kumar Singh <singhdhruvk@gmail.com> Date: Sat, 1 Aug 2026 21:24:53 +0530 Subject: [PATCH 7/8] Republish explorer throughput from a fresh measure The 300-seed chaos campaign now costs 5.3-6.3 s rather than the 5.0-5.2 s published for 0.1.0: recording a trace event per delivery, not just per send, is what lets a timeline draw both ends of a crossing, and a scenario this network-heavy pays for the extra events. Nine runs on the M4 Air after a warmup, median 5.8 s. --- benchmarks/README.md | 15 ++++++++++++--- docs/design.md | 5 +++-- 2 files changed, 15 insertions(+), 5 deletions(-) diff --git a/benchmarks/README.md b/benchmarks/README.md index 95df9ef..498685e 100644 --- a/benchmarks/README.md +++ b/benchmarks/README.md @@ -4,7 +4,8 @@ Three numbers matter for a simulation harness: what the simulated loop costs per scheduling step, how much simulated time it covers per wall-clock second, and how fast the explorer burns through seeds on a real test. Measured on a MacBook Air (Apple M4, 16 GB), macOS, CPython 3.12.13. Every number is the -median of 5 runs after one warmup run, on an otherwise idle machine. Rerun +median of at least 5 runs after one warmup run, on an otherwise idle +machine. Rerun them with the commands below; expect the ratios, not the absolute times, to transfer to other machines. @@ -68,8 +69,16 @@ The jobqueue chaos campaign runs one full distributed scenario per seed — a broker, 3 workers, and 2 clients submitting 8 jobs (some poisoned) under randomized partitions and a worker crash, then settles for up to 600 simulated seconds and checks every invariant. 300 seeds complete in -**5.0–5.2 s**, about **59 seeds/second**, in one process. A thousand-seed -overnight search is a 17-second coffee break. +**5.3–6.3 s** across nine runs (median 5.8 s), about **52 seeds/second**, +in one process. A thousand-seed overnight search is a 19-second coffee +break. + +That is slower than the ~59 seeds/second published for 0.1.0, and the cost +is a feature: 0.2.0 records a trace event for every packet delivery, not +just for every send, which is what lets a timeline draw both ends of a +crossing — and a scenario this network-heavy pays for the extra events +directly. The wire is where this benchmark spends its time, which is why +it is the number that moved. ## Campaigns diff --git a/docs/design.md b/docs/design.md index d0e4f5c..7cfa74f 100644 --- a/docs/design.md +++ b/docs/design.md @@ -313,8 +313,9 @@ so SimLoop schedules a task step in ~4.4 µs where the stock macOS loop spends ~16 µs — about half of that inside the per-iteration `kqueue` call — making the simulation roughly 3.6× faster per step *including* trace recording. Sleep-heavy workloads compress ~2,000× against wall clock, and -the full jobqueue chaos scenario explores ~59 seeds/second in one process on -a laptop. +the full jobqueue chaos scenario explores ~52 seeds/second in one process on +a laptop — down from ~59 in 0.1.0, which is what the per-delivery trace +events a timeline draws from cost a network-heavy workload. The trio thread priced deterministic scheduling at ~15% overhead; replacing the loop instead of instrumenting it turned the overhead negative. From afaf4683804962c3c701746f31bb3a5e65d70b52 Mon Sep 17 00:00:00 2001 From: Dhruv Kumar Singh <singhdhruvk@gmail.com> Date: Sat, 1 Aug 2026 21:25:01 +0530 Subject: [PATCH 8/8] Say what the timeline refusal and the lost verb actually cover Both spellings of --simloop-timeline reach the guard as one string, so the error fired on --simloop-timeline=tests while telling the user to write exactly that. Name the two ways out instead, and pin the = form. The crash sweep records lost for held packets where the crashed host is either end, so a crashed sender's packets land in the destination's lane; say so where the arrival fates are listed and in the verb table. --- benchmarks/README.md | 11 ++++++----- docs/design.md | 2 +- docs/supported-api.md | 3 ++- src/simloop/_explore.py | 4 +++- src/simloop/_pytest_plugin.py | 8 +++++++- src/simloop/_timeline.py | 15 ++++++++++----- tests/test_pytest_plugin.py | 8 +++++++- 7 files changed, 36 insertions(+), 15 deletions(-) diff --git a/benchmarks/README.md b/benchmarks/README.md index 498685e..30c4bfe 100644 --- a/benchmarks/README.md +++ b/benchmarks/README.md @@ -4,9 +4,9 @@ Three numbers matter for a simulation harness: what the simulated loop costs per scheduling step, how much simulated time it covers per wall-clock second, and how fast the explorer burns through seeds on a real test. Measured on a MacBook Air (Apple M4, 16 GB), macOS, CPython 3.12.13. Every number is the -median of at least 5 runs after one warmup run, on an otherwise idle -machine. Rerun -them with the commands below; expect the ratios, not the absolute times, to +median of at least 5 runs after one warmup run, with the machine as idle as +a developer laptop gets. Rerun them with the commands below; expect the +ratios, not the absolute times, to transfer to other machines. ## Scheduling overhead @@ -73,8 +73,9 @@ simulated seconds and checks every invariant. 300 seeds complete in in one process. A thousand-seed overnight search is a 19-second coffee break. -That is slower than the ~59 seeds/second published for 0.1.0, and the cost -is a feature: 0.2.0 records a trace event for every packet delivery, not +That is slower than the ~55 seeds/second (5.4–6.0 s) published for 0.1.0, +and the cost is a feature: 0.2.0 records a trace event for every packet +delivery, not just for every send, which is what lets a timeline draw both ends of a crossing — and a scenario this network-heavy pays for the extra events directly. The wire is where this benchmark spends its time, which is why diff --git a/docs/design.md b/docs/design.md index 7cfa74f..ffd39aa 100644 --- a/docs/design.md +++ b/docs/design.md @@ -314,7 +314,7 @@ spends ~16 µs — about half of that inside the per-iteration `kqueue` call — making the simulation roughly 3.6× faster per step *including* trace recording. Sleep-heavy workloads compress ~2,000× against wall clock, and the full jobqueue chaos scenario explores ~52 seeds/second in one process on -a laptop — down from ~59 in 0.1.0, which is what the per-delivery trace +a laptop — down from ~55 in 0.1.0, which is what the per-delivery trace events a timeline draws from cost a network-heavy workload. The trio thread priced deterministic scheduling at ~15% overhead; replacing the loop instead of instrumenting it turned the overhead negative. diff --git a/docs/supported-api.md b/docs/supported-api.md index 6e6ba99..02145fb 100644 --- a/docs/supported-api.md +++ b/docs/supported-api.md @@ -123,7 +123,8 @@ crossing pair up. The other verbs are usually what happened instead: `drop` (a lossy link, or a datagram meeting a partition), `hold` and `release` (a stream packet parked by a partition, then put back on the wire when it heals), `dup` (a duplicate on its way as well, under the same uid), and `lost` (it reached a -machine that was gone, or a port with nothing bound). "Usually", because the +machine that was gone, a port with nothing bound, or it was a held packet +whose own sender crashed). "Usually", because the second kind of loss follows a `deliver` rather than replacing it: the packet did reach the machine, and only then found nothing to take it. `crash` and `restart` name a machine instead of a link. diff --git a/src/simloop/_explore.py b/src/simloop/_explore.py index aa62697..f3a101b 100644 --- a/src/simloop/_explore.py +++ b/src/simloop/_explore.py @@ -132,7 +132,9 @@ class SeedReport: ``trace`` stays out of the repr: it can hold tens of thousands of events, and this object is reachable from a failing test's traceback, where a - dataclass repr would print the whole run into the terminal. + dataclass repr would print the whole run into the terminal. It is held + whether or not a timeline was asked for, so the memory is the failing + run's full event list either way. """ seed: int diff --git a/src/simloop/_pytest_plugin.py b/src/simloop/_pytest_plugin.py index 1b7d13d..8d22b9f 100644 --- a/src/simloop/_pytest_plugin.py +++ b/src/simloop/_pytest_plugin.py @@ -136,6 +136,9 @@ def _timeline_dir(config: pytest.Config) -> str | None: next argument as one: ``pytest --simloop-timeline tests/`` would collect nothing it was told to, run the whole suite instead, and drop the pages into the test tree. An argument pytest would have collected is refused. + By the time the value reaches here the two spellings are the same string, + so ``--simloop-timeline=tests`` is refused as well; the message names the + ways out rather than a syntax the user may already be using. """ directory: str | None = config.getoption("--simloop-timeline") if directory is None: @@ -143,7 +146,10 @@ def _timeline_dir(config: pytest.Config) -> str | None: if directory and _is_test_path(directory, config): raise pytest.UsageError( f"--simloop-timeline wants a directory, and {directory!r} is a " - "test path: write the directory as --simloop-timeline=DIR" + "test path pytest would have collected: pass " + "--simloop-timeline with no value to write the pages where " + "pytest was invoked, or name a directory that is not also a " + "test path" ) # Written where the run was started from, which is where pytest's own # artifacts land and what a relative path in the report is relative to. diff --git a/src/simloop/_timeline.py b/src/simloop/_timeline.py index da7f669..8f23986 100644 --- a/src/simloop/_timeline.py +++ b/src/simloop/_timeline.py @@ -38,11 +38,16 @@ # mark; everything else that marks a lane is a packet's small misfortune, and # a run that drops a thousand datagrams must not look like a thousand crashes. _MACHINE_FATES = frozenset({"crash", "restart"}) -# A packet is only ever "lost" where it was going: the network records it when -# a packet reaches a machine that is gone or that has nothing bound to take it -# (SimNetwork._deliver, SimNetwork.crash). Every other fate — dropped at -# transmission, held by a standing cut, duplicated, released — happens at the -# sending end, so it marks the sender's lane. +# "lost" marks the destination's lane. Two of the three places it is recorded +# earn that: a packet reaching a machine that is gone, and one reaching a port +# with nothing bound (both SimNetwork._deliver). The third does not — when a +# host crashes it sweeps the packets a standing cut was holding and records +# "lost" for every one where the crashed host is *either* end, so a crashed +# sender's held packets are charged to the lane they were addressed to rather +# than to the machine that died. The mark still lands on a lane the packet +# concerned, and the label carries "src>dst" either way. Every other fate — +# dropped at transmission, held by a standing cut, duplicated, released — +# happens at the sending end, so it marks the sender's lane. _ARRIVAL_FATES = frozenset({"lost"}) # Layout, in user units of the SVG viewBox. The page is zoomable, so these diff --git a/tests/test_pytest_plugin.py b/tests/test_pytest_plugin.py index ec8c0c0..9b6cbe4 100644 --- a/tests/test_pytest_plugin.py +++ b/tests/test_pytest_plugin.py @@ -345,7 +345,13 @@ def test_timeline_flag_does_not_swallow_a_test_path(pytester: pytest.Pytester) - for swallowed in ("test_demo.py", "suite", "test_demo.py::test_flaky"): result = pytester.runpytest_subprocess("--simloop-timeline", swallowed) assert result.ret != 0, swallowed - result.stderr.fnmatch_lines(["*--simloop-timeline=DIR*"]) + result.stderr.fnmatch_lines(["*--simloop-timeline with no value*"]) + # The two spellings are one string by the time the guard sees them, so the + # = form is refused too — which is why the message names the ways out + # instead of telling the user to write the = form. + result = pytester.runpytest_subprocess("--simloop-timeline=suite") + assert result.ret != 0 + result.stderr.fnmatch_lines(["*--simloop-timeline with no value*"]) def test_timeline_flag_accepts_a_directory_holding_no_tests(