SPEC-015 - Observability Formats: Log Records, Trace, Crash Record, Debug Descriptor, Monitors¶

Implementation and release scope: Project status records the implemented subset; roadmap defines release gates. Acceptance of this design does not establish implementation, verification, or support. Reconciled 2026-10-14.

Status: Accepted 2026-10-07 by the project owner (“do all”), with the defaults of §12. Specification work item 14 of the roadmap (07 §3). Requirements: docs/requirements/OBS.md (OBS-001 to 012 restated; new from 013). Builds on: 04 §7 (logging, tracing, flight recorder, descriptor, statistics), 03 §10.2 (crash record); ADR-009, ADR-011, ADR-021, ADR-034; SPEC-002 §10 (latency metrics), SPEC-010 §13 (partition events), SPEC-011 §14 (port contribution), SPEC-013 §8 (the bridge consumes the trace), SPEC-014 §6 (generated trace metadata); 09 §7 (NOLOAD sections and symbol-address identifiers), §9 (embdbg, embread); the trace events named in every earlier specification. Research: R-001 §8: ThreadX’s inlined trace with an object registry, Zephyr’s dictionary logging with strings linked into a DEVNULL region, NuttX’s critmonitor with caller addresses, ChibiOS’s and uC/OS-III’s debugger exports, Hubris’s debugger-centric statics. This specification combines them into one compile-out set with open formats (CTF) and a versioned descriptor, which no kernel in the comparison offers together.

1. Scope and terms¶

Term	Meaning
Log record	One deferred-format log call: an identifier plus raw arguments, decoded on the host from the ELF
Trace event	One fixed-layout kernel event in a CTF stream
Crash record	The fixed-layout record written to retained memory on a fatal fault
Debug descriptor	The versioned, read-only structure every image exports for RTOS-aware tools
Monitor	A worst-case recorder with the program counter of the opener (ADR-034)
Flight recorder	The tail of the trace ring kept in retained memory and copied into the crash record
Transport	How bytes leave the target: UART, SWO/ITM, memory channel read by a probe, USB, retained ring, network

2. Logging¶

2.1 Call sites¶

EMB_LOG_ERR(module, "sensor %u failed: %d", id, status);
EMB_LOG_WRN(module, ...);  EMB_LOG_INF(module, ...);  EMB_LOG_DBG(module, ...);
EMB_LOG_HEXDUMP_DBG(module, buf, len, "rx frame");
EMB_LOG_MODULE_DECLARE(name, CONFIG_EMB_LOG_LEVEL_<NAME>);   /* once per module; compile-time level */

Format strings use a printf subset (%d %i %u %x %X %c %s %p %lld %llu %f and width and precision flags); %s arguments are copied by length (bounded by CONFIG_EMB_LOG_STR_MAX, default 32) because a pointer is meaningless on the host. A call below the module’s compile-time level compiles to nothing; a call below the runtime level (emb_log_set_level(module, level)) returns after one comparison (OBS-002).

2.2 Interning (ADR-009)¶

Each call site targets a static const metadata object (format string, level, module id, file, line, argument type signature) in .emb_log, placed in a NOLOAD dummy region (LOG_STRINGS) by the planned generated script; its address is the identifier (09 §7), avoiding loaded format strings and an identifier table. EmbCC now accepts AVR linker scripts. The tiny plain-text backend remains a footprint/design choice, rather than a missing-script requirement; deferred metadata/linker/debugger integration is not implemented or qualified by that compiler capability (SPEC-012 §10).

2.3 Record format¶

record := id timestamp args
id        : u16 when LOG_STRINGS fits in 64 KB, else u32 (chosen at link time, stated in the ELF note)
timestamp : u32 trace clock ticks (SPEC-015 §3.4), or absent when CONFIG_EMB_LOG_TIMESTAMP=n
args      : raw little-endian values in the order and widths given by the metadata's type signature;
            %s as u8 length + bytes; hexdump as u16 length + bytes

Records are produced into a per-CPU lock-free ring (ISR-safe, OBS-003) with a reservation of the exact record size; when the ring is full the record is dropped and a per-ring drop counter increments; the next successful record is preceded by a dropped(u16 count) record (id 1). Id 0 is reserved for a stream-synchronization marker emitted every CONFIG_EMB_LOG_SYNC_INTERVAL records so that a decoder joining mid-stream resynchronizes.

2.4 Processing and transport¶

