Replace the per-slot statistics file with a non-perturbing stage recorder, and bump the libe3 submodule

[Thecave3]

Goal

Replace the current per-slot statistics file with a recorder that does not
perturb what it measures, and decompose the controller's share of the E3 data
path into stages that join the library's own records.

Two problems with the current mechanism

1. It writes on the data path. The per-slot stage CSV opens an ofstream,
   writes a row, and flushes it once per slot, inside the sample handler.
   A synchronous formatted write plus a flush on a per-slot path costs orders of
   magnitude more than the intervals it is trying to record, so the numbers it
   produces include a large and variable contribution from the act of recording
   them.

2. It depends on something that does not exist. The code comments state that
   the downstream send stages "are measured library-side in libe3's
   publisher-stage CSV (--pub-stages-log), joinable by message_id". There is no
   such option in libe3, on any branch. So the send side of the path is
   currently unmeasured, and the CSV that exists stops at the handoff.

Scope

Stage	What
Hook to codelet	already derived from the RAN-side timestamps
Codelet to dispatcher	already derived
Dispatcher to handler	the queue wait, already derived
Shared-memory publish	currently timed inline
E3SM encode	the Service Model payload encoder
Emit / fan-out	the handoff into the library, per subscriber
Everything downstream	owned by libe3, not by this repository

E3SM and E3AP are separate boxes. This repository owns the Service Model
codec. E3AP framing, queuing, encoding and the connector send are the library's,
and are instrumented there. Do not re-time them here; join to them instead.

Mechanism

Use latrec, the per-thread lock-free ring recorder that libe3 ships in
include/libe3/latrec.h: one clock_gettime(CLOCK_MONOTONIC) plus four stores
per stamp into an mmap-backed ring. No syscall, no allocation, no formatting, no
lock, and no I/O on the data path. Conversion to a table happens offline, out of
process, against the mmap'd rings.

A stage block is reserved for this controller in wineslab/libe3#55. Use those
identifiers; do not invent your own.

The recorder is gated by a single runtime environment variable and is off by
default, so the same binary runs traced and untraced. Once it is in, the
--stats-log option and its per-slot flush should go: keeping two recording
mechanisms means one of them is always the one that is wrong.

Work items

• Bump the libe3 submodule. It is currently pinned to a commit from the
  JSON-encoder camelCase change, which predates a large amount of the
  library's current behavior, including several data-quality fixes to the
  transport and teardown paths. Measurements taken against that pin are not
  comparable with anything else. Bump it, and rebuild against current main.
• Replace the per-slot CSV with latrec stamps at the same boundaries.
• Add a stamp at the E3SM encode boundary, distinct from the emit
  boundary.
• Remove the --pub-stages-log references from the comments, and instead
  document that the downstream stages come from the library's own records,
  joined by the message identifier the library already assigns.
• Confirm the join actually works end to end: a controller record and a
  library record for the same indication must be pairable.

Exploration first

Do not assume the code locations beyond what is stated above. Find and record
them back in this issue as file:function for:

1. Where the sample handler is entered and where each currently-derived stage
   boundary sits.
2. Where the Service Model payload is encoded.
3. Where the indication is handed to the library, per subscriber.
4. Where the message identifier that keys the join is available.

Data-taking review (mandatory)

This must be a permanent, flag-gated capability, not a throwaway.

• Confirm no stamp allocates, formats, locks, or writes a file on the sample
  path once the CSV is gone.
• Quantify what the old mechanism was costing: run the same workload with
  the CSV enabled and with latrec enabled, and report both against a clean
  run. This is worth recording, because it tells us how much of the existing
  per-slot numbers were measurement artifact.
• Record the ring sizing used and whether any capture wrapped.

Acceptance

• Merged, with the submodule bumped and the build green against current
  library main.
• The per-slot flushing CSV is removed.
• One captured run produces complete, ordered records for the stages above,
  joinable to the library's records by the message identifier.
• The exploration table (file:function per stage) is filled in above.
• The old-versus-new overhead comparison is recorded here.

Closing paragraph

When this is done, write a closing paragraph here covering: what landed, the
stage identifiers now emitted and where, what the old per-slot CSV was costing,
how the join to the library's records was verified, and anything still open.

[Thecave3]

Closing paragraph

Landed as a draft PR, #5, not a merge — this repository is one of several moving to the shared recorder at once, and the assembled system gets validated together afterwards. CI is green on both build configurations.

