eta_log (eta v0.1.0)

A deterministic event log, and the thing that makes a failing run readable.

A trace is a scheduler artifact. {step, 8} records which process was chosen and says nothing about what that process did, what it read, or what state anything was in — and the ids are anonymous positions assigned in registration order. Turning one into an explanation means reconstructing every mailbox state by hand, which is a decoder ring rather than a repro.

The schedule tells you what the scheduler did. This is where you define the narrative of your system — nothing here generates a story, you choose what is worth recording and where, and the quality of a failure report follows from those choices. eta_run writes its own decisions into the same log, so there is one ordered timeline rather than two that have to be reconciled:

  12  $eta        {step,8}
  13  reader-6    query_sent
  14  $eta        {step,1}
  15  r2          {applied_write,{1,1}}
  16  r2          {answered_read,{1,1}}
  17  $eta        {step,8}
  18  reader-6    {quorum_max,{1,1}}

What a system under test calls

Not these functions directly. Include the header and use the macros:

-include_lib("eta/include/eta.hrl").

init(Index) ->
    ok = ?ETA_LABEL({replica, Index}),
    {ok, #st{index = Index}}.

handle_cast({read, Ref, From}, St = #st{ts = Ts}) ->
    _ = ?ETA_LOG({answered_read, Ts}),
    ...

Under a release build the macros expand to nothing at all, so the module has no relationship to this library: no call, no table lookup, nothing to pay for and nothing for a release to carry. log/1 below is inert when no collection is running, but inert is not free and still requires eta to be present. The macros are what make it safe to leave instrumentation in the source of something that ships. Same shape as EUnit's TEST.

The functions below are the driver side — collection, correlation and presentation — and are called from tests and shells rather than from a module that ships.

A harness may use either. It never ships, so the macros buy it nothing, and calling label/1 and log/1 directly means a harness can be written in Elixir: the macros are Erlang, and so is eta_transform, so the harness is the one part of a simulated system with that freedom.

Three phases, like `fprof`

eta_run:run(my_harness, #{seed => 3}),   %% 1. collect
eta_log:profile(),                       %% 2. correlate
eta_log:analyze().                       %% 3. present

Collection is on by default during a run (log => false disables it) and can be driven by hand with trace/1 outside one.

The middle phase is not ceremony. Process labels cannot be resolved while a run is in progress: ids are handed out as processes register, and only the harness can name them, with its own state in hand. So the raw log stays dumb — ids and terms, no callbacks on the hot path — and profile/0 does the correlation afterwards, attaching each event to the step it happened inside and finding the boundary where the scheduler handed the system back.

The data outlives the run

Deliberately, and this is the mistake worth not repeating. A log deleted during teardown is unreadable exactly when you want to read it. Like fprof's trace file, what you collect survives until the next collection starts or you call stop/0.

Ordering, and why the counter is shared

Every event takes its sequence number from one ets:update_counter, and anything the harness stamps must take its timestamps from the same place. Two counters mean a violation reporting earlier: {3, 4, ...} that indexes into nothing. One counter means the violation points into the narrative — read the numbers, jump to those lines.

It cannot perturb the schedule

eta_run's own calls happen in the driver process, which the scheduler does not own, so they are safe by construction. Calls from inside a scheduled process are safe too, for a reason worth stating: a step ends when a process blocks in a receive, and an ETS operation never blocks. Observability that changed the schedule would be worse than none, since every failure you then investigated would be a different failure from the one you set out to investigate.

This documentation is LLM-generated. See the AI disclosure in README.md.

Summary

Types

entry()

event()

Functions

analyze()

Renders the profiled timeline to the terminal. See analyze/1.

analyze(Opts)

Renders the profiled timeline.

events()

The raw log, oldest first. profile/0 is usually what you want.

label(Label)

Names the calling process for the log.

log(What)

Records an event and returns its sequence number.

profile()

Correlates the raw log into a timeline: resolves ids to names, attaches every event to the step it happened inside, and marks where the simulation ended.

register_labels(Map)

Records the id-to-name mapping for this run. Called by eta_run at teardown, once ids can finally be joined to names.

running()

Whether a log exists, whether or not it is recording. log/1 returns 0 only when this is false.

self_labels()

Every label a process gave itself this run, as #{pid() => term()}.

seq()

The sequence number of the last event recorded, or 0.

stop()

Discards the collected log. Safe to call when nothing is running.

trace/1

Starts or stops collection. eta_run calls this for you; use it directly when driving eta_sched by hand.

Types

entry()

-type entry() ::
          #{seq := non_neg_integer(),
            label := term(),
            name := binary(),
            what := term(),
            step := non_neg_integer() | undefined,
            simulated := boolean()}.

event()

-type event() :: {non_neg_integer(), term(), term()}.

Functions

analyze()

-spec analyze() -> ok.

Renders the profiled timeline to the terminal. See analyze/1.

analyze(Opts)

-spec analyze(map()) -> ok.

Renders the profiled timeline.

Options:

dest ([]) — [] for the terminal, or a filename.
until (infinity) — stop at this sequence number. Pass the finish stamp from a violation and the output ends exactly where the story does:
```
#{outcome := {violation, #{later := {_Start, Finish, _}}}} = Result,
eta_log:analyze(#{until => Finish}).
```
teardown (false) — include events logged after the scheduler released the system. Off by default because they ran on the real scheduler and are not part of the run.
driver (true) — include eta_run's own step, op and clock entries. Turn it off for a pure account of what the system did.

events()

-spec events() -> [event()].

The raw log, oldest first. profile/0 is usually what you want.

label(Label)

-spec label(term()) -> ok.

Names the calling process for the log.

Call ?ETA_LABEL(Label) rather than this, so a release build strips it. See the module doc.

Kept in the process dictionary, so logging costs nothing at the call sites and no API has to carry a label around. Call it once, wherever the process starts: in a gen_server's init/1, or at the top of whatever an operation spawns.

A label is permanent

The first call wins. A second call with a different label is ignored and warned about, because a label is a property of a process, not of its current state. A replica that becomes leader has not become a different process, and saying so would rewrite the name on every step it took beforehand. Log the transition as an event instead — that is what events are for, and it keeps the before and the after both readable.

It also names the step lines

Registering here is what lets a {step, Id} line carry the same name as the events underneath it. The process cannot know its own scheduler id — it is labelled in init/1, before eta_sched has assigned one — so the pid is recorded and eta_run joins it against the scheduler's id-to-pid map at teardown.

That join is why the self-reported name wins over eta_harness's optional labels/1. Two sources naming one process is how the same process ends up under 2 names in one report, and one of those sources is the process itself. Use labels/1 for the processes that never labelled themselves: something from a library you do not own, or a module you kept the header out of.

log(What)

-spec log(term()) -> non_neg_integer().

Records an event and returns its sequence number.

Call ?ETA_LOG(Event) rather than this from a module that ships; see the module doc. This returns 0 when there is no log at all, and the macro returns 0 when the module was not built for simulation, so the 2 are consistent. Under trace(stamps) the number is real and only the recording is skipped.

Stamp your harness's own timestamps from this return value. An invariant that reports "read A finished at 11, read B started at 12" is only useful if 11 and 12 name lines in this log.

profile()

-spec profile() -> [entry()].

Correlates the raw log into a timeline: resolves ids to names, attaches every event to the step it happened inside, and marks where the simulation ended.

The last part matters more than it sounds. eta_run releases every suspended process before tearing the system down, so anything logged after that point ran on the real scheduler and is not part of the run. It is real, it is nondeterministic, and a reader who does not know that will try to make sense of it.

register_labels(Map)

-spec register_labels(#{non_neg_integer() => term()}) -> ok.

Records the id-to-name mapping for this run. Called by eta_run at teardown, once ids can finally be joined to names.

The plural of label/1 in subject, not in object: label/1 is a process naming itself, this is the finished map for the whole run — every self-reported label plus whatever eta_harness:labels/1 added for the processes that never reported one.

Stored beside the events rather than resolved into them, so the raw log stays a record of facts and naming stays a presentation concern.

running()

-spec running() -> boolean().

Whether a log exists, whether or not it is recording. log/1 returns 0 only when this is false.

self_labels()

-spec self_labels() -> #{pid() => term()}.

Every label a process gave itself this run, as #{pid() => term()}.

eta_run joins this against the scheduler's id-to-pid map; a harness has no reason to call it.

seq()

-spec seq() -> non_neg_integer().

The sequence number of the last event recorded, or 0.

stop()

-spec stop() -> ok.

Discards the collected log. Safe to call when nothing is running.

trace/1

-spec trace(start | stamps | stop) -> ok.

Starts or stops collection. eta_run calls this for you; use it directly when driving eta_sched by hand.

stamps is collection turned off without turning the clock off: log/1 still returns a real, increasing sequence number, it just records nothing. That is what eta_run's log => false uses, and the distinction matters more than it sounds.

A harness is told to stamp its operations from log/1, so that a violation reporting earlier: {8, 11, ...} indexes into the narrative. If switching collection off made those stamps 0, every one of them would compare equal, and an invariant phrased as "this finished before that started" would quietly stop holding — a run that checks nothing, reported as a clean pass. Keeping the counter costs one ETS row.

Starting either way discards whatever was collected before, the same way eta_time:start/0 resets a running clock.

eta_log (eta v0.1.0)

What a system under test calls

Three phases, like fprof

The data outlives the run

Ordering, and why the counter is shared

It cannot perturb the schedule

Summary

Types

Functions

Types

entry()

event()

Functions

analyze()

analyze(Opts)

events()

label(Label)

A label is permanent

It also names the step lines

log(What)

profile()

register_labels(Map)

running()

self_labels()

seq()

stop()

trace/1

Three phases, like `fprof`