Skip to content

Record the slot path's stages with latrec instead of a per-slot CSV - #6

Draft
Thecave3 wants to merge 1 commit into
tests/native-memcpyfrom
feat/latrec-stage-recorder
Draft

Record the slot path's stages with latrec instead of a per-slot CSV#6
Thecave3 wants to merge 1 commit into
tests/native-memcpyfrom
feat/latrec-stage-recorder

Conversation

@Thecave3

Copy link
Copy Markdown
Collaborator

Closes #4. Rebased onto tests/native-memcpy.

Supersedes #5, which was auto-closed when the fork hosting its branch was deleted. Same commit, same content — the branch now lives in this repository rather than a fork, so CI runs here natively without needing approval.

Draft on purpose. One of several repositories moving to the shared stage recorder at once; each lands as a draft, and the assembled system gets validated together afterwards. Nothing here has run against a radio — see Not done.

What the rebase changed, and why it was not mechanical

tests/native-memcpy rewrites the data path this change instruments: 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, all CLI flags collapse into one --config <file.yaml>, and the codelet's single timestamp is split into codelet_entry_ts_ns and codelet_ts_ns. So this was re-derived against the new code rather than merged into it.

Most of that helped. In particular 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. That is what makes the A1/A2 mapping below possible; the previous revision of this PR had to carry those timestamps as aux payloads and reconstruct them offline precisely because they were in a different domain.

A1 and A2 are recorded here — the gNB needs no instrumentation

Both of A1's boundaries are already on the wire when a slot arrives, so the controller replays them instead of the RAN keeping a ring of its own:

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

RECORD_BEGIN is back-dated to gnb_ts_ns (last symbol, grid complete, nothing copied) and PROCESS_BEGIN to codelet_ts_ns (just before the codelet submits). Four sub-hops stay recoverable from aux payloads, which keeps jbpf dispatch separable from the data movement and preserves the distinction the branch added the entry/exit split for.

This is a real behavioural change from the previous revision, where A1 measured ≈ 0 by construction because both stamps were issued back-to-back at handler entry.

The ring invariant, and why there is a clamp

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 — a descent produces a plausible-looking capture cut at the wrong offset, not an error. Program order gives a wide margin (the jbpf hook is a synchronous inline call, and A1 is tens of µs against a ≥ 500 µs slot spacing), but a pipeline stall or several sectors interleaving on one ring would break it.

So the floor is enforced per thread rather than assumed, and the count of enforced stamps is reported — in the drop CSV's latrec_clamped column and in the shutdown summary. A non-zero count means A1 is understated for that many slots. That guard immediately earned its keep: it caught a defect in the bench, which was seeding its synthetic clock from CLOCK_REALTIME while the now-stamps read CLOCK_MONOTONIC.

The comments that were wrong

codelet_ts_ns was documented as a "codelet entry timestamp" whose interval with gnb_ts_ns was "jbpf invocation + verifier path overhead". Three errors:

  1. It is stamped last, immediately before jbpf_send_output(), not at entry.
  2. The interval is therefore A1 — the data recording itself, dominated by the convert and the row write. The branch's own measurements put the convert at ~66 µs of a ~71 µs p50, leaving jbpf dispatch at ~4–5 µs.
  3. There is no runtime verifier cost at all: 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 no longer does. It also never said what makes it A1 — last symbol, grid complete, before any copy — so that is now stated.

The rest

  • libe3 pin → 22f3918 (0.1.2), a genuine fast-forward from both the branch's pin and the previous one. latrec.h, tools/*.py, messages/ and all of cmake/ bar the SWIG file are byte-identical, so the stage catalog, ring format and origin_seq join are unchanged. Its message-id work surfaces the assigned 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, and the claim in the docs stands with that qualifier. (Pin the SHA: the branch was force-pushed and a cached ref resolves to an abandoned lineage.)
  • --stats-loglogging.latrec_dir, placement only; recording is decided at build time by --latrec.
  • Drop accounting kept. It is aggregate and throttled to ≤ 1/s, so it was never the thing that perturbed. The branch's codelet_publish_us insight is preserved in the stamps rather than in a CSV.
  • The legacy eCPRI SM keeps its own stage CSV under its own config key. Different data path, out of scope for Replace the per-slot statistics file with a non-perturbing stage recorder, and bump the libe3 submodule #4 — but it has the same per-slot-flush problem and should get the same treatment when that path is next touched.
  • BOOLEAN staging dropped from build.sh. It existed to have libe3 compile asn_DEF_BOOLEAN for Spectrum-ConfigControl; the branch stopped compiling that type, so the staging had nothing left to supply while still aborting the build on any host without asn1c's reference skeletons. Verified nothing references the symbol.
  • Bench is instrumentation-only. The slot-work arm is gone: under writer: gnb the controller moves no slot data, so it measured nothing this process does — and against real work the stamps were never resolvable anyway.

What recording costs

Median of 15 batches, net of the loop floor, -DUSE_NATIVE=OFF:

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 are separate jobs and drew different runners — an EPYC 7763 and an Intel Xeon 6973P-C — where the csv arm, identical code in both builds, differed by 2.7×. That arm is the calibration anchor: when it disagrees, nothing else in those two reports is comparable either. The untraced leg is further apart again because latrec_tnow() compiles to return 0 there, so the bench's per-slot clock read vanishes and the loop floor collapses to ~1 ns.

