- Introduce a new tracer scoped object that only records if the event duration exceeds the programmed threshold.

lib/include/srsran/srslog/event_trace.h

@@ -40,8 +40,7 @@ void event_trace_init(log_channel& c);
 /// The event trace data will be written into the specified filename after
 /// capacity bytes of data have been generated or at program exit.
 /// Returns true on success, otherwise false.
-bool event_trace_init(const std::string& filename,
-                      std::size_t capacity = 1024 * 1024);
+bool event_trace_init(const std::string& filename, std::size_t capacity = 1024 * 1024);
 
 #ifdef ENABLE_SRSLOG_EVENT_TRACE
 
@@ -51,12 +50,16 @@ void trace_duration_begin(const std::string& category, const std::string& name);
 /// Generates the end phase of a duration event.
 void trace_duration_end(const std::string& category, const std::string& name);
 
-/// Generates a complete event.
 #define SRSLOG_TRACE_COMBINE1(X, Y) X##Y
 #define SRSLOG_TRACE_COMBINE(X, Y) SRSLOG_TRACE_COMBINE1(X, Y)
+
+/// Generates a complete event.
 #define trace_complete_event(C, N)                                                                                     \
-  auto SRSLOG_TRACE_COMBINE(scoped_complete_event, __LINE__) =                 \
-      srslog::detail::scoped_complete_event(C, N)
+  auto SRSLOG_TRACE_COMBINE(scoped_complete_event, __LINE__) = srslog::detail::scoped_complete_event(C, N)
+
+/// Generates a complete event but only is recorded if the event duration exceeds a certain threshold in microseconds.
+#define trace_threshold_complete_event(C, N, T)                                                                        \
+  auto SRSLOG_TRACE_COMBINE(scoped_complete_event, __LINE__) = srslog::detail::scoped_complete_event(C, N, T)
 
 #else
 
@@ -64,6 +67,7 @@ void trace_duration_end(const std::string& category, const std::string& name);
 #define trace_duration_begin(C, N)
 #define trace_duration_end(C, N)
 #define trace_complete_event(C, N)
+#define trace_threshold_complete_event(C, N, T)
 
 #endif
 
@@ -73,8 +77,10 @@ namespace detail {
 class scoped_complete_event
 {
 public:
-  scoped_complete_event(const char* cat, const char* n) :
-    category(cat), name(n), start(std::chrono::steady_clock::now())
+  scoped_complete_event(const char*               cat,
+                        const char*               n,
+                        std::chrono::microseconds threshold = std::chrono::microseconds::zero()) :
+    category(cat), name(n), start(std::chrono::steady_clock::now()), threshold(threshold)
   {}
 
   ~scoped_complete_event();
@@ -83,6 +89,7 @@ private:
   const char* const                                  category;
   const char* const                                  name;
   std::chrono::time_point<std::chrono::steady_clock> start;
+  std::chrono::microseconds                          threshold;
 };
 
 } // namespace detail

lib/src/srslog/event_trace.cpp

@@ -119,11 +119,15 @@ srslog::detail::scoped_complete_event::~scoped_complete_event()
   }
 
   auto end  = std::chrono::steady_clock::now();
-  unsigned long long diff = std::chrono::duration_cast<std::chrono::microseconds>(end - start).count();
+  auto diff = std::chrono::duration_cast<std::chrono::microseconds>(end - start);
+
+  if (diff < threshold) {
+    return;
+  }
 
   small_str_buffer str;
-  // Limit to the category and name strings to a predefined length so everything fits in a small string.
-  fmt::format_to(str, "{:.32} {:.16}, {}", category, name, diff);
+  // Limit the category and name strings to a predefined length so everything fits in a small string.
+  fmt::format_to(str, "{:.32} {:.16}, {}", category, name, diff.count());
   str.push_back('\0');
   (*tracer)(std::move(str));
 }

lib/test/srslog/event_trace_test.cpp

@@ -14,6 +14,7 @@
 #include "srsran/srslog/log_channel.h"
 #include "test_dummies.h"
 #include "testing_helpers.h"
+#include <thread>
 
 using namespace srslog;
 
@@ -68,6 +69,27 @@ static bool when_tracing_with_complete_event_then_one_event_is_generated(backend
   return true;
 }
 
+static bool when_tracing_with_under_threshold_complete_event_then_no_event_is_generated(backend_spy& spy)
+{
+  {
+    trace_threshold_complete_event("a", "b", std::chrono::microseconds(100000));
+  }
+  ASSERT_EQ(spy.push_invocation_count(), 0);
+
+  return true;
+}
+
+static bool when_tracing_with_above_threshold_complete_event_then_one_event_is_generated(backend_spy& spy)
+{
+  {
+    trace_threshold_complete_event("a", "b", std::chrono::microseconds(10));
+    std::this_thread::sleep_for(std::chrono::microseconds(1000));
+  }
+  ASSERT_EQ(spy.push_invocation_count(), 1);
+
+  return true;
+}
+
 int main()
 {
   test_dummies::sink_dummy s;
@@ -80,6 +102,10 @@ int main()
   TEST_FUNCTION(when_tracing_with_duration_event_then_two_events_are_generated, backend);
   backend.reset();
   TEST_FUNCTION(when_tracing_with_complete_event_then_one_event_is_generated, backend);
+  backend.reset();
+  TEST_FUNCTION(when_tracing_with_under_threshold_complete_event_then_no_event_is_generated, backend);
+  backend.reset();
+  TEST_FUNCTION(when_tracing_with_above_threshold_complete_event_then_one_event_is_generated, backend);
 
   return 0;
 }