A log worker (a system work queue item by default, or a dedicated thread at a configured priority) drains the rings into frames (§7) and hands them to the configured transport; in IMMEDIATE mode (debugging early boot) the call site writes the frame itself. The plain-text backend formats on target with a minimal vsnprintf and the same call sites, for the tiny profile and for a host without the ELF.

2.5 Host decoding¶

tools/logdec reads the ELF (the LOG_STRINGS region’s symbols and their metadata) and a byte stream, and prints text with timestamps, module, level, file and line; embdbg embeds the same decoder; the decoder refuses a stream whose ELF build id does not match the image’s and says so.

M1 does not implement these logging rings or decoders. Before claiming ISR-safe lock-free behavior, specify nested producer reservation, commit/publication order, preemption of an unfinished record, overflow and consumer progress; a per-CPU ring still has thread and nested-ISR producers. Validate record atomicity and decoder recovery, including resets during writes.

3. Tracing (ADR-021)¶

3.1 Event set¶

Every specification named its events; the catalogue lives in hw/trace_events.yaml and the generator emits the enum, the inline emitters, and the CTF metadata (SPEC-014 §6). Classes and their events:

Class	Events
`sched`	`switch(from, to, reason)`, `ready(thread, cause)`, `yield`, `sched_lock`, `sched_unlock(duration)`, `idle_enter`, `idle_exit`
`thread`	`init`, `start`, `exit(code)`, `join`, `suspend`, `resume`, `cancel(delivered)`, `priority(thread, base, eff, cause)`, `destroy`
`wait`	`wait_begin(thread, object, reason, deadline)`, `wait_end(thread, result, blocked_cycles)`, `wake(source, waker, thread, result)`, `requeue`
`sync`	`mutex_lock(contended)`, `mutex_unlock(handed_to)`, `prio_inherit(thread, from, to, cause)`, `pi_depth_exceeded`, `deadlock_detected`, `sem_give(handed)`, `event_set(bits, woken)`, `cond_signal(woken)`
`ipc`	`msgq_send`, `msgq_receive`, `msgq_full_block`, `pipe_write`, `pipe_read`, `pipe_close`, `pool_alloc`, `pool_free`, `pool_transfer`
`notify`	`notify_set(target, bits, woke)`, `notify_wait(mask, mode, result)`, `bind_signal(object, thread, bit)`
`work`	`work_submit(queue, item, result)`, `work_start(latency)`, `work_end(duration)`, `work_cancel(state)`, `dwork_schedule(deadline)`
`time`	`tick`, `timeout_arm`, `timeout_fire`, `timer_expire`, `timer_overrun(count)`, `tickless_sleep(until)`, `tickless_wake(elapsed)`
`irq`	`irq_enter(n)`, `irq_exit(n, switched)`, `irq_lock_max(cycles, pc)` (monitor threshold)
`tp`	`budget_consumed`, `budget_overrun(policy)`, `replenish`, `share_filter(partition, eligible)`, `deadline_miss`
`obj`	`obj_init(type, handle, name)`, `obj_destroy(type, handle, flushed)`, `cap_grant`, `cap_derive`, `cap_delete`, `cap_revoke`, `system_freeze`
`part`	`partition_fault(p, thread, class, code, pc)`, `partition_restart(p, count, duration)`, `partition_suspend`, `partition_resume`, `cap_denied(p, nr, reason)`, `irq_delivered(p, irq)`, `syscall(p, nr, status)` (optional)
`power`	`state_enter(state)`, `state_exit(state, residency)`, `device_suspend`, `device_resume`
`user`	`user_event(id, a, b)`: an application hook with two words

M1 traces every outcome, including immediate returns and misuse that faults, so the differential bridge observes each operation end; bound semaphore notifications to terminated targets are dropped and timer IRQs emit TICK (A19). The complete generated catalogue/ring below is planned.

Event payloads are fixed-size little-endian fields; handles appear as their object index and generation (POINTER model: the pointer), threads as their index, so the decoder maps them to names through the object registry events (obj_init) and the descriptor.

3.2 Emission and storage¶

EMB_TRACE_<event>(...) expands to nothing when the class is compiled out (CONFIG_EMB_TRACE_CLASSES) and otherwise to a runtime class-mask test and a reservation in the per-CPU trace ring; the emitter runs inside the kernel’s critical section where the event is generated and costs a timestamp read plus the field stores. Rings are CTF streams: each ring is divided into packets (default 1 KB) with a CTF packet header (stream id, timestamp begin and end, events_discarded count, content size); overflow drops the oldest packet and increments events_discarded (OBS-005 bounded store).

