diff --git a/docs/session-api.md b/docs/session-api.md index cb94582..c26abb1 100644 --- a/docs/session-api.md +++ b/docs/session-api.md @@ -65,9 +65,98 @@ one. `timeout` is wall-clock effort, not virtual time — assert on | `symbol(name)` | ELF symbol address | | `threads()` / `heap()` | RTOS thread snapshot / heap report, when recognised | +See [Debugging what the firmware is doing](#debugging-what-the-firmware-is-doing) +for the shape of `threads()` and `heap()`, and for the observers the Rust +backend adds beyond this table. + Every observer takes `machine=` in a scenario; the constructor's `machine=` and `uart=` are the defaults. +## Debugging what the firmware is doing + +Everything here is read out of guest memory or out of logs the engine already +fills. Nothing halts the machine, nothing perturbs timing, and no firmware +instrumentation is required — so an assertion made here is an assertion about +the run that actually happened. + +Two rules run through the whole surface, and they are worth stating once: + +- **Layout comes from the image, never from a table in our source.** Struct + offsets are read from the ELF's own DWARF, so a kernel option that moves a + member moves it here too. The alternative — a constant probed once against + one build — reads a neighbouring member on the next build and reports a + plausible number, which is worse than reporting nothing. +- **What the target does not record is reported as `None`, not approximated.** + A missing key is a fact about the build; an invented one is a bug you find + much later. + +### `threads()` — the RTOS thread snapshot + +```python +{"rtos": "Zephyr", + "threads": [{"id": ..., "name": "led1", "state": "ready", "priority": 5, + "core": 0, + "stack": {"base": ..., "sizeBytes": 512, "peakUsedBytes": 128}}], + "truncated": False} +``` + +`None` when no kernel is recognised — a bare-metal image, or one whose symbols +were stripped. + +`truncated` is the adapter's own signal, not a constant. Without the kernel's +all-threads list there is no way to see anything but the thread currently +running, and a one-entry list presented as complete is the worst available +answer. On Zephyr the list needs `CONFIG_THREAD_MONITOR`, names need +`CONFIG_THREAD_NAME`, the published offsets need `CONFIG_DEBUG_THREAD_INFO`, +and `stack.peakUsedBytes` needs `CONFIG_INIT_STACKS` (unpainted stacks have no +high-water mark to find, so the key is present and `None`). A stock build has +none of them — `truncated: True` is the common case, not the exotic one. + +This is one of the clearest places where a simulator beats a probe: on a +no-MMU MCU every thread shares one address space, so trace hardware has no +architectural context to observe and cannot see threads at all. + +### `heap()` — the allocator report + +```python +{"allocator": "Zephyr sys_heap", "arenaSizeBytes": 4180, + "freeBytes": 3820, "usedBytes": 360, + "minimumFreeBytes": 3532, "peakUsedBytes": 648, "regions": 1} +``` + +`None` when no allocator is recognised. Two are: + +| allocator | recognised by | how the numbers are obtained | +| --- | --- | --- | +| `ESP-IDF heap_caps` | `registered_heaps` | walks the registered-region list and reads `multi_heap`'s own counters | +| `Zephyr sys_heap` | `_system_heap` | walks the chunk chain structurally — needs no Kconfig and costs the target nothing | + +The Zephyr walk validates itself: a correct traversal lands *exactly* on the +sentinel the kernel's own accounting loop terminates against. The chunk field +width is a Kconfig predicate that is invisible in the image, so both widths are +tried and only an exact landing is accepted. If neither lands, the heap reads +as unrecognised rather than as a partial sum. + +`minimumFreeBytes` and `peakUsedBytes` are `None` together when the allocator +keeps no low-water mark. ESP-IDF maintains one; Zephyr's chunk chain describes +the heap as it is now and records no history, so the peak is refused rather +than back-computed from current state. `largestFreeBlockBytes` and +`fragmentationRatio` — present on the Renode backend — are absent here rather +than guessed. + +### Rust-backend extras + +No Renode counterpart yet, so these hang off `sim._b` rather than `Sim`: + +| method | returns | +| --- | --- | +| `sim._b.switches()` | `[{t, core, task}]` — the context-switch timeline, from a non-halting watch on the kernel's current-thread pointer | +| `sim._b.task_usage(start, end)` | `[{task, seconds, runs, longestRun}]` over a virtual-time window | +| `sim._b.isr_usage(start, end)` | `{"vectors": [{exception, name, seconds, count, longest, maxDepth}], "threadSeconds": ...}` — works bare-metal too, with no kernel attached | + +`interrupts()` needs no flag on this backend: the exception hook is always on, +so the log is there whether or not `trace_interrupts` was passed. + ## Timing assertions and the quantum Renode delivers scheduled events on sync points, so a timing assertion is only diff --git a/src/simantic/_rust.py b/src/simantic/_rust.py index 0282702..db7b3f9 100644 --- a/src/simantic/_rust.py +++ b/src/simantic/_rust.py @@ -23,6 +23,21 @@ class NotSupported(SimError): """The Rust backend has no implementation of this yet (simantic-core#183).""" +def _vector_name(v: int) -> str: + """Cortex-M exception number to the name a developer recognises. + + Deliberately empty for anything outside the architecturally-defined range + -- on RISC-V `vector` is `mcause`, where the same integers mean something + else entirely, and only the platform knows what IRQ 7 is wired to. An + empty name is the honest answer; a wrong one costs more than none. + """ + fixed = {2: "NMI", 3: "HardFault", 4: "MemManage", 5: "BusFault", 6: "UsageFault", + 11: "SVCall", 12: "DebugMonitor", 14: "PendSV", 15: "SysTick"} + if v in fixed: + return fixed[v] + return f"IRQ{v - 16}" if v >= 16 else "" + + class RustBackend: def __init__(self, machines: list[dict], *, base: Path, media, services, quantum, trace_symbols, trace_interrupts, engine_dir): @@ -30,8 +45,12 @@ def __init__(self, machines: list[dict], *, base: Path, media, services, quantum raise NotSupported("backend='rust' runs one machine; multi-machine scenarios need backend='renode'") if media or services: raise NotSupported("backend='rust' has no media or network services yet (simantic-core#183)") - if trace_symbols or trace_interrupts: - raise NotSupported("backend='rust' has no symbol/interrupt tracing yet (simantic-core#183)") + if trace_symbols: + raise NotSupported("backend='rust' has no symbol tracing yet (simantic-core#183)") + # trace_interrupts needs no flag here: the engine's exception hook is + # always on, so interrupts() is served from the log either way. The + # argument stays accepted so the same test runs on both backends. + self._trace_interrupts = bool(trace_interrupts) m = machines[0] self.machines = [m["name"]] self._elf = (base / m["elf"]).read_bytes() @@ -47,6 +66,9 @@ def __init__(self, machines: list[dict], *, base: Path, media, services, quantum self._records: dict[str, list[dict]] = {k: [] for k in ("uart", "frames", "logs", "interrupts", "symbol_trace")} self._records["logs"] = [{"t": 0.0, "level": "Warning", "source": "platform", "message": w} for w in self._s.warnings()] + # How much of the engine's cumulative ISR log has been turned into + # records already (see _advance). + self._isr_seen = 0 # -- stimulus --------------------------------------------------------- @@ -94,6 +116,18 @@ def _advance(self, seconds: float) -> list[dict]: "text": bytes(data).decode("latin-1")} for t, label, data in self._s.take_uart()] self._records["uart"].extend(fresh) + # The ISR log is cumulative and never drained by reading, so re-slice + # from where we left off rather than re-adding what is already there. + events = self._s.interrupts() + seen = self._isr_seen + if len(events) > seen: + self._records["interrupts"].extend( + {"t": t, "machine": self.machines[0], + "direction": "entry" if entry else "exit", + "exception": vector, "name": _vector_name(vector), "core": core} + for t, core, vector, entry in events[seen:] + ) + self._isr_seen = len(events) return fresh # -- observation ------------------------------------------------------ @@ -119,10 +153,74 @@ def symbol(self, name: str, machine: str | None) -> int: raise SimError(f"no symbol {name!r} in the ELF") from None def threads(self, machine: str | None): - raise NotSupported("backend='rust' has no RTOS thread view through Sim yet (simantic-core#183)") + rtos = self._s.rtos_name() + if rtos is None: + return None + threads = [] + for tid, name, state, priority, core, base, size, peak in self._s.tasks() or (): + t = {"id": tid, "name": name, "state": state, "priority": priority, "core": core} + if size is not None: + # peak is None when the build did not paint stacks; the key is + # still present so a caller can tell "not painted" from "0 + # used", but it is never invented. + t["stack"] = {"base": base, "sizeBytes": size, "peakUsedBytes": peak} + threads.append(t) + # `truncated` is the adapter's own signal, not a constant. Without + # the kernel's all-threads list there is no way to see anything but + # what is currently running, and a one-entry list presented as + # complete is the worst of the three possible answers. + # + # Zephyr needs CONFIG_THREAD_MONITOR for that list to exist (and + # CONFIG_THREAD_NAME for names, CONFIG_DEBUG_THREAD_INFO for the + # published offsets, CONFIG_INIT_STACKS for stack high-water). A + # stock build has none of them, so this is the common case, not the + # exotic one. + return {"rtos": rtos, "threads": threads, + "truncated": not self._s.task_enumeration_available()} def heap(self, machine: str | None): - raise NotSupported("backend='rust' has no heap report through Sim yet (simantic-core#183)") + h = self._s.heap() + if h is None: + return None + allocator, free, minimum_free, pool, regions = h + # Key names match the Renode backend's where the meaning matches. + # largestFreeBlockBytes/fragmentationRatio are deliberately absent + # rather than guessed: this allocator view has no free-list walk, and + # a fabricated fragmentation number is worse than a missing one. + # + # `minimum_free` is None when the allocator keeps no low-water mark to + # read. ESP-IDF's multi_heap maintains one; Zephyr's sys_heap does not + # -- its chunk chain describes the heap as it is now and records no + # history, so a peak is refused rather than approximated from the + # current state. Both keys stay present and go None together, so a + # caller can tell "not tracked" from "nothing used". + peak = None if minimum_free is None else pool - minimum_free + return {"allocator": allocator, "arenaSizeBytes": pool, "freeBytes": free, + "usedBytes": pool - free, "minimumFreeBytes": minimum_free, + "peakUsedBytes": peak, "regions": regions} + + # -- pyrite-only observation ------------------------------------------ + # + # No Renode counterpart, so these are not on `Sim` -- reach them through + # `sim._b`. Both are served from logs the engine already fills, so neither + # halts the machine or perturbs timing. + + def switches(self): + """Context switches as [{"t", "core", "task"}]; empty without a kernel.""" + return [{"t": t, "core": core, "task": task} for t, core, task in self._s.switches()] + + def task_usage(self, start: float = 0.0, end: float | None = None): + """Per-task totals over a window: [{"task", "seconds", "runs", "longestRun"}].""" + return [{"task": tid, "seconds": secs, "runs": runs, "longestRun": longest} + for tid, secs, runs, longest in self._s.task_usage(start, end)] + + def isr_usage(self, start: float = 0.0, end: float | None = None): + """Per-vector totals plus thread-mode time, over a window.""" + rows, thread_seconds = self._s.isr_usage(start, end) + return {"vectors": [{"exception": v, "name": _vector_name(v), "seconds": secs, + "count": count, "longest": longest, "maxDepth": depth} + for v, secs, count, longest, depth in rows], + "threadSeconds": thread_seconds} def close(self) -> None: self._s = None diff --git a/tests/test_rust_backend.py b/tests/test_rust_backend.py index db45d4a..27feea3 100644 --- a/tests/test_rust_backend.py +++ b/tests/test_rust_backend.py @@ -97,6 +97,57 @@ def inject_gpio(self, p, pin, level): def read_memory(self, addr, n): return bytes(range(n)) + # -- observation: bare metal by default (no kernel, no allocator) -------- + + def rtos_name(self): + return None + + def task_enumeration_available(self): + return False + + def tasks(self): + return None + + def heap(self): + return None + + def switches(self): + return [] + + def task_usage(self, start=0.0, end=None): + return [] + + def interrupts(self): + # (t, core, vector, entry) -- one SysTick entry/exit pair at 1 ms. + return [(0.001, 0, 15, True), (0.0010005, 0, 15, False)] + + def isr_usage(self, start=0.0, end=None): + return ([(15, 5e-07, 1, 5e-07, 1)], self.t - 5e-07) + + +class KernelSession(FakeSession): + """A FakeSession whose image has a kernel, so the task views are live.""" + + def rtos_name(self): + return "FreeRTOS" + + def task_enumeration_available(self): + return True + + def tasks(self): + # (id, name, state, priority, core, base, size, peak) + return [(0x2000_0100, "LED1", "running", 3, 0, 0x2000_8000, 512, 128), + (0x2000_0200, "", "ready", 0, None, 0x2000_9000, 256, None)] + + def switches(self): + return [(0.0005, 0, 0x2000_0100), (0.002, 0, 0x2000_0200)] + + def task_usage(self, start=0.0, end=None): + return [(0x2000_0100, 0.0015, 1, 0.0015), (0x2000_0200, 0.001, 1, 0.001)] + + def heap(self): + return ("ESP-IDF heap_caps", 4000, 3500, 8192, 2) + @pytest.fixture def fake_engine(monkeypatch, tmp_path): @@ -136,10 +187,12 @@ def test_expect_records_and_symbols_on_rust(fake_engine): def test_unsupported_calls_say_so(fake_engine): repl, elf = fake_engine with Sim(elf=elf, repl=repl, uart="usart2", backend="rust") as sim: - with pytest.raises(NotSupported, match="core#183"): - sim.threads() with pytest.raises(NotSupported): sim.inject_can("can1", 0x123, b"\x01") + with pytest.raises(NotSupported): + sim.inject_radio("radio", b"\x01") + with pytest.raises(NotSupported, match="symbol tracing"): + Sim(elf=elf, repl=repl, backend="rust", trace_symbols=["main"]) with pytest.raises(NotSupported, match="one machine"): Sim(scenario={"machines": {"a": {"elf": str(elf), "repl": str(repl)}, "b": {"elf": str(elf), "repl": str(repl)}}}, backend="rust") @@ -216,3 +269,137 @@ def test_records_are_paged_not_returned_whole(fake_engine): with Sim(elf=elf, repl=repl, uart="usart2", backend="rust") as sim: page, cursor, truncated = sim._b.records("uart", 0, 1) assert len(page) <= 1 and cursor <= 1 and isinstance(truncated, bool) + + +# -- observation: the #101 visibility layer, reachable from pytest ------------ + +def test_a_bare_metal_image_reports_no_kernel_rather_than_failing(fake_engine): + """Absence of a kernel is an answer, not an error: `None`, not an exception. + A caller has to be able to tell "no RTOS here" from "an RTOS I could not + read", and only the first is representable as None.""" + repl, elf = fake_engine + with Sim(elf=elf, repl=repl, uart="usart2", backend="rust") as sim: + assert sim.threads() is None + assert sim.heap() is None + assert sim._b.switches() == [] + + +def test_interrupts_are_records_with_the_vector_named(fake_engine): + repl, elf = fake_engine + with Sim(elf=elf, repl=repl, uart="usart2", backend="rust") as sim: + sim.run_for(0.01) + entry, exit_ = sim.interrupts(from_start=True) + assert entry["direction"] == "entry" and exit_["direction"] == "exit" + assert entry["exception"] == 15 and entry["name"] == "SysTick" + assert entry["machine"] == "machine" and entry["core"] == 0 + + +def test_the_isr_log_is_cumulative_and_is_not_re_added_each_advance(fake_engine): + """The engine's ISR log is never drained by reading it, unlike the UART + queue. Re-slicing from a cursor is what keeps a second run_for from + duplicating every record recorded during the first.""" + repl, elf = fake_engine + with Sim(elf=elf, repl=repl, uart="usart2", backend="rust") as sim: + sim.run_for(0.01) + sim.run_for(0.01) + assert len(sim.interrupts(from_start=True)) == 2 + + +def test_tasks_come_through_as_threads(fake_engine, monkeypatch): + repl, elf = fake_engine + monkeypatch.setattr(sys.modules["simantic_rust"], "Session", KernelSession) + with Sim(elf=elf, repl=repl, uart="usart2", backend="rust") as sim: + snap = sim.threads() + assert snap["rtos"] == "FreeRTOS" and snap["truncated"] is False + led1, unnamed = snap["threads"] + assert led1["name"] == "LED1" and led1["state"] == "running" and led1["priority"] == 3 + assert led1["stack"] == {"base": 0x2000_8000, "sizeBytes": 512, "peakUsedBytes": 128} + # A build that compiled names out, and one that did not paint stacks: + # both are real configurations, so neither is invented. + assert unnamed["name"] == "" and unnamed["stack"]["peakUsedBytes"] is None + + +def test_heap_reports_only_what_the_allocator_actually_tells_us(fake_engine, monkeypatch): + """`largestFreeBlockBytes`/`fragmentationRatio` exist on the Renode + backend but not here — this view has no free-list walk. They are absent + rather than guessed.""" + repl, elf = fake_engine + monkeypatch.setattr(sys.modules["simantic_rust"], "Session", KernelSession) + with Sim(elf=elf, repl=repl, uart="usart2", backend="rust") as sim: + h = sim.heap() + assert h["allocator"] == "ESP-IDF heap_caps" + assert h["arenaSizeBytes"] == 8192 and h["freeBytes"] == 4000 + assert h["usedBytes"] == 4192 and h["peakUsedBytes"] == 4692 + assert h["minimumFreeBytes"] == 3500 + assert "largestFreeBlockBytes" not in h + + +def test_the_peak_is_none_when_the_allocator_keeps_no_low_water_mark(fake_engine, monkeypatch): + """Zephyr's `sys_heap` is walked structurally: the chunk chain describes the + heap as it is now and records no history. The peak is refused rather than + approximated from the current state, and it takes `minimumFreeBytes` with + it -- both keys stay present so "not tracked" is distinguishable from 0.""" + repl, elf = fake_engine + + class NoHistory(KernelSession): + def heap(self): + return ("Zephyr sys_heap", 3820, None, 4180, 1) + + monkeypatch.setattr(sys.modules["simantic_rust"], "Session", NoHistory) + with Sim(elf=elf, repl=repl, uart="usart2", backend="rust") as sim: + h = sim.heap() + assert h["allocator"] == "Zephyr sys_heap" + assert h["arenaSizeBytes"] == 4180 and h["freeBytes"] == 3820 + assert h["usedBytes"] == 360 and h["regions"] == 1 + assert h["minimumFreeBytes"] is None and h["peakUsedBytes"] is None + + +def test_switch_and_usage_windows_are_available(fake_engine, monkeypatch): + repl, elf = fake_engine + monkeypatch.setattr(sys.modules["simantic_rust"], "Session", KernelSession) + with Sim(elf=elf, repl=repl, uart="usart2", backend="rust") as sim: + sim.run_for(0.01) + assert [s["task"] for s in sim._b.switches()] == [0x2000_0100, 0x2000_0200] + busiest = sim._b.task_usage()[0] + assert busiest["task"] == 0x2000_0100 and busiest["runs"] == 1 + usage = sim._b.isr_usage() + assert usage["vectors"][0]["name"] == "SysTick" + assert usage["threadSeconds"] > 0 + + +def test_a_riscv_vector_is_not_given_an_arm_name(): + """`vector` is `mcause` on RISC-V, where these integers mean something + else. An empty name is the honest answer; a wrong one costs more.""" + from simantic._rust import _vector_name + + assert _vector_name(15) == "SysTick" + assert _vector_name(16) == "IRQ0" + assert _vector_name(7) == "" + + +class UnenumerableSession(KernelSession): + """A kernel whose all-threads list the build left out -- Zephyr without + CONFIG_THREAD_MONITOR. Only the running thread is ever visible.""" + + def rtos_name(self): + return "Zephyr" + + def task_enumeration_available(self): + return False + + def tasks(self): + return [(0x2000_0080, "", "running", 15, 0, 0x2000_0c40, 320, None)] + + +def test_a_partial_thread_list_is_reported_as_truncated(fake_engine, monkeypatch): + """The failure this guards against is silent, not loud: without + CONFIG_THREAD_MONITOR the adapter can only see the running thread, and a + one-entry list marked complete reads as "this firmware has one thread". + Measured on the irq-timer fixture, three threads had actually run.""" + repl, elf = fake_engine + monkeypatch.setattr(sys.modules["simantic_rust"], "Session", UnenumerableSession) + with Sim(elf=elf, repl=repl, uart="usart2", backend="rust") as sim: + snap = sim.threads() + assert snap["rtos"] == "Zephyr" + assert len(snap["threads"]) == 1 + assert snap["truncated"] is True