Add optional [LAT] latency-profiling log points

CMakeLists.txt

@@ -98,4 +98,5 @@ message(STATUS "  Build Examples:   ${LIBE3_BUILD_EXAMPLES}")
 message(STATUS "  ZeroMQ Support:   ${LIBE3_ENABLE_ZMQ}")
 message(STATUS "  AddressSanitizer: ${LIBE3_ENABLE_ASAN}")
 message(STATUS "  ThreadSanitizer:  ${LIBE3_ENABLE_TSAN}")
+message(STATUS "  Latency [LAT]:    ${LIBE3_ENABLE_LATENCY}")
 message(STATUS "")

cmake/libe3Options.cmake

@@ -15,3 +15,7 @@ option(LIBE3_ENABLE_PROTOBUF "Enable Protocol Buffers encoding support" OFF)
 option(LIBE3_ENABLE_ASAN "Enable AddressSanitizer" OFF)
 option(LIBE3_ENABLE_TSAN "Enable ThreadSanitizer" OFF)
 option(LIBE3_BUILD_DOCS "Build documentation" OFF)
+# Optional [LAT] latency-profiling log points (see include/libe3/latency.hpp).
+# Off by default: compiled out entirely, so normal builds are unaffected and
+# enabling it does not require raising the logger to DEBUG.
+option(LIBE3_ENABLE_LATENCY "Emit [LAT] latency-profiling log points" OFF)

cmake/libe3Sources.cmake

@@ -5,6 +5,7 @@
 set(LIBE3_PUBLIC_HEADERS
     include/libe3/types.hpp
     include/libe3/logger.hpp
+    include/libe3/latency.hpp
     include/libe3/e3_connector.hpp
     include/libe3/e3_encoder.hpp
     include/libe3/mpmc_queue.hpp

cmake/libe3Targets.cmake

@@ -61,6 +61,10 @@ else()
     target_compile_definitions(libe3 PUBLIC LIBE3_HAS_ZMQ=0)
 endif()
 
+if(LIBE3_ENABLE_LATENCY)
+    target_compile_definitions(libe3 PRIVATE LIBE3_LATENCY)
+endif()
+
 set_target_properties(libe3 PROPERTIES
     VERSION ${PROJECT_VERSION}
     SOVERSION ${PROJECT_VERSION_MAJOR}
@@ -118,6 +122,10 @@ else()
     target_compile_definitions(libe3_shared PUBLIC LIBE3_HAS_ZMQ=0)
 endif()
 
+if(LIBE3_ENABLE_LATENCY)
+    target_compile_definitions(libe3_shared PRIVATE LIBE3_LATENCY)
+endif()
+
 set_target_properties(libe3_shared PROPERTIES
     VERSION ${PROJECT_VERSION}
     SOVERSION ${PROJECT_VERSION_MAJOR}

include/libe3/latency.hpp

@@ -0,0 +1,88 @@
+/**
+ * @file latency.hpp
+ * @brief Optional latency-profiling log points for the E3 critical path.
+ *
+ * SPDX-License-Identifier: Apache-2.0
+ *
+ * Compile-gated by LIBE3_LATENCY (enable with the CMake option
+ * -DLIBE3_ENABLE_LATENCY=ON): off by default, so normal builds pay zero cost
+ * and default log verbosity is untouched. When enabled, each site emits ONE
+ * INFO line in a shared machine-parseable format so an offline collector can
+ * grep and correlate interleaved gNB / E3 agent / dApp logs:
+ *
+ *   [LAT] stage=<name> t_ns=<monotonic ns> anchor_ns=<producer_ts|0> [k=v ...]
+ *
+ * t_ns comes from steady_clock, which on Linux/glibc is backed by
+ * CLOCK_MONOTONIC with the same epoch as clock_gettime(CLOCK_MONOTONIC), so it
+ * subtracts directly against the gNB (C) and aerial timestamps on the same
+ * node. anchor_ns is the carried producer timestamp (0 on the control return
+ * leg, where the collector pairs by consecutive line).
+ *
+ * Gating is the compile switch, NOT the log level: a profiling run does not
+ * have to raise the logger to DEBUG (which would flood it with unrelated
+ * debug output).
+ */
+#ifndef LIBE3_LATENCY_HPP
+#define LIBE3_LATENCY_HPP
+
+#include <chrono>
+#include <cstdint>
+
+#include "libe3/logger.hpp"
+
+namespace libe3 {
+
+/** Monotonic now in ns (== CLOCK_MONOTONIC on glibc). */
+inline uint64_t lat_mono_ns() {
+    return static_cast<uint64_t>(
+        std::chrono::duration_cast<std::chrono::nanoseconds>(
+            std::chrono::steady_clock::now().time_since_epoch())
+            .count());
+}
+
+/** Wall-clock now in ns (== CLOCK_REALTIME on glibc). */
+inline uint64_t lat_real_ns() {
+    return static_cast<uint64_t>(
+        std::chrono::duration_cast<std::chrono::nanoseconds>(
+            std::chrono::system_clock::now().time_since_epoch())
+            .count());
+}
+
+#ifndef LIBE3_LATENCY
+/** Sink that swallows the trailing "<< k << v" chain when profiling is off. */
+struct NullLatSink {
+    template <typename T>
+    NullLatSink& operator<<(const T&) {
+        return *this;
+    }
+};
+#endif
+
+}  // namespace libe3
+
+#ifdef LIBE3_LATENCY
+
+// Returns the log stream so callers may append " k=v" pairs, e.g.
+//   E3_LAT(LOG_TAG, "ind_wire_tx", 0) << " type=" << t;
+#define E3_LAT(component, stage, anchor)                               \
+    E3_LOG_INFO(component) << "[LAT] stage=" stage                     \
+                           << " t_ns=" << ::libe3::lat_mono_ns()       \
+                           << " anchor_ns=" << (anchor)
+
+// Per-process run-start line: CLOCK_MONOTONIC <-> CLOCK_REALTIME for future
+// cross-node (xApp) alignment. No-op for same-node Phase 1 correlation.
+#define E3_LAT_CLOCK_OFFSET(component)                                 \
+    E3_LOG_INFO(component) << "[LAT] clock_offset"                     \
+                           << " mono_ns=" << ::libe3::lat_mono_ns()    \
+                           << " real_ns=" << ::libe3::lat_real_ns()
+
+#else /* !LIBE3_LATENCY */
+
+#define E3_LAT(component, stage, anchor) \
+    while (false) ::libe3::NullLatSink {}
+#define E3_LAT_CLOCK_OFFSET(component) \
+    while (false) ::libe3::NullLatSink {}
+
+#endif /* LIBE3_LATENCY */
+
+#endif  // LIBE3_LATENCY_HPP

src/core/e3_interface.cpp

@@ -9,6 +9,7 @@
 
 #include "libe3/e3_interface.hpp"
 #include "libe3/logger.hpp"
+#include "libe3/latency.hpp"
 #include <cctype>
 #include <chrono>
 #include <cstdlib>
@@ -391,6 +392,7 @@ void E3Interface::setup_loop_ran() {
 void E3Interface::inbound_loop_ran() {
     apply_thread_config(config_.io_thread_affinity, config_.io_thread_niceness);
     E3_LOG_INFO(LOG_TAG) << "Inbound loop (RAN) started";
+    E3_LAT_CLOCK_OFFSET(LOG_TAG);
 
     ErrorCode result = connector_->setup_inbound_connection();
     if (result != ErrorCode::SUCCESS) {
@@ -436,6 +438,7 @@ void E3Interface::inbound_loop_ran() {
             case PduType::DAPP_CONTROL_ACTION: {
                 auto* action = std::get_if<DAppControlAction>(&pdu.choice);
                 if (action) {
+                    E3_LAT(LOG_TAG, "ctrl_wire_rx", 0) << " bytes=" << action->action_data.size();
                     handle_control_action(*action, pdu.message_id);
                 }
                 break;
@@ -516,6 +519,12 @@ void E3Interface::outbound_loop_ran() {
         }
 
         ErrorCode send_result = connector_->send(encode_result->buffer);
+        // Stage 5 (last libe3 instant out): the encoded indication/response hits
+        // the wire. The producer timestamp lives inside the opaque SM payload, so
+        // anchor is 0 here; the collector pairs it to the gNB's ind_emit_oai by
+        // consecutive line.
+        E3_LAT(LOG_TAG, "ind_wire_tx", 0) << " type=" << pdu_type_to_string(pdu_opt->type)
+                                          << " bytes=" << encode_result->buffer.size();
         if (send_result != ErrorCode::SUCCESS) {
             E3_LOG_ERROR(LOG_TAG) << "Failed to send PDU";
         } else {
@@ -757,6 +766,8 @@ void E3Interface::handle_control_action(const DAppControlAction& action, uint32_
     ServiceModel* sm = SmRegistry::instance().get_by_ran_function(action.ran_function_identifier);
 
     if (sm && sm->is_running()) {
+        E3_LAT(LOG_TAG, "ctrl_dispatch", 0) << " rf=" << action.ran_function_identifier
+                                            << " ctrl=" << action.control_identifier;
         ErrorCode result = sm->handle_control_action(request_message_id, action);
         if (result != ErrorCode::SUCCESS) {
             E3_LOG_ERROR(LOG_TAG) << "SM failed to process control action: "