diff --git a/.github/workflows/build-and-measure.yml b/.github/workflows/build-and-measure.yml new file mode 100644 index 0000000..50b85a6 --- /dev/null +++ b/.github/workflows/build-and-measure.yml @@ -0,0 +1,201 @@ +# Build the controller both ways, and measure what recording a slot costs. +# +# The matrix leg is the one thing that has to vary: libe3's stage recorder is a +# build-time decision (-DLIBE3_ENABLE_LATREC), carried to us as a PUBLIC compile +# definition, so "traced" and "untraced" are two different binaries rather than +# two run modes. Building both is what stops the untraced path from rotting +# unnoticed - and the untraced leg is the one that proves the stamps really do +# compile away to nothing. +name: build and measure + +on: + push: + branches: [main] + pull_request: + workflow_dispatch: + +permissions: + contents: read + +jobs: + build: + name: build (latrec=${{ matrix.latrec }}) + runs-on: ubuntu-latest + # Cold, this is asn1c-from-source + libe3 + jbpf and its third-party tree + + # the controller. Comfortably inside an hour; nowhere near the 6h default. + timeout-minutes: 60 + strategy: + fail-fast: false + matrix: + latrec: [on, off] + + steps: + - uses: actions/checkout@v4 + with: + # build.sh fetches the submodules itself and then runs jbpf's + # init_and_patch_submodules.sh over them. Letting the checkout action + # do it first would hand that patch script a tree it did not lay out. + submodules: false + + # The libe3 pin decides which asn1c revision is wanted, so it belongs in + # the cache key. hashFiles cannot read a gitlink, and the submodule is not + # checked out yet, so read the pinned SHA straight out of the tree object. + - name: Read the libe3 pin + id: pin + run: echo "sha=$(git rev-parse HEAD:libe3)" >> "$GITHUB_OUTPUT" + + # asn1c is built from the mouse07410 fork, which is minutes of autotools. + # No restore-keys: a stale asn1c is worse than no cache, because it would + # generate against a different grammar than the pinned libe3 expects. + - name: Cache asn1c + id: cache-asn1c + uses: actions/cache@v4 + with: + path: /opt/asn1c + key: asn1c-${{ runner.os }}-${{ steps.pin.outputs.sha }} + + - name: Cache ccache + uses: actions/cache@v4 + with: + path: ~/.ccache + key: ccache-${{ runner.os }}-latrec${{ matrix.latrec }}-${{ github.sha }} + restore-keys: | + ccache-${{ runner.os }}-latrec${{ matrix.latrec }}- + ccache-${{ runner.os }}- + + - name: Install dependencies and build + env: + # -march=native would tune to whatever CPU this runner happens to be, + # which breaks both ccache reuse across heterogeneous runners and any + # comparison of the measurements below between runs. + E3C_CMAKE_ARGS: -DUSE_NATIVE=OFF + run: | + sudo apt-get update + sudo apt-get install -y --no-install-recommends ccache + export PATH="/usr/lib/ccache:${PATH}" + if [ "${{ matrix.latrec }}" = "on" ]; then + ./build.sh --install-deps --latrec + else + ./build.sh --install-deps + fi + + - name: Record the machine the numbers came from + run: | + { + echo "## Environment (latrec=${{ matrix.latrec }})" + echo + echo '```' + grep -m1 'model name' /proc/cpuinfo || true + echo "nproc: $(nproc)" + echo "/dev/shm: $(df -h /dev/shm | tail -1)" + echo "libe3 pin: $(git -C libe3 rev-parse --short HEAD) ($(cat libe3/VERSION))" + echo '```' + } > report.md + + # The claim being tested: with the recorder off, nothing links against the + # recorder runtime. A timing test cannot show that - only the symbol + # table can. + # + # The check is on global and undefined symbols specifically. libe3 only + # compiles src/core/latrec.c when the recorder is on, so a traced binary + # carries `D latrec_tls` plus `T latrec_seq_next` / `latrec_tls_open_as` + # / `latrec_set_output_dir`; an untraced one carries none of them. What + # an untraced binary can still carry is lowercase `t` entries for the + # inline no-op stubs latrec.h substitutes - local copies the optimiser + # did not bother to discard. Those are empty functions, not the + # recorder, and grepping for them would assert something that is not + # true and would fail for the wrong reason. + - name: Assert nothing links the recorder + if: matrix.latrec == 'off' + run: | + status=0 + for binary in out/bin/e3_controller out/bin/bench_stage_recording; do + # Uppercase type letter = global or undefined, i.e. a real link. + if nm -C "$binary" | grep -E ' [A-Z] ' | grep -i latrec; then + echo "::error::$binary links latrec symbols in an untraced build" + status=1 + else + echo "ok: $binary links no latrec symbols" + fi + if nm -C "$binary" | grep -qw latrec_tls; then + echo "::error::$binary carries the latrec ring registry" + status=1 + fi + done + [ "$status" -eq 0 ] || exit 1 + { + echo + echo '## Not linked' + echo + echo 'Neither binary links any latrec symbol, and neither carries the ring' + echo 'registry. Only latrec.h'"'"'s inline no-op stubs remain, as local symbols.' + } >> report.md + + - name: Measure what recording a slot costs + run: | + mkdir -p rings + { + echo + ./out/bin/bench_stage_recording \ + --latrec-dir "$PWD/rings" \ + --csv-path "$PWD/bench_csv_arm.log" + } >> report.md 2>&1 + # The bench fails if any stamp had to be clamped: that would mean its + # synthetic slot times are not ascending, so its latrec arm would be + # exercising the clamp path rather than the one production takes. + + # Converting the capture with libe3's own tool is what checks the parts of + # the contract that live outside this repository: that the ring role maps + # to the component we intend, that the stage ids form a complete source + # leg, and that the emit-tail hop column materialises. A capture that + # wrapped is not a valid measurement, so fail on it. + - name: Convert and validate the capture + if: matrix.latrec == 'on' + run: | + python3 -m pip install --quiet numpy + TOOLS=/usr/local/share/libe3/tools + python3 "$TOOLS/latrec2csv.py" rings | tee convert.log + { + echo + echo '## Capture' + echo + echo '```' + cat convert.log + echo '```' + } >> report.md + + # The role must land in ocudu.csv, not other.csv: latrec2csv maps the + # role prefix through its own table, so a rename here silently + # reattributes every record to an unknown component. + test -f rings/csv/ocudu.csv \ + || { echo "::error::records were not attributed to the ocudu component"; exit 1; } + + # The emit tail replaces the removed CSV's emit_ns, and only exists + # because (ENCODE_E3SM_DONE -> WAIT_ENTER) is a declared extra hop. + head -2 rings/csv/ocudu.csv | grep -q 'ENCODE_E3SM_DONE__WAIT_ENTER_us' \ + || { echo "::error::the emit-tail hop column is missing"; exit 1; } + + python3 - <<'PY' + import csv, sys + with open('rings/csv/rings.csv') as fh: + rows = list(csv.DictReader(fh)) + if not rows: + sys.exit('::error::no rings were written') + for r in rows: + # A wrapped ring has lost records off the front, so any span + # computed across the wrap is wrong. Better to fail than to + # publish a number from a truncated capture. + if r['wrapped'] != '0' or int(r['lost_records'] or 0): + sys.exit(f"::error::{r['ring']} wrapped ({r['lost_records']} lost) " + "- shorten the run or raise LATREC_ENTRIES_LOG2") + print(f"ok: {r['ring']} {r['rec_count']} records, no wrap, " + f"clock {r['clock_ns_per_call']} ns/call") + PY + + - uses: actions/upload-artifact@v4 + with: + name: report-latrec-${{ matrix.latrec }} + path: | + report.md + rings/csv/ + if-no-files-found: warn diff --git a/CMakeLists.txt b/CMakeLists.txt index daa7448..7b7fff8 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -232,3 +232,27 @@ target_link_libraries(e3_controller PRIVATE set_target_properties(e3_controller PROPERTIES RUNTIME_OUTPUT_DIRECTORY "${OUTPUT_DIR}/bin" ) + +# ---- Recording-cost bench ---- +# Prices the stage recorder that replaced the per-slot stats CSV. Deliberately +# minimal: it links the same trace header the slot handler uses and nothing +# else -- no jbpf, no Service Model, no shared-memory writer, no encoders. That +# is enough to measure the recording mechanism, and it keeps the target +# buildable (and CI-runnable) with no RAN attached. +# +# There is no "real slot work" arm to link for: under the default +# shm.writer: gnb the gNB converts and writes the row itself, so the controller +# moves no slot data at all. See bench/bench_stage_recording.cpp. +option(E3C_BUILD_BENCH "Build the stage-recording cost bench" ON) + +if(E3C_BUILD_BENCH) + add_executable(bench_stage_recording bench/bench_stage_recording.cpp) + target_include_directories(bench_stage_recording PRIVATE + ${CMAKE_SOURCE_DIR}/include + ${CMAKE_SOURCE_DIR}/src + ) + target_link_libraries(bench_stage_recording PRIVATE libe3::libe3 pthread rt) + set_target_properties(bench_stage_recording PROPERTIES + RUNTIME_OUTPUT_DIRECTORY "${OUTPUT_DIR}/bin" + ) +endif() diff --git a/README.md b/README.md index ab5c652..bcbfd92 100644 --- a/README.md +++ b/README.md @@ -56,33 +56,49 @@ packages by hand and re-run `./build.sh` without `--install-deps`. Whether or not `--install-deps` was used, `build.sh` then runs: -1. `git submodule update --init --recursive` (fetches libe3 @ tag `0.0.6` and - jbpf). -2. `jbpf/init_and_patch_submodules.sh` to bring in jbpf's third-party - dependencies. +1. `git submodule update --init --recursive` (fetches libe3 and jbpf at their + pinned commits). +2. `jbpf/init_and_patch_submodules.sh` for jbpf's third-party dependencies, then + `apply_jbpf_patches.sh` for the patches to jbpf's own core. 3. Configure + build libe3 with both encoders (`-DLIBE3_ENABLE_ASN1=ON -DLIBE3_ENABLE_JSON=ON -DLIBE3_BUILD_EXAMPLES=OFF - -DLIBE3_BUILD_TESTS=OFF`), stage `asn1c`'s `BOOLEAN.*` skeletons into - `libe3/build/messages/` (toolchain shim — libe3's E3AP grammar does not use - `BOOLEAN` and the `mouse07410` fork skips them, so we supply the reference - copies), then `sudo cmake --install libe3/build` to `/usr/local`. -4. Configure + build the E3Controller; jbpf is compiled in-tree via - `add_subdirectory`. + -DLIBE3_BUILD_TESTS=OFF`), then `sudo cmake --install libe3/build` to + `/usr/local`. +4. Configure + build the E3Controller and the recording-cost bench; jbpf is + compiled in-tree via `add_subdirectory`. `e3.encoding` in the config is therefore a pure runtime choice, because libe3 is built with both encoders. +### `--latrec` + +Builds libe3 with `-DLIBE3_ENABLE_LATREC=ON`, compiling in the stage recorder — +see [Stage records](#stage-records). Off by default, and off is the normal way +to run: libe3 only compiles the recorder in when it is set, so without it the +controller's stamps degrade to `latrec.h`'s inline no-ops and nothing links the +recorder runtime. + +There is only this one flag. `LIBE3_ENABLE_LATREC` is a `PUBLIC` compile +definition on `libe3::libe3`, so a traced libe3 turns the controller's stamps on +by itself — nothing has to be passed twice, and a mismatch between the two is a +link error rather than a silently untraced build. Set `LATREC_DEFAULT_DIR=` +alongside it to change the compiled-in default ring directory (otherwise +`/tmp/latrec`). + +`rm -rf libe3/build` before switching `--latrec` on or off: it changes the +behaviour of an installed public header. + ### Overrides & re-runs - `JOBS=N ./build.sh` — parallelism (defaults to `nproc`). -- `ASN1C_SKELETON_DIR= ./build.sh` — override where `BOOLEAN.*` are - copied from. Default probe order is - `/opt/asn1c/share/asn1c` → `/usr/local/share/asn1c` → `/usr/share/asn1c`. +- `E3C_CMAKE_ARGS='-DUSE_NATIVE=OFF' ./build.sh` — extra configure flags for + the controller. CI passes exactly this: `-march=native` is right on a + deployment host but wrong for a measurement run on a shared runner, where it + makes numbers incomparable between runs. +- `LIBE3_BUILD_TYPE=RelWithDebInfo ./build.sh` — libe3's build type. - If you re-build without `--install-deps` on a host where the earlier run put `asn1c` under `/opt/asn1c/`, the script re-adds `/opt/asn1c/bin` to `PATH` automatically before invoking `cmake`. -- `rm -rf libe3/build` before re-running is enough to force the `BOOLEAN.*` - shim to re-stage; `cmake` picks the rest up incrementally. ### ASN.1 Code Generation @@ -152,7 +168,8 @@ threads: poll_interval_us: 100 # ignored when poll_core >= 0 (busy-poll) logging: - stats_log_path: "" # empty disables the per-slot stage CSV + drops_log_path: "" # empty disables the drop-accounting CSV + latrec_dir: "" # where stage-record rings go; needs --latrec target_slot: -1 # -1 = every UL slot ``` @@ -191,7 +208,7 @@ radio: | `jbpf` | `ipc_name`, `run_path`, `mem_size_bytes`, `lcm_socket_path`, `codelet_base_path` | Must agree with the gNB's own `jbpf:` YAML section | | `e3` | `encoding`, `link_layer`, `transport`, `setup_port`, `publisher_port`, `subscriber_port` | `encoding` is `asn1` or `json`; JSON/cuBB dApps expect ports 5555/5556/5557 | | `threads` | `poll_core`, `worker_core`, `publisher_core`, `poll_interval_us` | `-1` = no pinning (the poll thread then sleeps rather than busy-spinning) | -| `logging` | `stats_log_path` | Empty disables the per-slot stage CSV | +| `logging` | `drops_log_path`, `latrec_dir` | Drop accounting, and where stage-record rings land ([Stage records](#stage-records)) | | *(top level)* | `target_slot` | Forward only this slot index within a 10 ms frame; `-1` forwards every UL slot | #### Who writes the rows (`shm.writer`) @@ -239,14 +256,180 @@ The two directions are not symmetric, which is why the check exists: > `e3.encoding` is a pure runtime choice. If libe3 was built with only one > encoder, it must match, or the outbound encoder rejects every PDU. -#### Timing logs +#### Drop accounting + +Off by default; enabled by setting `logging.drops_log_path`. One cumulative row +per second: `uptime_s, published, dropped_total, latrec_clamped`, then a column +per drop reason. Aggregate and throttled, so it does no work on the slot path. -Off by default; enabled by setting `logging.stats_log_path`. Written by `E3SMLayer1`, one -row per published UL slot: `slot_seq, gnb_to_codelet_us, codelet_to_dispatch_us, -dispatch_to_handler_us, shm_ns, encode_ns, emit_ns, nof_subc, iq_bytes`. +The drop *counters* are always on — the throttled stderr line and the shutdown +summary do not depend on this path. + +Per-slot stage timing is not here; see [Stage records](#stage-records). An example launcher is available [here](start_e3controller_example.sh). +## Stage records + +Where the time goes on the slot path, recorded without perturbing it. + +The controller stamps its own stages into **latrec**, the per-thread lock-free +ring recorder libe3 ships in `libe3/latrec.h`. A stamp is one +`clock_gettime(CLOCK_MONOTONIC)` plus four stores into an mmap-backed ring: no +syscall, no allocation, no formatting, no lock and no I/O on the slot path. +Conversion to tables happens offline, out of process, against the ring files. + +This replaced a per-slot CSV that opened an `ofstream`, wrote a row and flushed +it once per slot inside the sample handler — so the numbers it produced included +the cost of producing them. See [What recording costs](#what-recording-costs). + +Build with `./build.sh --latrec`, then point the rings somewhere with +`logging.latrec_dir`. + +### The stages + +One row per slot, on the forward leg. Box numbering is libe3's +`docs/path-a-e3-loop.md`; the identifiers are the shared catalog's, which names +*operations* rather than components — there is no controller-specific stage +block, and which component performed an operation is read off the ring that +recorded it. + +| Box | Segment | Covers | +|---|---|---| +| A1 | `RECORD_BEGIN` → `PROCESS_BEGIN` | the data recording: jbpf dispatch, then the cbf16 → fp16 convert of the grid and the row write into `/e3_ran_buffers` | +| A2 | `PROCESS_BEGIN` → `ENCODE_E3SM_BEGIN` | getting it to the Service Model: jbpf 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 | + +**A1 and A2 are recorded here, and the gNB needs no instrumentation for it.** +Both of A1's boundaries are already on the wire by the time the slot arrives: +`gnb_ts_ns` is stamped on the last symbol with the resource grid complete and +nothing yet copied, and `codelet_ts_ns` just before the codelet submits. So the +controller replays them rather than the RAN keeping a ring of its own. + +That works because the whole chain reads `CLOCK_MONOTONIC` — the gNB hook, +`jbpf_time_get_ns()` (see `jbpf_patches/jbpf_monotonic_time.patch`) and the +dispatcher poll — which is latrec's own clock. No domain conversion, no offset +arithmetic, no rate skew to absorb. **All of those sites have to agree**; if one +drifts back to `CLOCK_REALTIME` the stage intervals silently mix epochs. + +Four sub-hops stay recoverable from `aux` payloads, which is what keeps jbpf +dispatch separable from the data movement: + +| Sub-hop | Value | +|---|---| +| jbpf dispatch | `RECORD_BEGIN.aux2` − `RECORD_BEGIN` | +| convert + row write | `PROCESS_BEGIN` − `RECORD_BEGIN.aux2` | +| jbpf ring transit | `PROCESS_BEGIN.aux` − `PROCESS_BEGIN` | +| queue wait | `ENCODE_E3SM_BEGIN` − `PROCESS_BEGIN.aux` | + +Everything past the emit boundary — E3AP encode, the outbound queue, the +connector send — is libe3's box and is stamped inside libe3. **E3SM and E3AP are +separate boxes**: the Service Model codec is ours, the E3AP codec is the +library's, and keeping them apart is what makes the library's cost separable +from ours. We do not re-time the library's stages; we join to them. + +Slots that never reach the traced region are not stamped. In particular the "no +subscribers" path returns before the first stamp: that is the normal idle state, +and recording it would fill the ring with slots nobody asked for. A slot whose +encode fails closes its row with `SKIPPED` / `LATREC_SKIP_ENCODE`. + +### Back-dating and the clamp + +A1's boundaries happened before the handler ran, so those two stamps carry times +earlier than the moment they are issued. 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 would not raise an error, it +would produce a plausible capture cut at the wrong offset. + +Ordering normally holds with a wide margin: the jbpf hook is a synchronous +inline call, so slot N's codelet has returned before slot N+1 is stamped, and A1 +is tens of microseconds against a slot spacing of at least 500 µs at 30 kHz SCS. +Two things can still break it — a pipeline stall longer than the slot spacing, +and several RU receive threads (one per sector) whose slots interleave on one +ring. So the floor is enforced rather than assumed, and the count of enforced +stamps is reported in `latrec_clamped` in the drop CSV and in the shutdown +summary. **A non-zero count means A1 is understated for that many slots.** + +### Reading a capture + +```bash +python3 /usr/local/share/libe3/tools/latrec2csv.py +``` + +Records land in `ocudu.csv` — the ring role is `e3controller.l1_kpm`, and +`latrec2csv.py` maps the `e3controller` prefix onto the `ocudu` component. The +hops appear as `RECORD_BEGIN__PROCESS_BEGIN_us` and so on, with the emit tail as +`ENCODE_E3SM_DONE__WAIT_ENTER_us`. + +**Joining to libe3's records.** The controller publishes each slot's record +sequence with `latrec_ctx_set()` immediately before entering the library; libe3 +stamps it into `EMIT_ENTER`'s `aux`, which surfaces as the `origin_seq` column +on the outbound leg. So: + +- `source.seq == outbound.origin_seq` links a slot to its emission. Both legs + are in `ocudu.csv`, because the emit boundary and the enqueue are stamped on + the calling thread — ours. +- That outbound row's `seq` then links into `libe3.csv`, where the library's own + outbound thread stamped `DEQUEUE` → `ENCODE_E3AP_DONE` → `SEND_DONE`. + +Two steps, because the outbound leg is split across the two threads that perform +it. There is no shared message identifier doing this work: E3AP's `message_id` +wraps at 1000, and while libe3 ≥ 0.1.2 surfaces it to a *dApp* calling +`send_control`/`send_report`, it is still not visible on the Service Model emit +path this SM uses. + +### Ring sizing and the capture window + +Rings default to 2^18 records (8 MiB per thread). The slot path writes five +records per published slot, so at 30 kHz SCS with every UL slot forwarded +(~2000 slots/s) a default ring holds about **26 seconds** before it wraps: + +```bash +LATREC_ENTRIES_LOG2_E3CONTROLLER_L1_KPM=24 # 512 MiB, ~28 min; ceiling 2^28 +``` + +The variable is the ring role uppercased with non-alphanumerics replaced by `_`. +It sizes the ring — it does not enable anything. + +**A wrapped capture is not a valid measurement**: records are lost off the front +and any span computed across the wrap is wrong. `rings.csv` reports `wrapped` +and `lost_records` for exactly this reason, and CI fails on a non-zero value. + +### What recording costs + +`out/bin/bench_stage_recording` prices the recorder. It links the same trace +header the slot handler uses and nothing else — no jbpf, no Service Model, no +shared-memory writer — so it runs in CI with no RAN attached. + +There is deliberately no "real slot work" arm: under the default +`shm.writer: gnb` the gNB converts and writes the row itself, so the controller +moves no slot data at all, and against real work the stamps were never +resolvable anyway. + +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 land on whatever runner they get — on one run an EPYC 7763 and an Intel Xeon +6973P-C, where the `csv` arm alone differed by 2.7×. That arm is the calibration +anchor: it is the same code in both builds, so when it disagrees, nothing else +in those two reports is comparable either. + +The untraced leg is further apart still, and for a second reason: with the +recorder off `latrec_tnow()` compiles to `return 0`, so the bench's per-slot +clock read disappears and the loop floor collapses (~1 ns instead of ~30 ns). +Read that leg for the `csv` arm and the not-linked assertion, not for a +comparison against the traced one. + ## Codelets The jbpf codelets are built and verified **in this repository**, under diff --git a/bench/bench_stage_recording.cpp b/bench/bench_stage_recording.cpp new file mode 100644 index 0000000..99bf1ca --- /dev/null +++ b/bench/bench_stage_recording.cpp @@ -0,0 +1,390 @@ +/* + * What does recording a slot cost? + * + * This exists because the mechanism it replaces got the answer wrong. The + * per-slot stage CSV that used to live at the tail of E3SMLayer1::on_sample + * opened an ofstream, wrote a row and *flushed* it, once per slot, on the + * pipeline worker thread - so every number it reported included the cost of + * reporting it. Replacing it is only justified if the replacement is cheap, and + * "cheap" has to be measured rather than asserted. + * + * Three arms, one binary, no slot work: + * + * none the loop and the argument marshalling, nothing else - the floor + * latrec exactly what on_sample now emits per slot, from the same header + * csv the removed writer, reproduced field for field + * + * Deliberately no "real slot work" arm. Under the default `shm.writer: gnb` the + * gNB converts the grid and writes the shared-memory row itself, so the + * controller does no data movement at all - a slot-work arm here would measure + * something this process does not do. And against real work the stamps were + * never resolvable anyway: they are a fraction of a percent of it, so the only + * honest output was a bound. The interesting number lives here, where a + * per-slot write(2) and a handful of stores differ by an order of magnitude and + * separate cleanly. + * + * Method notes that matter for believing the output: + * - Batch timing, not per-iteration. One clock_gettime costs more than a + * latrec stamp, so timing each iteration would measure the timing. + * - Arms are interleaved and rotated across batches, so a runner that slows + * down partway through penalises every arm equally instead of whichever one + * ran last. + * - Median across batches, with min/max, rather than a mean: one descheduled + * batch should not move the answer. + * - The clock's own cost is measured and reported, since it is the floor + * under every latrec stamp. + * + * The `csv` arm is a benchmark reference, not a recording facility: nothing in + * the controller writes a per-slot CSV any more. It is kept so the mechanism + * can still be priced after it is gone. + * + * Build with a libe3 configured -DLIBE3_ENABLE_LATREC=ON, or the latrec arm + * measures the no-op stubs - which is itself worth checking, see --mode + * compiled-out. + */ +#include "e3sm/l1_kpm/l1_kpm_trace.h" + +#include + +#include +#include +#include +#include +#include +#include +#include +#include + +#include + +namespace trace = e3sm_l1kpm_trace; + +namespace { + +using clock_type = std::chrono::steady_clock; + +/* One slot's worth of plausible stage inputs. Values are arbitrary but + * realistic in magnitude, so the CSV arm formats the same number of digits it + * would in production (integer formatting cost scales with digit count). */ +struct SlotFacts { + uint64_t seq; + uint32_t sfn; + uint16_t abs_slot; + /* Absolute times fed to the back-dated stamps. Offsets from `now` are tiny + * on purpose - see slot_facts(). */ + uint64_t gnb_ts_ns; + uint64_t codelet_entry_ts_ns; + uint64_t codelet_ts_ns; + uint64_t dispatch_ts_ns; + uint32_t bytes_written; + uint32_t nof_subc; + std::size_t encoded_bytes; + std::size_t subscribers; +}; + +SlotFacts slot_facts(uint64_t i) +{ + /* The two A1 stamps are back-dated, so they have to ascend across + * iterations or the ring's monotone floor kicks in and we would be timing + * the clamp path instead of the normal one. + * + * In production that is free: slots are >=500 us apart and A1 is ~70 us + * deep, so slot N+1's gnb stamp is comfortably later than slot N's last + * record. This loop iterates ~130 ns apart, so a 70 us back-date could not + * possibly ascend. The offsets below are therefore nanoseconds, not + * microseconds - and that costs nothing in fidelity, because what a stamp + * costs does not depend on the magnitude of the timestamp it carries. It + * depends on the code path, and this is the same one. + * + * The CSV arm does not use these at all; it formats fixed realistic + * durations, so its integer-formatting cost stays representative. */ + const uint64_t now = latrec_tnow(); + SlotFacts f{}; + f.seq = i + 1; + f.sfn = static_cast(i % 1024); + f.abs_slot = static_cast(i % 20); + f.gnb_ts_ns = now - 4; + f.codelet_entry_ts_ns = now - 3; + f.codelet_ts_ns = now - 2; + f.dispatch_ts_ns = now - 1; + f.bytes_written = 733824; + f.nof_subc = 3276; + f.encoded_bytes = 96; + f.subscribers = 1; + return f; +} + +/* ---------------- the three ways of recording a slot ---------------- */ + +/* Arm `none`: the loop and the argument marshalling, nothing else. This is the + * floor the other two are measured against, not zero. */ +void record_none(const SlotFacts& f) +{ + asm volatile("" : : "r"(&f) : "memory"); +} + +/* Arm `latrec`: exactly what E3SMLayer1::on_sample emits per slot - the same + * inline functions, from the same header, in the same order. */ +void record_latrec(const SlotFacts& f) +{ + trace::record_begin(f.seq, f.sfn, f.abs_slot, f.gnb_ts_ns, f.codelet_entry_ts_ns); + trace::process_begin(f.seq, f.codelet_ts_ns, f.dispatch_ts_ns, f.bytes_written); + trace::encode_begin(f.seq, f.bytes_written); + trace::encode_done(f.seq, f.encoded_bytes); + trace::bind_libe3(f.seq); + trace::emit_tail(f.seq, f.subscribers); +} + +/* Arm `csv`: the removed mechanism, reproduced field for field - including the + * saturating subtraction it used, and the flush that is the whole point. */ +class CsvArm { +public: + explicit CsvArm(const std::string& path) : out_(path, std::ios::out | std::ios::trunc) + { + out_ << "slot_seq," + "gnb_to_codelet_us,codelet_publish_us," + "codelet_to_dispatch_us,dispatch_to_handler_us," + "shm_ns,encode_ns,emit_ns,nof_subc,iq_bytes\n"; + } + + bool ok() const { return out_.is_open(); } + + void record(const SlotFacts& f) + { + /* Fixed, realistic stage durations - the measured shape at 30 kHz SCS: + * ~5 us jbpf dispatch, ~66 us convert + row write, then the ring + * transit and the queue wait. Literals rather than differences of + * f's timestamps, because those are nanoseconds apart here (see + * slot_facts) and would format far fewer digits than production. */ + out_ << f.seq << ',' + << 5 << ',' + << 66 << ',' + << 9 << ',' + << 15 << ',' + << 0 << ',' + << 1850 << ',' + << 2400 << ',' + << f.nof_subc << ',' + << f.bytes_written << '\n'; + out_.flush(); // the whole point: one flush per slot, on the data path + } + +private: + std::ofstream out_; +}; + +/* ---------------- statistics ---------------- */ + +struct Summary { + double median_ns; + double min_ns; + double max_ns; +}; + +Summary summarise(std::vector batch_ns_per_iter) +{ + std::sort(batch_ns_per_iter.begin(), batch_ns_per_iter.end()); + Summary s{}; + const std::size_t n = batch_ns_per_iter.size(); + s.median_ns = (n % 2) ? batch_ns_per_iter[n / 2] + : 0.5 * (batch_ns_per_iter[n / 2 - 1] + batch_ns_per_iter[n / 2]); + s.min_ns = batch_ns_per_iter.front(); + s.max_ns = batch_ns_per_iter.back(); + return s; +} + +template +double time_batch_ns_per_iter(Fn&& fn, uint64_t iters, uint64_t& counter) +{ + const auto t0 = clock_type::now(); + for (uint64_t i = 0; i < iters; ++i) { + fn(counter++); + } + const auto t1 = clock_type::now(); + const double total = + static_cast(std::chrono::duration_cast(t1 - t0).count()); + return total / static_cast(iters); +} + +/* Percentage of one slot's budget at 30 kHz SCS. The number that actually + * answers "was the old mechanism a problem?". */ +double pct_of_slot_budget(double ns) { return 100.0 * ns / 500000.0; } + +void print_row(const char* name, const Summary& s) +{ + std::printf("| %-22s | %12.1f | %10.1f | %10.1f | %8.4f%% |\n", + name, s.median_ns, s.min_ns, s.max_ns, pct_of_slot_budget(s.median_ns)); +} + +bool latrec_compiled_in() +{ +#ifdef LIBE3_ENABLE_LATREC + return true; +#else + return false; +#endif +} + +int run_instrumentation(uint64_t iters, uint64_t batches, const std::string& csv_path) +{ + CsvArm csv(csv_path); + if (!csv.ok()) { + std::fprintf(stderr, "cannot open %s for the csv arm\n", csv_path.c_str()); + return 1; + } + + std::vector none_b, latrec_b, csv_b; + uint64_t counter = 0; + + /* Warm up every arm before measuring anything: first-touch page faults on + * the ring mapping and the ofstream buffer would otherwise be charged to + * whichever arm ran first. */ + for (uint64_t i = 0; i < 512; ++i) { + const SlotFacts f = slot_facts(counter++); + record_none(f); + record_latrec(f); + csv.record(f); + } + + for (uint64_t b = 0; b < batches; ++b) { + /* Rotate the order so no arm is permanently first or last. */ + const int order[3] = {static_cast(b % 3), + static_cast((b + 1) % 3), + static_cast((b + 2) % 3)}; + for (int slot = 0; slot < 3; ++slot) { + switch (order[slot]) { + case 0: + none_b.push_back(time_batch_ns_per_iter( + [](uint64_t i) { record_none(slot_facts(i)); }, iters, counter)); + break; + case 1: + latrec_b.push_back(time_batch_ns_per_iter( + [](uint64_t i) { record_latrec(slot_facts(i)); }, iters, counter)); + break; + default: + csv_b.push_back(time_batch_ns_per_iter( + [&csv](uint64_t i) { csv.record(slot_facts(i)); }, iters, counter)); + break; + } + } + } + + std::printf("\n### Recording one slot\n\n"); + std::printf("| %-22s | %12s | %10s | %10s | %9s |\n", + "arm", "median ns", "min ns", "max ns", "of slot"); + std::printf("|------------------------|--------------|------------|------------|-----------|\n"); + const Summary sn = summarise(none_b); + const Summary sl = summarise(latrec_b); + const Summary sc = summarise(csv_b); + print_row("none (loop floor)", sn); + print_row(latrec_compiled_in() ? "latrec (5 records)" : "latrec (STUBS - off)", sl); + print_row("csv (removed)", sc); + + const double latrec_net = sl.median_ns - sn.median_ns; + const double csv_net = sc.median_ns - sn.median_ns; + std::printf("\nNet of the loop floor: latrec %.1f ns/slot, csv %.1f ns/slot.\n", + latrec_net, csv_net); + if (latrec_net > 0.0) { + std::printf("The removed CSV cost %.0fx what the stamps cost.\n", csv_net / latrec_net); + } + std::printf("Clock read (the floor under every stamp): %u ns.\n", + latrec_measure_clock_ns()); + + /* A clamp here would mean the synthetic times did not ascend, i.e. the + * bench is exercising the wrong path and its latrec arm is not comparable + * with production. Report it rather than letting it pass silently. */ + if (const uint64_t clamped = trace::clamped(); clamped != 0) { + std::printf("\nWARNING: %llu stamp(s) were clamped. The synthetic slot times are not\n" + " ascending, so the latrec arm above is not measuring the normal\n" + " path. Treat the number as invalid.\n", + static_cast(clamped)); + return 1; + } + if (!latrec_compiled_in()) { + std::printf("\nNOTE: built without LIBE3_ENABLE_LATREC, so the latrec arm above is\n" + " measuring the no-op stubs, not the recorder.\n"); + } + return 0; +} + +int run_compiled_out() +{ + /* A timing test cannot prove absence - only a build can. This reports what + * the binary was built with so CI can assert on it; the companion check is + * `nm` over a latrec-OFF build finding no global latrec symbols. */ + std::printf("LIBE3_ENABLE_LATREC=%s\n", latrec_compiled_in() ? "ON" : "OFF"); +#ifdef LATREC_DEFAULT_DIR + std::printf("LATREC_DEFAULT_DIR=%s\n", LATREC_DEFAULT_DIR); +#else + std::printf("LATREC_DEFAULT_DIR=(unset)\n"); +#endif + return 0; +} + +void usage(const char* prog) +{ + std::fprintf(stderr, + "Usage: %s [--mode instrumentation|compiled-out|all]\n" + " [--iters N] [--batches K] [--csv-path P] [--latrec-dir D]\n\n" + " --mode which measurement to run (default: all)\n" + " --iters iterations per batch (default: 2000)\n" + " --batches batches per arm (default: 15)\n" + " --csv-path scratch file for the csv arm (default: ./bench_csv_arm.log)\n" + " --latrec-dir where to write stage-record rings\n", prog); +} + +} // namespace + +int main(int argc, char** argv) +{ + std::string mode = "all"; + std::string csv_path = "./bench_csv_arm.log"; + std::string latrec_dir; + uint64_t iters = 2000; + uint64_t batches = 15; + + enum { OPT_MODE = 1000, OPT_ITERS, OPT_BATCHES, OPT_CSV_PATH, OPT_LATREC_DIR }; + static struct option opts[] = { + {"mode", required_argument, nullptr, OPT_MODE}, + {"iters", required_argument, nullptr, OPT_ITERS}, + {"batches", required_argument, nullptr, OPT_BATCHES}, + {"csv-path", required_argument, nullptr, OPT_CSV_PATH}, + {"latrec-dir", required_argument, nullptr, OPT_LATREC_DIR}, + {"help", no_argument, nullptr, 'h'}, + {nullptr, 0, nullptr, 0} + }; + + int o; + while ((o = getopt_long(argc, argv, "h", opts, nullptr)) != -1) { + switch (o) { + case OPT_MODE: mode = optarg; break; + case OPT_ITERS: iters = std::strtoull(optarg, nullptr, 10); break; + case OPT_BATCHES: batches = std::strtoull(optarg, nullptr, 10); break; + case OPT_CSV_PATH: csv_path = optarg; break; + case OPT_LATREC_DIR: latrec_dir = optarg; break; + default: usage(argv[0]); return o == 'h' ? 0 : 2; + } + } + if (mode != "all" && mode != "instrumentation" && mode != "compiled-out") { + usage(argv[0]); + return 2; + } + + if (!latrec_dir.empty()) { + latrec_set_output_dir(latrec_dir.c_str()); + } + /* Single-threaded, so one ring covers every arm. Opened here, before any + * measurement, so the mapping is faulted in off the measured path. */ + trace::open_ring(); + + std::printf("## Stage-recording cost\n"); + std::printf("\nlatrec: %s. Batches: %llu, iterations/batch: %llu.\n", + latrec_compiled_in() ? "compiled in" : "NOT compiled in", + static_cast(batches), + static_cast(iters)); + + int rc = 0; + if (mode == "all" || mode == "compiled-out") rc |= run_compiled_out(); + if (mode == "all" || mode == "instrumentation") rc |= run_instrumentation(iters, batches, csv_path); + return rc; +} diff --git a/build.sh b/build.sh index a78d721..1b1af8e 100755 --- a/build.sh +++ b/build.sh @@ -17,21 +17,33 @@ # then build + INSTALL to /usr/local (both encoders -> runtime --encoding) # 4. build the E3Controller (jbpf is built in-tree via add_subdirectory) # -# Usage: ./build.sh [--install-deps] +# Usage: ./build.sh [--install-deps] [--latrec] # --install-deps Install all system packages before building. Debian/Ubuntu # only (uses apt-get). Uses sudo if not already root. +# --latrec Build libe3 with -DLIBE3_ENABLE_LATREC=ON, so the stage +# recorder is compiled in. Off by default: a normal build has +# no recorder in the process and the controller's own stamps +# compile to nothing. LIBE3_ENABLE_LATREC is a PUBLIC compile +# definition on libe3::libe3, so this one flag reaches the +# controller too -- there is nothing to pass twice, and a +# mismatch is a link error rather than a silently untraced +# build. Set LATREC_DEFAULT_DIR= alongside it to move +# the compiled-in default ring directory off /tmp/latrec. # # Override parallelism with JOBS= ./build.sh. +# Extra configure flags for the controller: E3C_CMAKE_ARGS='-DUSE_NATIVE=OFF'. set -euo pipefail cd "$(dirname "$0")" INSTALL_DEPS=0 +ENABLE_LATREC=0 for arg in "$@"; do case "$arg" in --install-deps|-d) INSTALL_DEPS=1 ;; - -h|--help) sed -n '2,20p' "$0"; exit 0 ;; + --latrec) ENABLE_LATREC=1 ;; + -h|--help) sed -n '2,34p' "$0"; exit 0 ;; *) echo "ERROR: unknown argument '$arg'" >&2 - echo "Usage: $0 [--install-deps]" >&2 + echo "Usage: $0 [--install-deps] [--latrec]" >&2 exit 2 ;; esac done @@ -156,31 +168,34 @@ echo "==> [3/4] Building + installing libe3 (ASN.1 + JSON) to /usr/local" # Overridable for a debug build: LIBE3_BUILD_TYPE=RelWithDebInfo ./build.sh LIBE3_BUILD_TYPE="${LIBE3_BUILD_TYPE:-Release}" echo " libe3 CMAKE_BUILD_TYPE=${LIBE3_BUILD_TYPE}" -cmake -S libe3 -B libe3/build -DCMAKE_BUILD_TYPE="${LIBE3_BUILD_TYPE}" \ - -DLIBE3_ENABLE_ASN1=ON -DLIBE3_ENABLE_JSON=ON \ - -DLIBE3_BUILD_EXAMPLES=OFF -DLIBE3_BUILD_TESTS=OFF - -# --- toolchain shim: supply BOOLEAN.* to libe3's E3AP runtime -------------- -# libe3 0.0.4's messages/asn1/V1/e3ap-1.0.0.cmake hard-lists BOOLEAN.{c,h} and -# BOOLEAN_{aper,print,rfill,uper,xer}.c as asn1c outputs, but its E3AP grammar -# never uses BOOLEAN, so the mouse07410 asn1c fork does NOT emit them and the -# build fails on the missing sources. Rather than patch libe3, drop asn1c's own -# BOOLEAN skeletons into libe3's generated dir before the build (asn1c won't -# overwrite them). libe3 then owns asn_DEF_BOOLEAN; E3Controller links it -# instead of compiling its own (see src/e3sm/asn/CMakeLists.txt). Re-run this -# script after a clean (rm -rf libe3/build) so the copy is re-staged. -BOOLEAN_FILES="BOOLEAN.c BOOLEAN.h BOOLEAN_aper.c BOOLEAN_print.c BOOLEAN_rfill.c BOOLEAN_uper.c BOOLEAN_xer.c" -SKEL="${ASN1C_SKELETON_DIR:-}" -if [ -z "${SKEL}" ]; then - for d in /opt/asn1c/share/asn1c /usr/local/share/asn1c /usr/share/asn1c; do - [ -f "$d/BOOLEAN.c" ] && { SKEL="$d"; break; } - done +LIBE3_CMAKE_ARGS=( + -DCMAKE_BUILD_TYPE="${LIBE3_BUILD_TYPE}" + -DLIBE3_ENABLE_ASN1=ON + -DLIBE3_ENABLE_JSON=ON + -DLIBE3_BUILD_EXAMPLES=OFF + -DLIBE3_BUILD_TESTS=OFF +) +if [ "$ENABLE_LATREC" -eq 1 ]; then + echo " latrec: ON (stage recorder compiled in)" + LIBE3_CMAKE_ARGS+=( -DLIBE3_ENABLE_LATREC=ON ) + # libe3 only defaults LATREC_DEFAULT_DIR into its build tree when it is + # building its own tests, which we turn off -- so without this the compiled-in + # default stays latrec.h's /tmp/latrec. Pass it through when the caller names + # one; logging.latrec_dir in the YAML overrides it per run either way. + if [ -n "${LATREC_DEFAULT_DIR:-}" ]; then + echo " latrec: default ring directory ${LATREC_DEFAULT_DIR}" + LIBE3_CMAKE_ARGS+=( "-DLATREC_DEFAULT_DIR=${LATREC_DEFAULT_DIR}" ) + fi fi -[ -n "${SKEL}" ] || { echo "ERROR: asn1c BOOLEAN skeletons not found; set ASN1C_SKELETON_DIR="; exit 1; } -echo " supplying BOOLEAN skeletons from ${SKEL} -> libe3/build/messages" -mkdir -p libe3/build/messages -for f in ${BOOLEAN_FILES}; do cp "${SKEL}/${f}" libe3/build/messages/; done -# --------------------------------------------------------------------------- +cmake -S libe3 -B libe3/build "${LIBE3_CMAKE_ARGS[@]}" + +# No BOOLEAN.* skeleton staging here. It existed because Spectrum-ConfigControl +# used BOOLEAN while libe3's E3AP grammar did not, so asn1c never emitted the +# skeleton on libe3's side and we staged it there to have libe3 compile it for +# us. Spectrum-ConfigControl is no longer compiled (src/e3sm/asn/CMakeLists.txt) +# and nothing references asn_DEF_BOOLEAN, so the staging had nothing left to +# supply -- while still aborting the build outright on any host without asn1c's +# reference skeletons on disk. cmake --build libe3/build -j"${JOBS}" $SUDO cmake --install libe3/build @@ -189,7 +204,12 @@ $SUDO cmake --install libe3/build # Step 4: E3Controller # --------------------------------------------------------------------------- echo "==> [4/4] Building E3Controller" -cmake -S . -B build -DINITIALIZE_SUBMODULES=OFF -cmake --build build -j"${JOBS}" --target e3_controller +# E3C_CMAKE_ARGS lets a caller add configure flags without editing this script. +# CI sets -DUSE_NATIVE=OFF: -march=native is right on a deployment host but wrong +# for a measurement run on whatever CPU a shared runner happens to be, since it +# makes numbers incomparable between runs. +# shellcheck disable=SC2086 +cmake -S . -B build -DINITIALIZE_SUBMODULES=OFF ${E3C_CMAKE_ARGS:-} +cmake --build build -j"${JOBS}" --target e3_controller bench_stage_recording echo "==> Done: $(pwd)/out/bin/e3_controller" diff --git a/codelets/include/jbpf_e3_slot_api.h b/codelets/include/jbpf_e3_slot_api.h index 1b9a520..e9d08e6 100644 --- a/codelets/include/jbpf_e3_slot_api.h +++ b/codelets/include/jbpf_e3_slot_api.h @@ -125,8 +125,12 @@ struct e3_shm_cfg { * MiB to a couple of KiB and stops being a per-config sizing problem. */ struct e3_slot_desc { - /* gNB hand-off timestamp (CLOCK_REALTIME ns), stamped by the hook caller - * immediately before the hook fires. RAN anchor for end-to-end latency. */ + /* A1 entry: gNB hand-off timestamp, stamped by the hook caller immediately + * before the hook fires - on the last symbol, grid complete, before + * anything has been copied. RAN anchor for end-to-end latency. + * + * CLOCK_MONOTONIC ns, matching jbpf_time_get_ns() (patched) and the + * controller's dispatcher poll, so all three subtract cleanly. */ uint64_t gnb_ts_ns; /* jbpf_time_get_ns() as the FIRST statement of jbpf_main, before any diff --git a/codelets/uplink_slot_samples/uplink_slot_data.h b/codelets/uplink_slot_samples/uplink_slot_data.h index fd4f2a2..4492a4f 100644 --- a/codelets/uplink_slot_samples/uplink_slot_data.h +++ b/codelets/uplink_slot_samples/uplink_slot_data.h @@ -36,21 +36,36 @@ * 4 ports * 14 symbols * 3276 subc * 4 bytes = 733824. */ #define MAX_SLOT_IQ_BYTES 733824 +/* LEGACY. The codelet publishes struct e3_slot_desc (codelets/include/ + * jbpf_e3_slot_api.h), not this. Nothing writes this struct any more; the + * header survives for MAX_SLOT_IQ_BYTES. Kept as the record of the full-IQ + * wire format. + */ struct uplink_slot_sample { - /* gNB-side hand-off timestamp (CLOCK_REALTIME ns) captured by the - * ocudu hook caller, right before the hook fires. This is the RAN - * anchor for end-to-end latency; the dApp subtracts its own - * CLOCK_REALTIME receipt time from it. Same clock domain as - * jbpf_time_get_ns() so codelet_ts_ns below subtracts cleanly. */ + /* A1 entry: the gNB hook caller stamps this immediately before the hook + * fires, on the LAST symbol of the slot, gated on is_valid - so the + * resource grid is complete and nothing has been copied yet. The gNB hands + * the codelet the grid's raw storage pointer and never memcpys it, so this + * is the true "data exists, nothing has moved" instant. + * + * CLOCK_MONOTONIC ns. (The gNB moved off CLOCK_REALTIME; the codelet's + * jbpf_time_get_ns() follows via jbpf_patches/jbpf_monotonic_time.patch, + * and so does the controller's dispatcher poll. All three have to agree or + * the subtractions below silently mix epochs.) */ uint64_t gnb_ts_ns; - /* NOTE: the descriptor path (`writer: gnb`) does not use this struct; it - * publishes struct e3_slot_desc, which carries the entry/exit split. This - * legacy full-IQ struct keeps a single stamp. + /* A1 exit / A2 entry, stamped LAST - just before jbpf_send_output(), after + * the codelet has finished moving the slot's data. Same clock as above. + * + * codelet_ts_ns - gnb_ts_ns = A1, the data recording itself. * - * Codelet entry timestamp (jbpf_time_get_ns(), CLOCK_MONOTONIC ns -- - * see jbpf_patches/jbpf_monotonic_time.patch). Subtract gnb_ts_ns for the - * ocudu hook -> codelet latency. */ + * This is emphatically NOT "hook -> codelet entry latency", and the cost it + * covers is not jbpf plumbing: dispatch is a few microseconds and the data + * movement is tens. Nor is there any verifier cost in it - the gNB loads + * through ubpf, whose JIT emits no bounds checks, and verification is an + * offline build-time gate (see codelets/Makefile). The descriptor path + * splits this into codelet_entry_ts_ns and codelet_ts_ns for exactly that + * reason; this legacy struct keeps the single stamp. */ uint64_t codelet_ts_ns; /* 3GPP slot identification (parsed by the ocudu hook). */ diff --git a/configs/e3_controller.yaml b/configs/e3_controller.yaml index fb05595..0848d78 100644 --- a/configs/e3_controller.yaml +++ b/configs/e3_controller.yaml @@ -174,23 +174,33 @@ threads: poll_interval_us: 100 logging: - # Per-slot RAN-side stage CSV (gnb -> codelet -> dispatch -> handler, plus - # shm/encode/emit costs). Empty disables it. - # - # Setting this also enables the DROP CSV, written alongside as - # _drops -- here /tmp/e3c_stages_drops.csv. - # It carries one cumulative row per second: published, dropped_total, and a - # column per reason (no_subscribers, ran_published_nothing, blob_too_small, - # ...). The drop COUNTERS themselves are always on: the throttled live stderr - # line and the shutdown summary do not depend on this path. - stats_log_path: "/tmp/e3c_stages.csv" + # Throttled drop-accounting CSV. Empty disables it. + # + # One cumulative row per second: uptime, published, dropped_total, + # latrec_clamped, and a column per drop reason (no_subscribers, + # ran_published_nothing, blob_too_small, ...). The drop COUNTERS themselves are + # always on: the throttled live stderr line and the shutdown summary do not + # depend on this path. + # + # This is the only file the L1-KPM SM writes. The per-slot stage CSV that used + # to live here is gone: it opened an ofstream, wrote a row and flushed it once + # per slot inside the sample handler, so the numbers it produced included the + # cost of producing them. Stage timing is latrec's job now. + drops_log_path: "/tmp/e3c_drops.csv" -# --------------------------------------------------------------------------- -# Legacy controller-side single-slot filter: slot index within a 10 ms frame -# (0..slots_per_frame()-1). -1 disables. -# -# Note this drops the slot AFTER the RAN has already converted and published it, -# so it saves the controller work and the RAN nothing. Workstream F's -# codelet-side slot_mask supersedes it by deciding before any data moves. -# --------------------------------------------------------------------------- + # Per-slot stage CSV for the LEGACY eCPRI SM (RF=1) only. Empty disables it. + spectrum_stats_log_path: "" + + # Where latrec writes its per-thread stage-record rings. + # + # PLACEMENT ONLY, not a switch. Whether anything is recorded at all is decided + # when libe3 is built, by -DLIBE3_ENABLE_LATREC (./build.sh --latrec); a normal + # build has no recorder in the process and ignores this. Empty leaves libe3's + # compiled-in default (/tmp/latrec unless the build overrode it). + # + # Rings default to 2^18 records, 8 MiB per thread. The slot path writes five + # records per published slot, so at 2000 slots/s that is ~26 s before the ring + # wraps -- and a wrapped capture is not a valid measurement. Raise it with + # LATREC_ENTRIES_LOG2_E3CONTROLLER_L1_KPM=24 (512 MiB, ~28 min); ceiling 2^28. + latrec_dir: "" target_slot: -1 diff --git a/configs/e3_controller_asn1.yaml b/configs/e3_controller_asn1.yaml index 9ca7ad0..09ae856 100644 --- a/configs/e3_controller_asn1.yaml +++ b/configs/e3_controller_asn1.yaml @@ -186,27 +186,33 @@ threads: poll_interval_us: 100 logging: - # Per-slot RAN-side stage CSV (gnb -> codelet -> dispatch -> handler, plus - # shm/encode/emit costs). Empty disables it. - # - # Setting this also enables the DROP CSV, written alongside as - # _drops -- here /tmp/e3c_stages_drops.csv. - # It carries one cumulative row per second: published, dropped_total, and a - # column per reason (no_subscribers, ran_published_nothing, blob_too_small, - # ...). The drop COUNTERS themselves are always on: the throttled live stderr - # line and the shutdown summary do not depend on this path. - # Distinct from the JSON config's /tmp/e3c_stages.csv ON PURPOSE: the two - # runs would otherwise write the same file and the second would silently - # overwrite the first. The drop CSV follows it automatically as - # /tmp/e3c_stages_asn1_drops.csv. - stats_log_path: "/tmp/e3c_stages_asn1.csv" + # Throttled drop-accounting CSV. Empty disables it. + # + # One cumulative row per second: uptime, published, dropped_total, + # latrec_clamped, and a column per drop reason (no_subscribers, + # ran_published_nothing, blob_too_small, ...). The drop COUNTERS themselves are + # always on: the throttled live stderr line and the shutdown summary do not + # depend on this path. + # + # This is the only file the L1-KPM SM writes. The per-slot stage CSV that used + # to live here is gone: it opened an ofstream, wrote a row and flushed it once + # per slot inside the sample handler, so the numbers it produced included the + # cost of producing them. Stage timing is latrec's job now. + drops_log_path: "/tmp/e3c_drops.csv" -# --------------------------------------------------------------------------- -# Legacy controller-side single-slot filter: slot index within a 10 ms frame -# (0..slots_per_frame()-1). -1 disables. -# -# Note this drops the slot AFTER the RAN has already converted and published it, -# so it saves the controller work and the RAN nothing. Workstream F's -# codelet-side slot_mask supersedes it by deciding before any data moves. -# --------------------------------------------------------------------------- + # Per-slot stage CSV for the LEGACY eCPRI SM (RF=1) only. Empty disables it. + spectrum_stats_log_path: "" + + # Where latrec writes its per-thread stage-record rings. + # + # PLACEMENT ONLY, not a switch. Whether anything is recorded at all is decided + # when libe3 is built, by -DLIBE3_ENABLE_LATREC (./build.sh --latrec); a normal + # build has no recorder in the process and ignores this. Empty leaves libe3's + # compiled-in default (/tmp/latrec unless the build overrode it). + # + # Rings default to 2^18 records, 8 MiB per thread. The slot path writes five + # records per published slot, so at 2000 slots/s that is ~26 s before the ring + # wraps -- and a wrapped capture is not a valid measurement. Raise it with + # LATREC_ENTRIES_LOG2_E3CONTROLLER_L1_KPM=24 (512 MiB, ~28 min); ceiling 2^28. + latrec_dir: "" target_slot: -1 diff --git a/include/e3_config.h b/include/e3_config.h index aeb9985..e2535f0 100644 --- a/include/e3_config.h +++ b/include/e3_config.h @@ -146,7 +146,28 @@ struct ThreadConfig { }; struct LoggingConfig { - std::string stats_log_path; + /* Throttled drop-accounting CSV (<=1 row/s, cumulative). Empty disables it. + * This is the only file the L1-KPM SM writes; per-slot stage timing is + * latrec's job -- see src/e3sm/l1_kpm/l1_kpm_trace.h. */ + std::string drops_log_path; + + /* Per-slot stage CSV for the LEGACY eCPRI Service Model (RF=1) only. + * Empty disables it. + * + * The slot-path SM (RF=2) no longer has one -- see latrec_dir below. This + * one is left as it was: it is on a different data path, and it has the same + * per-slot-flush problem, so it should get the same treatment when that path + * is next touched. */ + std::string spectrum_stats_log_path; + + /* Where latrec writes its per-thread stage-record rings. Empty leaves the + * directory compiled into libe3 (LATREC_DEFAULT_DIR, /tmp/latrec unless the + * build overrode it). + * + * Placement only, NOT a switch: whether anything is recorded is decided + * when libe3 is built, by -DLIBE3_ENABLE_LATREC (./build.sh --latrec). A + * build without it ignores this entirely. */ + std::string latrec_dir; }; struct ControllerConfig { diff --git a/libe3 b/libe3 index 35a3141..22f3918 160000 --- a/libe3 +++ b/libe3 @@ -1 +1 @@ -Subproject commit 35a31410c41cc201c1178c2dc6572415b4728c20 +Subproject commit 22f391842a062546cc1066934afd7a3626d5e0c2 diff --git a/src/e3_config.cpp b/src/e3_config.cpp index 35d8275..076472a 100644 --- a/src/e3_config.cpp +++ b/src/e3_config.cpp @@ -4,6 +4,8 @@ #include "e3_config.h" +#include + #include #include #include @@ -279,10 +281,13 @@ load_config(const std::string& path, ControllerConfig& out, std::string& err) /* ---- logging ---- */ if (const auto n = root["logging"]) { - if (!check_keys(n, "logging", {"stats_log_path"}, err)) { + if (!check_keys(n, "logging", + {"drops_log_path", "spectrum_stats_log_path", "latrec_dir"}, err)) { return false; } - get(n, "stats_log_path", out.logging.stats_log_path); + get(n, "drops_log_path", out.logging.drops_log_path); + get(n, "spectrum_stats_log_path", out.logging.spectrum_stats_log_path); + get(n, "latrec_dir", out.logging.latrec_dir); } get(root, "target_slot", out.target_slot); @@ -353,9 +358,26 @@ print_config(const ControllerConfig& cfg) if (cfg.target_slot >= 0) { std::printf(" target_slot: %d (controller-side filter)\n", cfg.target_slot); } - if (!cfg.logging.stats_log_path.empty()) { - std::printf(" stats log: %s\n", cfg.logging.stats_log_path.c_str()); + if (!cfg.logging.drops_log_path.empty()) { + std::printf(" drop log: %s\n", cfg.logging.drops_log_path.c_str()); + } + /* Three distinguishable states, worth telling apart on startup: not + * compiled in, compiled in and writing where libe3 was built to write, or + * compiled in and redirected. Otherwise "I set latrec_dir and got no rings" + * is indistinguishable from a wrong path. */ +#ifdef LIBE3_ENABLE_LATREC + std::printf(" stage recs: enabled -> %s\n", + cfg.logging.latrec_dir.empty() + ? LATREC_DEFAULT_DIR " (libe3 default)" + : cfg.logging.latrec_dir.c_str()); +#else + if (!cfg.logging.latrec_dir.empty()) { + std::printf(" stage recs: IGNORED (%s): libe3 built without " + "-DLIBE3_ENABLE_LATREC\n", cfg.logging.latrec_dir.c_str()); + } else { + std::printf(" stage recs: not compiled in\n"); } +#endif } bool diff --git a/src/e3_controller.cpp b/src/e3_controller.cpp index 2e229bd..39ed6d9 100644 --- a/src/e3_controller.cpp +++ b/src/e3_controller.cpp @@ -32,6 +32,7 @@ #include #endif #include +#include extern "C" { #include "jbpf_io.h" @@ -232,6 +233,14 @@ int main(int argc, char** argv) std::fprintf(stderr, "[E3Controller] configuration error: %s\n", cfg_err.c_str()); return 1; } + /* Where the stage-record rings go. This has to run before any thread opens + * one: the directory is read at each ring open, and both libe3's agent + * threads and our own pipeline worker open theirs as they start up. A no-op + * in a build without the recorder, so it is unconditional. */ + if (!config.logging.latrec_dir.empty()) { + latrec_set_output_dir(config.logging.latrec_dir.c_str()); + } + e3config::print_config(config); /* The LCM socket is created by the gNB, so its absence usually means the gNB @@ -280,22 +289,10 @@ int main(int argc, char** argv) return e == libe3::EncodingFormat::JSON ? "JSON" : "ASN.1 (APER)"; }; - // Derive the Spectrum SM's stats path from --stats-log by inserting - // "_spectrum" before the extension (or appending it if there's no - // extension). Keeps a single CLI flag while letting both SMs write - // side-by-side without colliding on the same file. Derived here so the - // banner below and the SM registration further down share the value. - std::string spectrum_stats_log_path; - if (!config.logging.stats_log_path.empty()) { - const std::string& p = config.logging.stats_log_path; - auto dot = p.find_last_of('.'); - auto sep = p.find_last_of('/'); - if (dot != std::string::npos && (sep == std::string::npos || dot > sep)) { - spectrum_stats_log_path = p.substr(0, dot) + "_spectrum" + p.substr(dot); - } else { - spectrum_stats_log_path = p + "_spectrum"; - } - } + // Per-slot stage CSV for the legacy eCPRI SM (RF=1) only. Its own config + // key now rather than a suffix derived from the slot-path SM's, because the + // slot-path SM no longer writes one -- see logging.latrec_dir. + const std::string& spectrum_stats_log_path = config.logging.spectrum_stats_log_path; std::cout << "=============================================\n"; std::cout << "E3 Agent Configuration (single-encoding):\n" @@ -306,8 +303,6 @@ int main(int argc, char** argv) << " Channel: setup=" << config.e3.setup_port << " publisher=" << config.e3.publisher_port << " subscriber=" << config.e3.subscriber_port << "\n" - << " Stats log: " - << (config.logging.stats_log_path.empty() ? "(disabled)" : config.logging.stats_log_path) << "\n" << " Spectrum stats: " << (spectrum_stats_log_path.empty() ? "(disabled)" : spectrum_stats_log_path) << "\n\n"; diff --git a/src/e3sm/l1_kpm/e3sm_layer_1.cpp b/src/e3sm/l1_kpm/e3sm_layer_1.cpp index 63c4f38..36fb79b 100644 --- a/src/e3sm/l1_kpm/e3sm_layer_1.cpp +++ b/src/e3sm/l1_kpm/e3sm_layer_1.cpp @@ -14,13 +14,15 @@ #include "e3sm_layer1_wrapper.h" #include "e3sm_layer1_json.h" +#include "l1_kpm_trace.h" #include #include -#include #include #include +namespace trace = e3sm_l1kpm_trace; + /* --------------------------------------------------------------------------- * Drop accounting * @@ -86,26 +88,18 @@ void E3SMLayer1::maybe_log_drops() { static_cast(total), static_cast(published_slots())); - if (stats_log_path_.empty()) { + if (drops_log_path_.empty()) { return; /* counters still maintained; only the CSV is opt-in */ } if (!drops_log_.is_open()) { - /* Sibling of the stage CSV, same convention e3_controller.cpp uses for - * the Spectrum SM's path: insert the suffix before the extension. */ - const std::size_t dot = stats_log_path_.find_last_of('.'); - const std::size_t slash = stats_log_path_.find_last_of('/'); - const bool has_ext = (dot != std::string::npos && - (slash == std::string::npos || dot > slash)); - const std::string path = has_ext - ? stats_log_path_.substr(0, dot) + "_drops" + stats_log_path_.substr(dot) - : stats_log_path_ + "_drops"; - drops_log_.open(path, std::ios::out | std::ios::trunc); + drops_log_.open(drops_log_path_, std::ios::out | std::ios::trunc); if (!drops_log_.is_open()) { - std::fprintf(stderr, "[E3SMLayer1] cannot open drop log %s\n", path.c_str()); - stats_log_path_.clear(); /* do not retry every second */ + std::fprintf(stderr, "[E3SMLayer1] cannot open drop log %s\n", + drops_log_path_.c_str()); + drops_log_path_.clear(); /* do not retry every second */ return; } - drops_log_ << "uptime_s,published,dropped_total"; + drops_log_ << "uptime_s,published,dropped_total,latrec_clamped"; for (std::size_t i = 0; i < kDropCount; ++i) { drops_log_ << ',' << drop_name(static_cast(i)); } @@ -115,11 +109,15 @@ void E3SMLayer1::maybe_log_drops() { const double uptime_s = std::chrono::duration(now - drops_log_start_).count(); - drops_log_ << uptime_s << ',' << published_slots() << ',' << total; + drops_log_ << uptime_s << ',' << published_slots() << ',' << total + << ',' << trace::clamped(); for (std::size_t i = 0; i < kDropCount; ++i) { drops_log_ << ',' << drops_[i].load(std::memory_order_relaxed); } drops_log_ << '\n'; + /* Aggregate and throttled to <=1/s, so this flush is nowhere near the slot + * path -- unlike the per-slot stage CSV this replaced, which flushed once + * per slot from inside the handler. */ drops_log_.flush(); /* a crash mid-run must not lose the accounting */ } @@ -129,6 +127,13 @@ std::string E3SMLayer1::drops_summary() const { std::ostringstream os; os << "[E3SMLayer1] slots published: " << pub << ", dropped: " << total; + /* Capture quality, not a drop: a non-zero count means the ring's ascending + * invariant had to be enforced on that many stamps, so A1 is understated + * for those slots. Worth seeing even on a run that dropped nothing. */ + if (const uint64_t clamped = trace::clamped(); clamped != 0) { + os << "\n latrec stamps clamped: " << clamped + << " (A1 understated for these; see l1_kpm_trace.h)"; + } if (total == 0) { os << " (none)"; return os.str(); @@ -337,24 +342,6 @@ void E3SMLayer1::on_sample(const e3sm_pipeline::SlotSample& s) { } } - using clock = std::chrono::steady_clock; - - // CLOCK_MONOTONIC ns at on_sample entry. Same domain as - // s.gnb_ts_ns / s.codelet_ts_ns / s.dispatch_ts_ns, so the four - // RAN-side stage durations subtract cleanly into statistics_layer1.log. - // - // Was CLOCK_REALTIME; the entire chain moved together. Monotonic matches - // latrec's clock (so stage rows and rings join without an offset) and cannot - // be stepped by NTP mid-run, which is what the saturating subtractions below - // were defending against. - auto realtime_ns_now = []() -> uint64_t { - struct timespec ts; - clock_gettime(CLOCK_MONOTONIC, &ts); - return static_cast(ts.tv_sec) * 1000000000ULL + - static_cast(ts.tv_nsec); - }; - const uint64_t handler_entry_ns = realtime_ns_now(); - // Single encoding: one wire format for every subscriber. const libe3::EncodingFormat enc = agent_ ? agent_->config().encoding : libe3::EncodingFormat::ASN1; @@ -362,30 +349,15 @@ void E3SMLayer1::on_sample(const e3sm_pipeline::SlotSample& s) { if (subs.empty()) { /* Counted, but NOT a fault: before the first dApp subscribes every slot * lands here, so a large no_subscribers count on a healthy run is - * normal and is exactly why the summary breaks reasons out. */ + * normal and is exactly why the summary breaks reasons out. + * + * Checked before the first stage stamp deliberately: this is the SM's + * normal idle state, and stamping it would fill the ring with records + * for slots nobody asked for. */ note_drop(Drop::NoSubscribers); return; // No one is listening; nothing to publish. } - // Publish the slot to /e3_ran_buffers. - // - // In `writer: controller` mode this converts cbf16 -> fp16 inline (the dApp - // expects fp16 on the wire). In `writer: gnb` mode the gNB-side helper has - // already written the row in the PHY RX thread and reported which one, so we - // must NOT write here: both writers keep their own ring cursor and two active - // writers would silently overwrite each other. publish_row_cbf16 hard-refuses - // in that mode; we take the indices the RAN reported instead. - const auto t_shm_start = clock::now(); - uint8_t fh_buf_idx = 0; - uint32_t fh_write_idx = 0; - if (shm_writer_.writes_rows()) { - shm_writer_.publish_row_cbf16(s.iq, ports_clamped, fh_buf_idx, fh_write_idx); - } else { - fh_buf_idx = s.fh_buffer_index; - fh_write_idx = s.fh_write_index; - } - const auto t_shm_end = clock::now(); - // Absolute slot within a 10 ms frame (0..19 at 30 kHz SCS). // // SlotIqPipeline forwards ocudu's slot_point::slot_index() directly @@ -400,10 +372,41 @@ void E3SMLayer1::on_sample(const e3sm_pipeline::SlotSample& s) { // 19 becomes 37 (both invalid). const uint16_t abs_slot = s.slot_id; - // Encode the slot once in the configured wire format. Encoder is + // Everything from here to emit_tail() is one row in the stage records. + // publish_seq keys it, including inside libe3 (see trace::bind_libe3). + const uint64_t publish_seq = + slot_publish_seq_.fetch_add(1, std::memory_order_relaxed) + 1; + + // A1: the data recording, replayed from the two boundaries the slot carries. + // Both stamps are back-dated to when they actually happened - the gNB, the + // codelet and the dispatcher all read CLOCK_MONOTONIC, which is latrec's own + // clock, so there is no conversion and no offset arithmetic. + trace::record_begin(publish_seq, s.sfn, abs_slot, s.gnb_ts_ns, s.codelet_entry_ts_ns); + trace::process_begin(publish_seq, s.codelet_ts_ns, s.dispatch_ts_ns, + (s.bytes_written > 0) ? s.bytes_written : s.iq_size_bytes); + + // Publish the slot to /e3_ran_buffers. + // + // In `writer: controller` mode this converts cbf16 -> fp16 inline (the dApp + // expects fp16 on the wire), and that cost lands inside A2. In `writer: gnb` + // mode the gNB-side helper has already written the row in the PHY RX thread + // and reported which one - that cost is inside A1 - so we must NOT write + // here: both writers keep their own ring cursor and two active writers would + // silently overwrite each other. publish_row_cbf16 hard-refuses in that mode; + // we take the indices the RAN reported instead. + uint8_t fh_buf_idx = 0; + uint32_t fh_write_idx = 0; + if (shm_writer_.writes_rows()) { + shm_writer_.publish_row_cbf16(s.iq, ports_clamped, fh_buf_idx, fh_write_idx); + } else { + fh_buf_idx = s.fh_buffer_index; + fh_write_idx = s.fh_write_index; + } + + // A3: encode the slot once in the configured wire format. Encoder is // O(small); we do it once per slot regardless of subscriber count. const bool want_json = (enc == libe3::EncodingFormat::JSON); - const auto t_encode_start = clock::now(); + trace::encode_begin(publish_seq, s.iq_size_bytes); encoded_buf_.clear(); const bool encoded_ok = want_json ? e3sm_layer1::encode_iq_indication_json( @@ -412,21 +415,25 @@ void E3SMLayer1::on_sample(const e3sm_pipeline::SlotSample& s) { : e3sm_layer1::encode_iq_indication_aper( s.gnb_ts_ns, s.sfn, abs_slot, shm_name_, fh_buf_idx, fh_write_idx, ports_clamped, encoded_buf_); - const uint64_t encode_ns = std::chrono::duration_cast( - clock::now() - t_encode_start).count(); if (!encoded_ok) { std::fprintf(stderr, "[E3SMLayer1] Failed to %s-encode indication (buf=%u row=%u)\n", want_json ? "JSON" : "APER", fh_buf_idx, fh_write_idx); + trace::encode_failed(publish_seq); note_drop(Drop::EncodeFailed); return; } + trace::encode_done(publish_seq, encoded_buf_.size()); + + // Hand off to libe3. Publishing publish_seq first is what lets the library's + // own records - E3AP encode, queuing, the connector send - be attributed back + // to this slot: libe3 stamps it into EMIT_ENTER's aux, which surfaces offline + // as the outbound leg's origin_seq. Everything downstream of here is the + // library's box, measured in the library; we do not re-time it. + trace::bind_libe3(publish_seq); - // Fan out one indication per subscriber. emit_ns here captures the - // SM-side enqueue cost (PDU build + emit_outbound); the encode + ZMQ - // send stages happen downstream in libe3's RAN outbound loop. - const auto t_emit_start = clock::now(); + // Fan out one indication per subscriber. for (uint32_t dapp_id : subs) { libe3::Pdu pdu = make_indication_pdu(dapp_id, RAN_FUNCTION_ID, encoded_buf_); @@ -443,80 +450,7 @@ void E3SMLayer1::on_sample(const e3sm_pipeline::SlotSample& s) { note_drop(Drop::EmitFailed); } } - const auto t_emit_end = clock::now(); - // --- Per-slot statistics (disabled unless --stats-log was given) --- - const uint64_t publish_seq = - slot_publish_seq_.fetch_add(1, std::memory_order_relaxed) + 1; - if (stats_log_path_.empty()) { - return; - } - // Schema: - // slot_seq, - // gnb_to_codelet_us, NOT "hook -> codelet entry". This is - // hook -> END of the codelet, and in `writer: gnb` - // mode that INCLUDES the whole data plane: - // - // gnb_ts_ns clock_gettime(CLOCK_MONOTONIC) taken - // immediately before the hook fires, on - // the last symbol of the slot, i.e. when - // the resource grid is complete - // (upper_phy_rx_symbol_handler_impl.cpp:73) - // ... ubpf JIT dispatch + the codelet's - // bounds-check ladder - // ... jbpf_e3_publish_slot(): the bf16 -> fp16 - // AVX2/F16C convert AND the full - // 733,824-byte row write into - // /e3_ran_buffers - // codelet_ts_ns jbpf_time_get_ns() at the END of the - // codelet (uplink_slot_collect.c:220, - // after the publish call at :174-180) - // - // So read this column as "gNB hook -> the IQ is in - // shared memory", not as jbpf invocation overhead. - // Sanity check: the standalone convert benchmarks at - // 66.5 us for a 4-port slot against a measured p50 of - // ~71 us, so the copy is ~94% of this stage and jbpf - // dispatch is only the remaining ~4-5 us. - // codelet_to_dispatch_us,codelet -> controller dispatcher poll - // dispatch_to_handler_us,dispatcher -> on_sample (SPSC queue wait) - // shm_ns, publish_row_cbf16 cost - // encode_ns, SM payload encoder cost - // emit_ns, emit_outbound fan-out (SM-side enqueue) cost - // nof_subc, iq_bytes slot size (handy if BWP changes) - // - // The three "us" stages are derived from RAN-side CLOCK_MONOTONIC ns - // stamps (gNB -> codelet -> dispatcher -> handler). Because that is also - // latrec's clock, these absolute stamps and the latrec rings can be joined - // directly -- no mono/real offset arithmetic. The post-encode ZMQ-send stage - // lives in libe3's outbound latrec leg (L0..L3). - if (!stats_log_.is_open()) { - stats_log_.open(stats_log_path_, std::ios::out | std::ios::trunc); - stats_log_ << "slot_seq," - "gnb_to_codelet_us,codelet_publish_us," - "codelet_to_dispatch_us,dispatch_to_handler_us," - "shm_ns,encode_ns,emit_ns,nof_subc,iq_bytes\n"; - } - auto ns_between = [](auto a, auto b) { - return std::chrono::duration_cast(b - a).count(); - }; - // Saturating subtractions: the three RAN-side stages are derived - // from absolute realtime stamps. In the (rare) clock-warp case - // they could go negative — clamp to 0 so the CSV row stays parseable. - auto sat_us = [](uint64_t lhs, uint64_t rhs) -> uint64_t { - return (lhs > rhs) ? ((lhs - rhs) / 1000ULL) : 0ULL; - }; - const uint64_t publish_us = - (s.bytes_written > 0) ? sat_us(s.codelet_ts_ns, s.codelet_entry_ts_ns) : 0ULL; - stats_log_ << publish_seq << ',' - << sat_us(s.codelet_entry_ts_ns, s.gnb_ts_ns) << ',' - << publish_us << ',' - << sat_us(s.dispatch_ts_ns, s.codelet_ts_ns) << ',' - << sat_us(handler_entry_ns, s.dispatch_ts_ns) << ',' - << ns_between(t_shm_start, t_shm_end) << ',' - << encode_ns << ',' - << ns_between(t_emit_start, t_emit_end) << ',' - << s.nof_subcarriers << ',' - << s.iq_size_bytes << '\n'; - stats_log_.flush(); + // The emit tail, over all subscribers. + trace::emit_tail(publish_seq, subs.size()); } diff --git a/src/e3sm/l1_kpm/e3sm_layer_1.h b/src/e3sm/l1_kpm/e3sm_layer_1.h index e180a47..1df9edd 100644 --- a/src/e3sm/l1_kpm/e3sm_layer_1.h +++ b/src/e3sm/l1_kpm/e3sm_layer_1.h @@ -47,7 +47,7 @@ class E3SMLayer1 : public libe3::ServiceModel { shm_name_(cfg.shm.name), shm_size_(cfg.shm.size_bytes), target_slot_(cfg.target_slot), - stats_log_path_(cfg.logging.stats_log_path), + drops_log_path_(cfg.logging.drops_log_path), geom_(cfg.radio), cbf16_scale_(cfg.shm.cbf16_scale), writer_mode_(cfg.shm.writer) @@ -107,9 +107,13 @@ class E3SMLayer1 : public libe3::ServiceModel { /* Bump a reason. Also drives the throttled live log line. */ void note_drop(Drop d); - /* Append a cumulative row to , at most once a - * second. Cumulative rather than per-interval so a row is meaningful on its - * own and a missed flush cannot lose events. No-op when stats logging is off. */ + /* Append a cumulative row to drops_log_path_, at most once a second. + * Cumulative rather than per-interval so a row is meaningful on its own and + * a missed flush cannot lose events. No-op when the path is empty. + * + * This is the only file this SM writes. It is aggregate and throttled, so + * unlike the per-slot stage CSV it replaced it does no work on the slot + * path -- stage timing is latrec's job now, see l1_kpm_trace.h. */ void maybe_log_drops(); /* SlotIqPipeline consumer callback (worker thread). Receives one @@ -126,8 +130,8 @@ class E3SMLayer1 : public libe3::ServiceModel { * -1 disables. Superseded by workstream F's codelet-side slot_mask, which * makes the same decision before any data moves. */ int target_slot_; - /* Path for the per-slot stage CSV. Empty disables stats logging. */ - std::string stats_log_path_; + /* Path for the throttled drop-accounting CSV. Empty disables it. */ + std::string drops_log_path_; e3sm_spectrum::ShmIqWriter shm_writer_; bool running_{false}; @@ -154,15 +158,15 @@ class E3SMLayer1 : public libe3::ServiceModel { /* One-shot: controller mode configured but the codelet only sends descriptors. */ bool writer_mode_warned_{false}; - /* Per-slot stats. slot_publish_seq_ increments for every slot - * we publish; counts indications emitted to dApps. stats_log_ is - * opened lazily on the first published slot when stats_log_path_ - * is non-empty. + /* Increments for every slot that reaches the traced region, and keys that + * slot's stage records across the whole E3 path including libe3's own -- it + * is published to the library with latrec_ctx_set() before emitting and + * comes back as the outbound leg's origin_seq. Only meaningful within this + * ring; every producer numbers from 1. * * Atomic because the shutdown summary reads it from the main thread while * on_sample increments it on the worker. */ std::atomic slot_publish_seq_{0}; - std::ofstream stats_log_; /* Drop accounting -- see enum Drop. */ std::atomic drops_[kDropCount]{}; diff --git a/src/e3sm/l1_kpm/l1_kpm_trace.h b/src/e3sm/l1_kpm/l1_kpm_trace.h new file mode 100644 index 0000000..7d65dd5 --- /dev/null +++ b/src/e3sm/l1_kpm/l1_kpm_trace.h @@ -0,0 +1,245 @@ +/* + * Stage stamps for the L1-KPM slot path. + * + * This header owns exactly one thing: how this repository's per-slot path maps + * onto libe3's shared stage catalog (libe3/latrec.h). It is the whole of the + * controller's instrumentation - E3SMLayer1::on_sample calls these and nothing + * else, and the recording bench links this same header, so what CI measures is + * the code that runs on the radio rather than a copy of it. + * + * The catalog names *operations*, not components: the same identifier is used + * wherever that operation is performed, and which component performed it is + * read off the ring that recorded it. So there is no E3Controller-specific + * stage block to use, and inventing one would break every offline tool. + * + * Boxes covered (libe3 docs/path-a-e3-loop.md numbering), all on the forward + * leg: + * + * A1 E3 data recording RECORD_BEGIN -> PROCESS_BEGIN + * A2 Processing PROCESS_BEGIN -> ENCODE_E3SM_BEGIN + * A3 Encode E3SM ENCODE_E3SM_BEGIN -> ENCODE_E3SM_DONE + * - emit tail ENCODE_E3SM_DONE -> WAIT_ENTER + * + * A1 and A2 are recorded HERE, from the timestamps the slot carries, rather + * than by the gNB stamping its own ring. The gNB needs no instrumentation for + * this: gnb_ts_ns marks A1's entry and codelet_ts_ns marks its exit, so both + * boundaries are already on the wire by the time the slot reaches us. + * + * A1 = gnb_ts_ns -> codelet_ts_ns the data recording itself: jbpf + * dispatch, then (writer: gnb) the + * cbf16 -> fp16 convert of the whole grid + * and the row write into /e3_ran_buffers. + * A2 = codelet_ts_ns -> encode getting it to the Service Model: the + * jbpf ring transit, the dispatcher poll + * and the queue wait. + * + * A4 onwards (E3AP encode, queuing, delivery) belong to libe3 and are stamped + * inside the library. E3SM is this repository's box; E3AP is the library's. We + * do not re-time the library's stages, we join to them - see bind_libe3(). + * + * Everything here compiles to nothing when libe3 was built without + * -DLIBE3_ENABLE_LATREC: latrec.h supplies inline no-op stubs, and because + * LIBE3_ENABLE_LATREC is a PUBLIC compile definition on libe3::libe3 there is + * no way for this translation unit to disagree with the library it links. + */ +#ifndef E3_SM_L1KPM_TRACE_H +#define E3_SM_L1KPM_TRACE_H + +#include +#include + +#include +#include +#include + +namespace e3sm_l1kpm_trace { + +/* Ring role for the thread that runs the slot path. + * + * The role is the component's identity: libe3's tools/latrec2csv.py maps the + * role's first segment through its RING_COMPONENTS table to decide which + * per-component CSV the records land in, and `e3controller` is the prefix + * reserved for us (it files under ocudu.csv, alongside the jbpf/gNB capture + * side of the same deployment). Do NOT shorten this to "l1_kpm": that prefix + * is claimed by OAI and the records would be filed as OAI's. A role the table + * does not recognise lands in other.csv. + */ +inline constexpr const char* kRingRole = "e3controller.l1_kpm"; + +/* Open the calling thread's ring. Idempotent, first-open-wins, and it faults + * in the whole mapping - so call it once at the top of the thread's loop, off + * the slot path, and never from on_sample. + * + * Ordering matters: libe3's queue_outbound opens a ring on demand for whatever + * thread emits, as libe3.outbound. Since the slot path emits from this same + * thread, if libe3 got there first the ring would carry libe3's name and every + * record we stamp would be filed as the library's. Opening here, before the + * first emit, is what keeps the component attribution correct. + */ +inline void open_ring() +{ + latrec_tls_open_as(kRingRole); +} + +#ifdef LIBE3_ENABLE_LATREC + +/* Monotone floor for this thread's ring, and how often we had to enforce it. + * + * A1's boundaries happened before we were called, so RECORD_BEGIN and + * PROCESS_BEGIN are stamped with times that precede the moment we stamp them. + * That is safe here in a way it would not have been before: the gNB hook, the + * codelet and the dispatcher poll all read CLOCK_MONOTONIC now, which is + * latrec's own clock, so there is no domain conversion and no rate skew to + * absorb. + * + * What still has to hold is the ring's own invariant. 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 - so a descent would not + * produce an error, it would produce a plausible-looking capture cut at the + * wrong offset. Ordering across slots is a program-order property and normally + * has a wide margin: the jbpf hook is a synchronous inline call, so slot N's + * codelet has returned before slot N+1 is stamped, and A1 is tens of + * microseconds against a slot spacing of at least 500 us at 30 kHz SCS. + * + * Two things can still break it, so we enforce rather than assume: + * - a pipeline stall longer than the slot spacing, and + * - several RU receive threads (one per sector) feeding one worker, whose + * slots interleave on this one ring with no ordering between them. + * + * Enforcing costs a compare and a store. A non-zero clamped() means A1 is + * understated for that many slots, which is why the count is surfaced rather + * than left to be inferred from the data. + */ +inline thread_local uint64_t tls_floor_ns = 0; +/* Process-wide, so the shutdown summary can read it from the main thread while + * the worker maintains it. Touched only when a clamp actually happens, which is + * the rare case - the floor itself is thread-local and costs a compare. */ +inline std::atomic g_clamped{0}; + +inline uint64_t monotone(uint64_t t_ns) +{ + if (t_ns <= tls_floor_ns) { + g_clamped.fetch_add(1, std::memory_order_relaxed); + t_ns = tls_floor_ns + 1; + } + tls_floor_ns = t_ns; + return t_ns; +} + +inline void stamp_at(uint64_t seq, uint8_t stage, uint64_t aux, uint64_t aux2, uint64_t t_ns) +{ + latrec_tstamp_at(seq, stage, aux, aux2, monotone(t_ns)); +} + +inline void stamp_now(uint64_t seq, uint8_t stage, uint64_t aux, uint64_t aux2) +{ + /* Routed through the same floor as the back-dated stamps, so the floor + * reflects every record in the ring and not just the ones we adjust. */ + stamp_at(seq, stage, aux, aux2, latrec_tnow()); +} + +/* Stamps whose time had to be clamped to keep the ring ascending. Non-zero + * means A1 is understated for that many slots. */ +inline uint64_t clamped() { return g_clamped.load(std::memory_order_relaxed); } + +#else /* !LIBE3_ENABLE_LATREC */ + +inline void stamp_at(uint64_t, uint8_t, uint64_t, uint64_t, uint64_t) {} +inline void stamp_now(uint64_t, uint8_t, uint64_t, uint64_t) {} +inline uint64_t clamped() { return 0; } + +#endif /* LIBE3_ENABLE_LATREC */ + +/* A1 entry: the slot's data existed and nothing had moved yet. + * + * aux carries the source-defined slot key, per the catalog. aux2 carries the + * codelet's entry stamp, which splits A1 into the part that is jbpf getting to + * the codelet and the part that is the codelet moving the data: + * + * jbpf dispatch RECORD_BEGIN.aux2 - RECORD_BEGIN t_ns + * convert + write PROCESS_BEGIN t_ns - RECORD_BEGIN.aux2 + */ +inline void record_begin(uint64_t seq, + uint32_t sfn, + uint16_t abs_slot, + uint64_t gnb_ts_ns, + uint64_t codelet_entry_ts_ns) +{ + stamp_at(seq, + LATREC_RECORD_BEGIN, + (static_cast(sfn) << 16) | abs_slot, + codelet_entry_ts_ns, + gnb_ts_ns); +} + +/* A1 exit / A2 entry: the slot's data was in place and the codelet was about to + * submit the descriptor. + * + * aux carries the dispatcher's poll stamp, splitting A2 into the jbpf ring + * transit and the queue wait: + * + * ring transit PROCESS_BEGIN.aux - PROCESS_BEGIN t_ns + * queue wait ENCODE_E3SM_BEGIN t_ns - PROCESS_BEGIN.aux + */ +inline void process_begin(uint64_t seq, uint64_t codelet_ts_ns, uint64_t dispatch_ts_ns, uint32_t bytes) +{ + stamp_at(seq, LATREC_PROCESS_BEGIN, dispatch_ts_ns, bytes, codelet_ts_ns); +} + +/* A2 exit / A3 entry. */ +inline void encode_begin(uint64_t seq, uint32_t payload_bytes) +{ + stamp_now(seq, + LATREC_ENCODE_E3SM_BEGIN, + payload_bytes, + static_cast(libe3::PduType::INDICATION_MESSAGE)); +} + +/* A3 exit. */ +inline void encode_done(uint64_t seq, std::size_t encoded_bytes) +{ + stamp_now(seq, + LATREC_ENCODE_E3SM_DONE, + static_cast(encoded_bytes), + static_cast(libe3::PduType::INDICATION_MESSAGE)); +} + +/* A3 failed: the slot produced no indication. Closes the row with a reason + * instead of leaving it looking like a lost record. */ +inline void encode_failed(uint64_t seq) +{ + stamp_now(seq, LATREC_SKIPPED, 0, LATREC_SKIP_ENCODE); +} + +/* Publish this slot's key to libe3, immediately before entering the library. + * + * This is the whole of the cross-component join: libe3 records whatever was + * last passed here into EMIT_ENTER's aux, which latrec2csv.py surfaces as the + * `origin_seq` column on the outbound leg. Without it the library's records + * are unattributable to the slot that produced them. + * + * It is a no-op on a thread with no ring open, which is the other reason + * open_ring() has to have run first. + */ +inline void bind_libe3(uint64_t seq) +{ + latrec_ctx_set(seq); +} + +/* The emit tail: subscriber fan-out bookkeeping after the payload has gone + * into the library. latrec2csv.py emits it as ENCODE_E3SM_DONE__WAIT_ENTER_us, + * because (ENCODE_E3SM_DONE -> WAIT_ENTER) is a declared extra hop on the + * source leg. + * + * Stamped once per slot, after the loop, so it covers every subscriber rather + * than just the first - aux carries how many there were, which is what makes + * the per-subscriber cost recoverable. + */ +inline void emit_tail(uint64_t seq, std::size_t subscribers) +{ + stamp_now(seq, LATREC_WAIT_ENTER, static_cast(subscribers), 0); +} + +} // namespace e3sm_l1kpm_trace + +#endif /* E3_SM_L1KPM_TRACE_H */ diff --git a/src/e3sm/slot_iq_pipeline.cpp b/src/e3sm/slot_iq_pipeline.cpp index 1156167..947a608 100644 --- a/src/e3sm/slot_iq_pipeline.cpp +++ b/src/e3sm/slot_iq_pipeline.cpp @@ -7,6 +7,8 @@ #include "slot_iq_pipeline.h" +#include "e3sm/l1_kpm/l1_kpm_trace.h" + #include #include #include @@ -324,6 +326,14 @@ void SlotIqPipeline::process_buffers(struct jbpf_io_stream_id* /*stream_id*/, } void SlotIqPipeline::worker_loop() { + /* Open this thread's stage-record ring before the loop, not inside it: the + * call faults in the whole mapping, and it has to happen before the first + * indication is emitted or libe3 would open the ring first under its own + * name and every record we stamp would be attributed to the library + * instead of to this component. Idempotent, and a no-op in a build without + * the recorder compiled in. */ + e3sm_l1kpm_trace::open_ring(); + while (running_.load(std::memory_order_acquire)) { const uint64_t tail = queue_tail_.load(std::memory_order_relaxed); const uint64_t head = queue_head_.load(std::memory_order_acquire); diff --git a/src/e3sm/slot_iq_pipeline.h b/src/e3sm/slot_iq_pipeline.h index 83d80c7..f535b09 100644 --- a/src/e3sm/slot_iq_pipeline.h +++ b/src/e3sm/slot_iq_pipeline.h @@ -94,10 +94,13 @@ struct SlotSample { uint32_t bytes_written{0}; uint8_t flags{0}; - /* RAN anchor (CLOCK_REALTIME ns) stamped by the ocudu hook caller - * at hand-off. Same domain as jbpf_time_get_ns() and the dApp's - * time.time_ns(), so it subtracts cleanly on both sides for true - * RAN -> dApp end-to-end latency. */ + /* A1 entry: RAN anchor stamped by the ocudu hook caller at hand-off, on the + * last symbol with the grid complete and nothing yet copied. + * + * CLOCK_MONOTONIC ns, same domain as jbpf_time_get_ns() (patched) and + * dispatch_ts_ns below, so the stage subtractions are exact. Note this is + * no longer comparable against a dApp's CLOCK_REALTIME clock without going + * through a ring header's mono/real pair. */ uint64_t gnb_ts_ns{0}; /* Codelet ENTRY timestamp (CLOCK_MONOTONIC ns). Subtract gnb_ts_ns for the @@ -110,8 +113,9 @@ struct SlotSample { uint64_t codelet_ts_ns{0}; /* Controller-side timestamps captured when the slot arrived at - * the dispatcher poll. dispatch_ts_ns = CLOCK_REALTIME ns at - * dispatcher entry (for stage timing vs. codelet_ts_ns). + * the dispatcher poll. dispatch_ts_ns = CLOCK_MONOTONIC ns at + * dispatcher entry (for stage timing vs. codelet_ts_ns). One read per poll + * batch, shared by every buffer in the batch. * recv_us = wall-clock microseconds at dispatcher entry (legacy, * kept for backwards-compatible stats consumers). * sample_id = monotonic count since startup. */ @@ -201,7 +205,7 @@ class SlotIqPipeline { * this buffer; the worker releases it (jbpf_io_channel_release_buf) after * the consumer fan-out. Valid from enqueue until that release. */ void* buf; - /* CLOCK_REALTIME ns at dispatcher poll entry. Used by the SM to + /* CLOCK_MONOTONIC ns at dispatcher poll entry. Used by the SM to * derive the codelet -> dispatcher stage cost. */ uint64_t dispatch_ts_ns; uint32_t recv_us;