MORI-IO CPU hot-path improvements + logging thread-safety

[pemeliya]

Profiling-guided reduction of CPU overhead on the MORI-IO submission/completion
hot paths, plus a correctness fix for the module logger under multithreading.

Commits:

• c6fadb9 — CPU hot path improvements
• e7213bf — MORI IO improvements guided by prof

Motivation

perf profiles of the high-IOPS workload showed the CPU cost concentrated in a
few places that were pure bookkeeping overhead rather than useful work:

• SubmissionLedger::Insert / ReleaseByCqe / RecordPostTimestamp were
  dominated by malloc/unordered_map (hashtable + rehash) frames and by
  pthread_mutex_lock/unlock, with the notif thread and worker threads
  actually colliding on the ledger mutex (descending into futex_wait).
• The notif thread's CQ poll loop rebuilt an endpoint snapshot (shared_lock +
  heap allocation) and took NotifManager::mu to resolve the notif context on
  every single poll.
• ScopedTimer / MORI_* logging resolved the logger via a string-hashed
  unordered_map lookup on every call, even when the level was disabled.

Separately, we tracked down repeated logger for module ... is nullptr spam to
a data race in the logger wrapper (details below).

Changes

1. SubmissionLedger: allocation-free ring + spinlock

src/io/rdma/common.hpp, src/io/rdma/ledger.cpp, src/io/rdma/common.cpp,
src/io/rdma/backend_impl.cpp

• Replaced the mutex-guarded std::unordered_map<recordId, SubmissionRecord>
  with a fixed, power-of-two ring buffer (std::vector<SubmissionRecord>)
  indexed by recordId & capMask_. A slot is empty iff its stored recordId
  is 0. This removes all per-op allocation and hashing.
• The ring is sized from the endpoint's maxSqDepth (maxMsgsNum) as
  next_pow2(maxSqDepth + slack) with a floor. Admission control bounds the
  number of live records below capacity, so recordId & capMask_ never aliases
  a still-live slot; a defensive check logs loudly if that invariant is ever
  violated.
• The ledger constructor gained a maxSqDepth parameter; ConnectEndpoint
  passes epConfig.maxMsgsNum.
• Swapped the std::mutex for a lightweight TTAS SpinLock (acquire/release
  ordering, pause/yield relax hint). The ledger critical sections are only a
  handful of instructions, so a spin is far cheaper than a futex under
  contention.
• RecordPostTimestamp() is kept as a separate O(1) ring lookup (stamps the
  post timestamp into the live slot under the lock) rather than folded into
  Insert.

2. NotifManager CQ-poll hot path

src/io/rdma/backend_impl.cpp, src/io/rdma/backend_impl.hpp,
src/io/rdma/common.hpp

• Lockless notif-context resolution: the QpNotifContext* is published once
  at registration into EndpointRuntime::notifCtx (an std::atomic<void*>,
  release store) and read locklessly in ProcessOneCqe (acquire load). The
  containing map is node-based, so the cached pointer stays valid. This removes
  the per-poll NotifManager::mu lock.
• Cached endpoint snapshot with an epoch: RdmaManager now exposes a
  monotonic EndpointsEpoch() bumped whenever the endpoint set changes. The
  busy-poll loop only rebuilds its snapshot (shared_lock + allocation) when the
  epoch moves instead of on every spin. SnapshotEndpointRuntimes now fills a
  caller-owned vector to avoid per-call heap churn.

3. Logging hot path (ScopedTimer / timer macros)

include/mori/utils/mori_log.hpp

• ScopedTimer now resolves the logger and checks the level up front; when
  DEBUG is disabled it is a true no-op (no string copy, no clock reads, no log
  call).
• MORI_TIMER / MORI_FUNCTION_TIMER cache the (module -> logger) resolution
  in a function-local static, so the hashtable probe happens once per
  call-site instead of on every invocation.

4. ModuleLogger thread-safety fix (nullptr spam)

include/mori/utils/mori_log.hpp

Root cause: ModuleLogger's internal std::unordered_maps (loggers_,
envOverrides_) were read by GetLogger and mutated by InitModule /
SetGlobalLevel from many threads with no synchronization. Under the RDMA
workload, a concurrent insert/rehash racing a find could hand back an empty
shared_ptr; the MORI_LOG macro then cached that transient null in its
call-site static forever, producing permanent logger ... is nullptr spam.
(spdlog itself is thread-safe — the race was entirely in this wrapper.)

• Added a std::mutex guarding all map/level state.
• Eagerly create all known module loggers in the constructor; the Meyers
  singleton guarantees this runs once before any thread can call GetLogger, so
  the common read path never races a write.
• Split logic into *_Locked helpers to avoid recursive locking; all level/env
  mutators now lock.
• GetLogger never returns null: it retries on-demand creation and, if that
  ever genuinely fails, abort()s loudly rather than letting callers silently
  drop logs (preferred over a silent no-op).

5. Tests

• tests/cpp/io/test_engine.cpp: added a SubmissionLedger ring wraparound
  test (insert/release across more than capacity ids; stale ids return
  nullptr).
• tests/cpp/utils/test_logging.cpp (new) + tests/cpp/CMakeLists.txt:
  multi-threaded ModuleLogger stress tests — concurrent resolution of
  known/unknown modules (never null), concurrent first-touch of the same new
  module (one stable instance), and logging while levels are reconfigured.
  Intended to also run under ThreadSanitizer.

Performance

Comparing perf self-samples on the ledger paths before/after (high-IOPS run):

Path	Before	After
SubmissionLedger::Insert	~87M (body + malloc/hashtable + mutex)	~1.5M
SubmissionLedger::RecordPostTimestamp	~50M (mostly mutex)	~2.6M
SubmissionLedger::ReleaseByCqe	~41M (body + mutex + futex_wait)	~2.9M

All malloc/unordered_map/hashtable frames and all pthread_mutex_* /
futex_wait frames disappeared from the ledger paths (~25x lower ledger CPU),
and the notif/worker threads no longer contend on the ledger lock. After these
changes the profile is dominated by ibv_poll_cq and the mlx5 driver's internal
CQ spinlock (the driver, not MORI) — a good candidate for follow-up.

Testing / validation

• test_logging built with the project ROCm toolchain: 3 tests PASSED.
• Same test under ThreadSanitizer (-fsanitize=thread, setarch -R to work
  around a container ASLR/mapping quirk): 3 tests PASSED, 0 data races,
  0 TSAN warnings — confirming the logger maps are now properly synchronized.
• SubmissionLedger ring wraparound test passes; existing ledger test still
  green.

Notes / risk

• The SpinLock is intended for the short, uncontended ledger critical
  sections. On an oversubscribed host (more busy threads than cores) a pure spin
  can waste cycles; the current deployment gives the notif thread and workers
  their own cores. If future profiles show time in SpinLock::lock, add a
  bounded spin + sched_yield/backoff fallback.
• Per-QP ring memory is capacity * sizeof(SubmissionRecord); very large
  maxSqDepth combined with many QPs increases per-QP footprint.
• ModuleLogger::GetLogger now abort()s on a fundamentally broken logging
  subsystem instead of returning null. This is unreachable in practice (the
  application logger is created eagerly and stdout_color_mt creates any new
  name), and is the intended fail-loud behavior.

Follow-ups (not in this PR)

• Reduce ibv_poll_cq + mlx5 CQ-spinlock cost (e.g., skip polling CQs with no
  outstanding completions, larger poll batch, adaptive backoff, or evaluate
  event-driven CQ mode).

[pemeliya]

Prof traces before and after modifications:
trace_before.txt
trace_after.txt

[Copilot]

Pull request overview

This PR optimizes MORI-IO’s RDMA submission/completion hot paths to reduce CPU overhead and fixes thread-safety issues in the logging wrapper under multithreaded workloads.

Changes:

• Replaces SubmissionLedger’s mutex+unordered_map with an allocation-free ring buffer guarded by a TTAS spinlock, plus adds wraparound coverage.
• Reduces NotifManager CQ-poll overhead by caching endpoint snapshots (epoch-based) and resolving notif context locklessly via an atomically published pointer.
• Speeds up logging/timer hot paths via call-site logger caching, and adds a mutex + eager module initialization to make ModuleLogger thread-safe (with new concurrency tests).

Reviewed changes

Copilot reviewed 9 out of 9 changed files in this pull request and generated 4 comments.

Show a summary per file

File	Description
tests/cpp/utils/test_logging.cpp	New multithreaded stress tests for ModuleLogger resolution and reconfiguration.
tests/cpp/io/test_engine.cpp	Adds a SubmissionLedger ring wraparound/release correctness test case.
tests/cpp/CMakeLists.txt	Adds test_logging executable + CTest entry.
src/io/rdma/ledger.cpp	Implements ring-buffer ledger + spinlock; adds post timestamp ring lookup.
src/io/rdma/common.hpp	Adds SpinLock, updates SubmissionLedger API and stores notifCtx atomic pointer.
src/io/rdma/common.cpp	Moves post-timestamp recording earlier in the telemetry block.
src/io/rdma/backend_impl.hpp	Changes endpoint snapshot API; adds endpoints epoch counter accessor.
src/io/rdma/backend_impl.cpp	Publishes notif context pointer; caches endpoint snapshot based on epoch.
include/mori/utils/mori_log.hpp	Adds ModuleLogger synchronization/eager init; caches logger lookup in logging/timer macros.

Comments suppressed due to low confidence (1)

src/io/rdma/ledger.cpp:96

• Same as Insert(): on ring overflow this logs but then overwrites a still-live slot, which can corrupt the ledger state. Consider failing fast (or otherwise preventing clobber) once overflow is detected.

  if (MORI_IO_TELEM_UNLIKELY(slot.recordId != 0)) {
    MORI_IO_ERROR(
        "SubmissionLedger::InsertOrphaned ring overflow: slot for recordId {} still holds live "
        "recordId {} (capacity {}); increase ring capacity",
        id, slot.recordId, capMask_ + 1);
  }

---

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

[maning00]

Thanks @pemeliya for the profiling and optimization work. The results look valuable, but the current PR mixes two different scopes.

Several changes are general MORI-IO optimizations unrelated to telemetry, including:

• SubmissionLedger allocation/locking optimization
• CQ endpoint snapshot caching
• Lockless notification-context lookup
• Logging thread-safety and call-site logger caching

These improvements also benefit the current main branch, so please extract them into a separate PR based on the latest main. This will make the changes easier to review, benchmark, and reuse independently of the telemetry feature.

After that, please continue investigating the overhead introduced specifically by feat/io-telemetry, especially when telemetry is disabled. The goal should be for the telemetry-disabled path to remain as close as possible to the equivalent main path.

For validation, please compare:

1. The latest main with and without the general optimizations. (PR 1)
2. feat/io-telemetry with telemetry disabled against main with the same general optimizations. (PR 2)
3. feat/io-telemetry with telemetry enabled against telemetry disabled on the same commit. (PR 2)

To summarize, please split this work into two PRs:

1. A general MORI-IO optimization PR targeting the latest main.
2. A telemetry-specific optimization PR targeting feat/io-telemetry, focused on eliminating overhead when telemetry is disabled and reducing the cost when it is enabled.