3.3 Modes¶

Snapshot: the ring is retained in RAM, dumped on demand (emb trace dump through the descriptor’s ring location) or on fault (the flight recorder, §4).
Streaming: the trace worker ships completed packets over the transport; back-pressure drops packets, never blocks the kernel.

3.4 Clock¶

Timestamps are emb_arch_trace_timestamp() (SPEC-011 §14) as a 32-bit value in the event header with the full 64-bit value in each packet header; the CTF metadata declares the clock class with the frequency from the hardware description (SPEC-014) so tools convert to time. On the tiny profile the clock is the kernel tick.

3.5 Tools¶

Babeltrace 2 and Trace Compass read the streams and the generated metadata directly; tools/tracedec converts to Perfetto’s JSON for its viewer and to the bridge’s newline-delimited JSON (SPEC-013 §8); embdbg reads the same streams. Nothing proprietary is needed to be useful (ADR-021).

4. Crash record (03 §10.2)¶

struct emb_crash_record_v1 {
  u32 magic ("EMBC"), u16 version (1), u16 length
  u8  build_id[20], u8 fw_version[8]
  u64 uptime_ticks, u32 reset_reason
  u8  fault_class, u8 fault_code, u8 cpu_id, u8 partition_id
  u16 thread_index, u16 thread_generation
  u32 fault_address, u32 pc, u32 lr_or_ra, u32 sp, u32 stack_base, u32 stack_size
  u8  status_reg_count, u8 gpr_count, u16 flight_event_count
  u32 status_regs[status_reg_count]        /* architecture status registers, layout from the descriptor */
  u32 gprs[gpr_count]
  u8  flight_recorder[...]                 /* the last trace packets, raw CTF */
  u32 crc32
}

Written by embk_fault_dispatch before any recovery action (FLT-001) into .retained (a NOLOAD section in a region with the retained attribute) or, failing that, .noinit SRAM; the small variant for AVR (SPEC-012 §8) is version 2 with 16-bit fields and no registers.
On the next boot the kernel validates magic and CRC and exposes emb_crash_record_get() and emb_crash_record_clear(); an application uploads it for telemetry; tools/crashdec symbolizes pc and the flight recorder with the ELF.
Contained partition faults (SPEC-010 §13) write a 32-byte mini-record ("EMBP", partition, thread, class, code, pc, uptime) into a retained ring of CONFIG_EMB_FAULT_RECORD_RING entries when enabled.
The crash record format is versioned and append-only; decoders accept every version they know.

5. Debug descriptor (ADR-011)¶

A const struct emb_debug_descriptor at the exported symbol emb_debug_descriptor (kept with used), found by tools through the symbol or by scanning for the magic "EMBD":

Section	Contents
header	magic, version, length, kernel version, configuration hash, profile, pointer size, endianness, port name and variant
types	object type tags with names and header offsets (`type_tag`, `lifecycle`, `generation`, `name`, `registry`)
thread	TCB field offsets: `arch.sp`, state, wait state, wait reason, wait queue, wake result, base and effective priority, name, index, generation, partition, owned list head, timeout node, notification bits, statistics block
scheduler	ready structure kind and location, per-CPU state location and field offsets (`current_thread`, `irq_nesting_depth`, `sched_lock_depth`, `reschedule_pending`), priority count, all-threads list head
objects	registry heads per type (`CONFIG_EMB_OBJ_LIST`), handle model, registry or capability table layouts
partitions	partition table location and layout, kstore layouts, capability table layout
rings	trace ring locations, packet size, class mask location; log ring locations; crash record location and version; fault mini-record ring
monitors	monitor block location and layout (§6)
arch	context frame layout (register offsets from the saved stack pointer), fault register layout, interrupt stack bounds (SPEC-011 §14)

Tools (embdbg, an OpenOCD RTOS plugin, pyOCD, probe-rs) implement one generic plugin that reads the descriptor and then enumerates threads, their states and stacks, owned locks, partitions, and dumps rings, independent of the kernel version (OBS-008). The descriptor is also what the HIL runner uses to pull traces and crash records.

6. Monitors and statistics (ADR-034, 04 §7.5)¶