Verification

Everything below was run against a libe3 built from the actual pin into a scratch prefix, not /usr/local — this workstation's /usr/local holds an older libe3, and trusting it is what let two broken build claims through on the previous revision.

  • Full build green both ways (e3_controller + bench), so the ASN.1 archive is actually linked — a bench-only build cannot catch a missing symbol.
  • A capture converts through libe3's own latrec2csv.py: 30,512 complete source-leg rows, filed under the intended component, wrapped=0, lost_records=0, no timestamp descents, zero clamps.
  • Every aux payload round-trips, and the four sub-hop subtractions are consistent.
  • RECORD_BEGIN__PROCESS_BEGIN_us is now non-zero — the structural fix.
  • Both CI legs green. Untraced builds link no latrec symbols and carry no ring registry. Stated that way deliberately: the stronger "no latrec symbols at all" is build-dependent (the optimiser may leave local copies of the empty inline stubs), so CI asserts on global and undefined symbols plus the absence of the ring registry.
  • The controller starts, links libe3 0.1.2 and prints stage recs: enabled -> <dir>, confirming the YAML → latrec_set_output_dir() path.

Not done

  • No radio run. The end-to-end join against a real gNB and dApp, and A1's actual magnitude (~71 µs expected), are for the hardware phase. The bench validates the mechanism and the cost, not the deployment.
  • The pin is temporary and moves to main once libe3's latrec work merges.

The per-slot stage CSV opened an ofstream, wrote a row and flushed it,
once per slot, inside the sample handler. A synchronous formatted write
plus a flush on the slot path costs far more than the intervals it was
recording, so every number it produced included the cost of producing
it. Measured: ~1840 ns per slot against ~111 ns for the five records
that replace it, or roughly 17x.

It also documented a mechanism that does not exist: README and two
source comments described downstream send stages as joinable through a
libe3 `--pub-stages-log` option. There is no such option in libe3 on
any branch, so the send side was simply unmeasured.

Stamp the same boundaries into latrec instead - one clock read and four
stores into an mmap-backed ring, no syscall, allocation, formatting,
lock or I/O on the slot path. The mapping onto the shared stage catalog
lives in one header, l1_kpm_trace.h, which the handler and the bench
both use, so what CI measures is the code that runs on the radio:

  A1  RECORD_BEGIN -> PROCESS_BEGIN          the data recording
  A2  PROCESS_BEGIN -> ENCODE_E3SM_BEGIN     getting it to the SM
  A3  ENCODE_E3SM_BEGIN -> ENCODE_E3SM_DONE  E3SM encode
      ENCODE_E3SM_DONE -> WAIT_ENTER         the emit tail

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 the slot
arrives: gnb_ts_ns is stamped on the last symbol with the grid complete
and nothing copied, and codelet_ts_ns just before the codelet submits.
So the controller back-dates those two stamps rather than the RAN
keeping a ring of its own. That is sound because the whole chain reads
CLOCK_MONOTONIC now - the hook, jbpf_time_get_ns() and the dispatcher
poll - which is latrec's own clock, so there is no domain conversion.

What still has to hold is the ring's own invariant: a single-writer log
whose t_ns ascends, whose one permitted descent libe3's reader treats as
the wrap point and silently rotates at. Program order gives a wide
margin (the jbpf hook is a synchronous inline call, and A1 is tens of
microseconds against a >=500 us slot spacing), but a pipeline stall or
several sectors interleaving on one ring would break it. So the floor is
enforced per thread and the count of enforced stamps is reported, in the
drop CSV and the shutdown summary - a non-zero count means A1 is
understated for that many slots.

Four sub-hops stay recoverable from aux payloads, which is what keeps
jbpf dispatch separable from the data movement, and preserves the
distinction the codelet's entry/exit timestamp split was added for.

Correct the two timestamp comments. 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, not at entry;
the interval is A1, the data recording itself, dominated by the convert
and the row write; 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 said
CLOCK_REALTIME in three places and no longer is.

Replace the CSV's option with logging.latrec_dir, which is placement
only: whether anything is recorded is decided when libe3 is built, by
-DLIBE3_ENABLE_LATREC (./build.sh --latrec). Keep the throttled
drop-accounting CSV - it is aggregate and <=1/s, so it is not the thing
that perturbed. The legacy eCPRI SM keeps its own stage CSV under its
own key; it is a different data path and has the same problem, to be
fixed when that path is next touched.

Move the libe3 pin to 22f3918 (0.1.2), a fast-forward. Its message-id
work surfaces the assigned 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.

Drop the BOOLEAN skeleton staging from build.sh. It existed to have
libe3 compile asn_DEF_BOOLEAN for Spectrum-ConfigControl; that type is
no longer compiled and nothing references the symbol, so the staging had
nothing left to supply while still aborting the build on any host
without asn1c's reference skeletons.

Add CI, which this repository had none of. It builds both ways, asserts
that an untraced binary links no latrec symbols and carries no ring
registry, runs the recording-cost bench, and converts a capture with
libe3's own tool to check the ring role maps to the intended component,
the source leg is complete, the emit-tail hop column materialises, and
nothing wrapped.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant