From e2c7809abb6ddb121b38a94d4bee3353a83a9c0b Mon Sep 17 00:00:00 2001 From: faluco Date: Thu, 25 Mar 2021 12:19:33 +0100 Subject: [PATCH] - Introduce a new tracer scoped object that only records if the event duration exceeds the programmed threshold. --- lib/include/srsran/srslog/event_trace.h | 27 ++++++++++++++++--------- lib/src/srslog/event_trace.cpp | 12 +++++++---- lib/test/srslog/event_trace_test.cpp | 26 ++++++++++++++++++++++++ 3 files changed, 51 insertions(+), 14 deletions(-) diff --git a/lib/include/srsran/srslog/event_trace.h b/lib/include/srsran/srslog/event_trace.h index f08fe86c7..8fcfd9e49 100644 --- a/lib/include/srsran/srslog/event_trace.h +++ b/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) -#define trace_complete_event(C, N) \ - auto SRSLOG_TRACE_COMBINE(scoped_complete_event, __LINE__) = \ - srslog::detail::scoped_complete_event(C, N) + +/// 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) + +/// 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,16 +77,19 @@ 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(); private: - const char* const category; - const char* const name; + const char* const category; + const char* const name; std::chrono::time_point start; + std::chrono::microseconds threshold; }; } // namespace detail diff --git a/lib/src/srslog/event_trace.cpp b/lib/src/srslog/event_trace.cpp index 7d84f018c..cb5cdae48 100644 --- a/lib/src/srslog/event_trace.cpp +++ b/lib/src/srslog/event_trace.cpp @@ -118,12 +118,16 @@ srslog::detail::scoped_complete_event::~scoped_complete_event() return; } - auto end = std::chrono::steady_clock::now(); - unsigned long long diff = std::chrono::duration_cast(end - start).count(); + auto end = std::chrono::steady_clock::now(); + auto diff = std::chrono::duration_cast(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)); } diff --git a/lib/test/srslog/event_trace_test.cpp b/lib/test/srslog/event_trace_test.cpp index 173089960..d55648e08 100644 --- a/lib/test/srslog/event_trace_test.cpp +++ b/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 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; }