emb_status_t emb_stats_cpu_get(uint8_t cpu, emb_stats_cpu_t *out);          /* utilization, idle residency, irq counts, max critical section */
emb_status_t emb_stats_thread_get(emb_thread_t t, emb_stats_thread_t *out);  /* cpu time, switches, blocked time, stack high-water, deadline misses, budget overruns, max boost */
emb_status_t emb_stats_object_get(emb_handle_t h, emb_stats_object_t *out);  /* contention count, max queue length */
emb_status_t emb_monitor_get(uint8_t category, emb_monitor_t *out);          /* worst cycles, opener pc, count over threshold; categories: IRQ_LOCK, SCHED_LOCK, ISR(vector), THREAD_RUN, WORK_HANDLER */
emb_status_t emb_monitor_set_threshold(uint8_t category, uint32_t cycles, uint8_t action);   /* TRACE | NOTIFY | FAULT */
void         emb_stats_reset(void);

Monitors record the interval length and the program counter of the code that opened it (the return address of emb_irq_lock, emb_sched_lock, the ISR vector, the thread entry, the work handler) in one compare and two stores at the closing point; the threshold action runs at the closing point too (a trace event, K_BUDGET-style notification to the supervisor, or a kernel fault). All statistics compile out with their options (OBS-005 discipline) and are exported through the descriptor.

7. Transports and framing¶

Byte-stream transports (UART, USB CDC, network) carry frames: COBS( channel u8, payload, crc16 ) with a zero delimiter; channels 0 log, 1 trace, 2 crash, 3 shell, 4 to 15 application. Decoders resynchronize on the delimiter.
SWO/ITM carries log on stimulus port 0 and trace on port 1 without framing (the hardware frames).
The memory channel (CONFIG_EMB_MEMCHAN) is a control block at the exported symbol emb_memchan describing up-and-down ring buffers in RAM that a debug probe reads and writes without stopping the target; CONFIG_EMB_MEMCHAN_RTT_COMPAT lays the control block out as SEGGER’s RTT does so that existing probe tooling reads it unchanged, while the native layout stays the documented one.
The retained ring transport keeps log frames in retained memory for upload after a reset.

8. Latency metrics (SPEC-002 §10)¶

The metrics SPEC-002 defines (interrupt latency, critical-section maximum, ISR-to-thread, switch cost) are produced by the monitors of §6 and by the harness’s own instrumentation (R-003 §6); their results carry the metadata record of 05 §4.4 and are published per release.

9. Profiles¶

Profile	Log	Trace	Crash record	Descriptor	Monitors
tiny	plain text over UART; deferred only with a linker script	off (optional `sched` class, tick timestamps)	small v2 in `.noinit`	present, reduced	off
base	deferred, memory channel or UART	snapshot ring, `sched`, `sync`, `irq` by default	v1 in retained or `.noinit`	full	optional
isolated, multicore	deferred; per-partition module ids	streaming or snapshot, all classes	v1 plus partition mini-records	full	on in checked builds
native	deferred to a host pipe, decoded live	streams to the bridge	written to a host file	full	on

10. Host tools¶

tools/logdec, tools/tracedec, tools/crashdec, and tools/descriptor (a Python library reading the descriptor through a probe or a memory dump) ship with the kernel and are what embdbg, the HIL runner, and the benchmark harness use. They refuse mismatched build ids and accept every format version they know.

11. Worked example: a field crash¶

A product in the field hard-faults in a driver. The fault entry writes the v1 record with the last 1 KB of trace into the retained region and reboots. On boot the application reads the record, uploads it. crashdec symbolizes pc to the faulting line, decodes the status registers for the architecture, and renders the flight recorder: the last switches, the ISR that ran, the mutex the thread held, the notification that woke it. Nobody reproduced anything (01 §6).

12. Decisions taken at acceptance (2026-10-07)¶

Log identifiers are symbol addresses in a NOLOAD dummy region; 16-bit ids when the region fits, else 32; record format id timestamp args with typed arguments from the metadata signature and bounded string copies.
Logs and traces live in per-CPU lock-free rings; drops are counted and announced in-band; nothing blocks the kernel.
Trace is CTF with generated metadata from trace_events.yaml; the catalogue of §3.1 is the full target event set; each release emits only events for implemented subsystems and versions its metadata; packets default to 1 KB with events_discarded.
Crash record v1 layout as in §4, append-only versioning, small v2 for AVR, partition mini-records in a retained ring.
The debug descriptor’s sections are those of §5 and it is found by symbol or magic; one generic tool plugin serves every kernel version.
Monitors record worst case with the opener’s program counter and act at the closing point; thresholds choose trace, notify, or fault.
Byte-stream framing is COBS with a channel byte and CRC-16; the memory channel offers an RTT-compatible layout as an option.
The host tools ship in the repository and are the only decoders the project needs.