What landed. The per-slot flushing CSV is gone: the ofstream, the row write, the per-slot flush(), the --stats-log option and the <fstream> include. In its place the slot handler stamps latrec at the same boundaries, through one header, src/e3sm/l1_kpm/l1_kpm_trace.h, that the recording bench also links — so what CI measures is the code that runs on the radio rather than a copy of it. --latrec-dir replaces --stats-log, but only as placement: whether anything is recorded is decided when libe3 is built, by -DLIBE3_ENABLE_LATREC, which reaches this repository on its own as a PUBLIC compile definition. There is no second flag and no environment gate.

The stage identifiers now emitted, all in E3SMLayer1::on_sample, keyed by slot_publish_seq_:

Box	Segment	Covers
A1	RECORD_BEGIN → PROCESS_BEGIN	gNB hook to slot handler entry
A2	PROCESS_BEGIN → ENCODE_E3SM_BEGIN	the shared-memory publish
A3	ENCODE_E3SM_BEGIN → ENCODE_E3SM_DONE	the E3SM payload encoder
—	ENCODE_E3SM_DONE → WAIT_ENTER	the emit tail over all subscribers — what the CSV called emit_ns

Plus SKIPPED/LATREC_SKIP_ENCODE on encode failure. These are the shared catalog's operation identifiers; there is no per-repo block to use, and component identity comes from the ring role e3controller.l1_kpm (checked against latrec2csv.py's RING_COMPONENTS, so records file under ocudu.csv rather than other.csv — note l1_kpm alone would have misfiled them as OAI's). The E3SM encode boundary is kept distinct from the emit boundary: E3SM is this repository's box, E3AP is the library's.

What the old mechanism cost. Median of 15 batches, 4 antenna ports, interleaved and rotated arms:

Recording one slot	Workstation (native)	CI runner (EPYC 9V45)
the removed per-slot CSV	~1795 ns	~987 ns
latrec	~150 ns	~106 ns
ratio	~12×	~9×

So the CSV cost roughly an order of magnitude more than the stamps — about 2.5% of the ~70 µs of real work a 4-port slot takes. A stamp is ~21–25 ns against a measured 19–24 ns clock read: the clock and almost nothing else. Against real slot work the stamps are not separable from run-to-run noise, and the bench reports that bound rather than a delta it cannot resolve; the untraced leg even measured a negative delta, which is what "inside the resolution" looks like. Compare within a host only: the two CI legs drew different runners and the CSV arm — identical code in both — differs by 44% between them.

Every measurement against the old pin should be discarded, as the issue says. These were all taken against the new one.

Ring sizing. 2^18 records, 8 MiB/thread, 5 records per published slot → about 26 s at 2000 slots/s before wrapping; LATREC_ENTRIES_LOG2_E3CONTROLLER_L1_KPM raises it. No capture wrapped — wrapped=0, lost_records=0 on every run, and CI now fails on a non-zero value, since records lost off the front make any span across the wrap wrong.

No stamp touches the data path. Confirmed by construction (each is one clock read and four stores into an mmap'd ring — no allocation, formatting, lock or I/O) and by the symbol table: an untraced build links no latrec symbols and carries no ring registry. Stated precisely, because the stronger claim is false — an untraced binary does still contain local copies of latrec.h's inline no-op stubs, which are empty; CI asserts on global and undefined symbols instead.

The --pub-stages-log fiction is gone from README.md (both occurrences plus the surrounding prose) and from both e3sm_layer_1.cpp comments. The README now documents the real mechanism.

How the join was verified — and where it stands. The mechanism is verified; the end-to-end run is not. A capture converts through libe3's own latrec2csv.py to 33,576 complete source-leg rows, correctly attributed, no wrap, no timestamp descents, with every aux payload round-tripping and the ENCODE_E3SM_DONE__WAIT_ENTER_us hop column materialising. CI re-checks all of that per run. But no radio traffic has gone through it, so the source→outbound join is not yet demonstrated on real records — that is deliberate and is the hardware phase's job.

Verifying it turned up a genuine libe3 bug worth recording here: ServiceModel::emit_outbound(), the documented Service Model emit path, never stamped the emit boundary, so latrec_ctx_set() was dead on it and origin_seq was never populated. It also silently broke libe3's own shipped sm_simple, whose header advertises itself as the template every producer should follow, and no test caught it because every test emitted via send_indication(). It has since been fixed in libe3, in the emitter itself, along with the symmetric gap on the inbound control path — so this SM uses the documented idiom with no workaround, and its control-action ack became attributable for free.

Still open.

1. The live-radio run. The end-to-end join against a real gNB and dApp, and the three-arm comparison on real traffic. The CSV arm comes from git — build the commit before this one and pass --stats-log; the README carries the three-command recipe.
2. The pin is temporary. It is on feat/latency-tracing (a995d57, 0.1.1), not main, because main has no latrec at all. It must move to main once libe3's latrec PR merges.
3. The dev branch is diverged and unrelated to this work: it carries an unmerged change to src/e3sm/asn/e3sm_layer1.asn (+14/−5) that never reached main. Worth resolving separately before it is forgotten.
4. -DUSE_NATIVE=OFF, which CI uses so numbers stay comparable across runner CPUs, drops the shared-memory publish off its AVX2+F16C fast path onto a scalar fallback that is roughly 17× slower. Harmless for stamp cost, but CI's absolute per-slot totals describe no real deployment. The bench detects this and says so; anyone reading those totals should know why.

[Thecave3]

Closing paragraph (revised — the first one described the wrong base and the wrong A1/A2 mapping)

Landed as a draft PR, #5, against tests/native-memcpy rather than main. CI is green on both build configurations, and the PR is mergeable / clean.

The earlier comment on this issue described work built on main, with A1 and A2 carried as aux payloads rather than recorded as stages. Both of those are superseded; what follows replaces it.

Why the rebase was not mechanical. tests/native-memcpy rewrites the data path this issue is about: the codelet's 733 KB memcpy is gone (descriptor-only, ~64 B), the gNB converts and writes the shared-memory row itself under the default shm.writer: gnb, every CLI flag collapses into one --config <file.yaml>, and the codelet's single timestamp is split into codelet_entry_ts_ns and codelet_ts_ns. So the change was re-derived against the new code.

Most of that helped. Decisively: the branch moves the whole RAN-side chain to CLOCK_MONOTONIC — the gNB hook, jbpf_time_get_ns() and the dispatcher poll — which is latrec's own clock.

What landed. The per-slot flushing CSV is gone from the slot-path SM: the ofstream, the row write, the per-slot flush(), and its config key. In its place the handler stamps latrec through one header, src/e3sm/l1_kpm/l1_kpm_trace.h, which the recording bench also links — so what CI measures is the code that runs on the radio. logging.latrec_dir replaces the old path, but only as placement: whether anything is recorded is decided when libe3 is built, by -DLIBE3_ENABLE_LATREC (./build.sh --latrec), which reaches this repository on its own as a PUBLIC compile definition. There is no second flag and no environment gate.

A1 and A2 are recorded here, and the gNB needs no instrumentation for it. Both of A1's boundaries are already on the wire when a slot arrives, so the controller back-dates them rather than the RAN keeping a ring of its own:

Box	Segment	Covers
A1	RECORD_BEGIN → PROCESS_BEGIN	the data recording: jbpf dispatch, then the cbf16 → fp16 convert and the row write
A2	PROCESS_BEGIN → ENCODE_E3SM_BEGIN	getting it to the Service Model: ring transit, dispatcher poll, queue wait
A3	ENCODE_E3SM_BEGIN → ENCODE_E3SM_DONE	the E3SM payload encoder
—	ENCODE_E3SM_DONE → WAIT_ENTER	the emit tail, over every subscriber

RECORD_BEGIN is stamped at gnb_ts_ns, PROCESS_BEGIN at codelet_ts_ns. Four sub-hops stay recoverable from aux payloads, which keeps jbpf dispatch separable from the data movement and preserves the distinction the entry/exit split was added for. Plus SKIPPED/LATREC_SKIP_ENCODE on encode failure. These are the shared catalog's operation identifiers — there is no per-repo block, and component identity comes from the ring role e3controller.l1_kpm (checked against latrec2csv.py's RING_COMPONENTS; l1_kpm alone would have misfiled records as OAI's). The E3SM encode boundary stays distinct from the emit boundary.

The two comments this issue's follow-up asked about were both wrong. codelet_ts_ns was documented as a "codelet entry timestamp" whose interval with gnb_ts_ns was "jbpf invocation + verifier path overhead". It is stamped last, immediately before jbpf_send_output(); the interval is therefore A1, the data recording itself — the branch's own figures put the convert at ~66 µs of a ~71 µs p50, leaving jbpf dispatch at ~4–5 µs; and there is no runtime verifier cost at all, since the gNB loads through ubpf whose JIT emits no bounds checks and verification is an offline build-time gate. gnb_ts_ns claimed CLOCK_REALTIME in three places and never said what makes it A1 (last symbol, grid complete, before any copy). All fixed.

What the old mechanism cost. Median of 15 batches, net of the loop floor:

Recording one slot	Workstation	CI (EPYC 7763)	Of a 500 µs slot
the removed per-slot CSV	~1840 ns	~1485 ns	0.30–0.37%
latrec, 5 records	~111 ns	~102 ns	0.02%
ratio	~17×	~15×

Per record that is ~20–22 ns against a measured 22–28 ns clock read: the clock and essentially nothing else. Compare within a host, never across one — the two CI legs drew an EPYC 7763 and an Intel Xeon 6973P-C, and the csv arm, identical code in both builds, differed by 2.7×. That arm is the calibration anchor.

Every measurement against the old pin should be discarded, as this issue asks. These are against 22f3918 (0.1.2), a genuine fast-forward this time.

Ring sizing. 2^18 records, 8 MiB/thread, five records per published slot → ~26 s at 2000 slots/s before wrapping; LATREC_ENTRIES_LOG2_E3CONTROLLER_L1_KPM raises it. No capture wrapped — wrapped=0, lost_records=0 on every run, and CI fails on a non-zero value.

No stamp touches the data path. One clock read and four stores into an mmap'd ring — no allocation, formatting, lock or I/O. Confirmed by the symbol table: an untraced build links no latrec symbols and carries no ring registry. Stated precisely, because the stronger claim is build-dependent — the optimiser may leave local copies of the empty inline stubs behind — so CI asserts on global and undefined symbols plus the absence of the ring registry.

Back-dating needed a guard, and it earned its keep immediately. A ring is a single-writer log whose t_ns must ascend, and libe3's reader treats the one permitted descent as the wrap point and silently rotates there. Program order gives a wide margin, but a pipeline stall or several sectors interleaving on one ring would break it — so the floor is enforced per thread and the count reported in latrec_clamped and the shutdown summary. A non-zero count means A1 is understated for that many slots. On its first run the guard caught a defect in the bench itself, which was seeding its synthetic clock from CLOCK_REALTIME while the stamps read CLOCK_MONOTONIC.

How the join was verified — and where it stands. The mechanism is verified; the end-to-end run is not. A capture converts through libe3's own latrec2csv.py to 30,512 complete source-leg rows, correctly attributed, no wrap, no descents, zero clamps, with every aux payload round-tripping and the four sub-hop subtractions consistent. RECORD_BEGIN__PROCESS_BEGIN_us is now non-zero, which is the structural fix. But no radio traffic has gone through it, so the source→outbound join and A1's real magnitude are still unproven — deliberately, that is the hardware phase's job.

Verification was done against libe3 built from the actual pin into a scratch prefix, not /usr/local: this workstation holds an older libe3 there, and trusting it produced two incorrect build claims on the previous revision.

Still open.

1. The live-radio run — the end-to-end join, and A1's actual magnitude (~71 µs expected).
2. The pin is temporary: 22f3918 is on a branch because main has no latrec. It moves to main once that work merges.
3. The legacy eCPRI SM still writes a per-slot flushing stage CSV, under its own config key. Same defect, different data path, out of scope here — it should get the same treatment when that path is next touched.
4. dev is diverged with an unmerged e3sm_layer1.asn change that never reached main. Unrelated, but worth resolving before it is forgotten.
5. libe3 ≥ 0.1.2 surfaces the assigned E3AP message id to a dApp calling send_control/send_report, but not on the Service Model emit path, so origin_seq remains the only cross-component join. Worth revisiting if that ever changes.

[Thecave3]

Correction to the comment above: the PR is now #6, not #5.

#5 was auto-closed when the fork hosting its branch was deleted, and GitHub cannot reopen a PR whose head repository is gone. #6 carries the same commit (5372204), the same 18 files and the same base (tests/native-memcpy) — nothing was lost, and the branch now lives in this repository rather than a fork, so CI runs natively.

Everything else in that comment stands.