perf: Add ScopedProfiler and ProfilerReporter to simplify profiling.

components/core/CMakeLists.txt

@@ -621,6 +621,7 @@ set(SOURCE_FILES_unitTest
         src/clp/Platform.hpp
         src/clp/Profiler.cpp
         src/clp/Profiler.hpp
+        src/clp/ProfilerReporter.hpp
         src/clp/Query.cpp
         src/clp/Query.hpp
         src/clp/QueryToken.cpp
@@ -629,6 +630,7 @@ set(SOURCE_FILES_unitTest
         src/clp/ReaderInterface.hpp
         src/clp/ReadOnlyMemoryMappedFile.cpp
         src/clp/ReadOnlyMemoryMappedFile.hpp
+        src/clp/ScopedProfiler.hpp
         src/clp/spdlog_with_specializations.hpp
         src/clp/SQLiteDB.cpp
         src/clp/SQLiteDB.hpp
@@ -734,9 +736,11 @@ set(SOURCE_FILES_unitTest
         tests/test-MemoryMappedFile.cpp
         tests/test-NetworkReader.cpp
         tests/test-ParserWithUserSchema.cpp
+        tests/test-ProfilerReporter.cpp
         tests/test-query_methods.cpp
         tests/test-regex_utils.cpp
         tests/test-SchemaSearcher.cpp
+        tests/test-ScopedProfiler.cpp
         tests/test-Segment.cpp
         tests/test-SQLiteDB.cpp
         tests/test-Stopwatch.cpp
@@ -797,6 +801,8 @@ if(CLP_ENABLE_TESTS)
             PRIVATE cxx_std_20
             )
     target_compile_definitions(unitTest
-            PRIVATE CLP_ENABLE_TESTS
+            PRIVATE
+            CLP_ENABLE_TESTS
+            PROF_TEST_ENABLED=1
             )
 endif()

components/core/src/clp/Profiler.cpp

@@ -1,11 +1,9 @@
 #include "Profiler.hpp"
 
-#include <memory>
-
-using std::unique_ptr;
 using std::vector;
 
 namespace clp {
-vector<Stopwatch>* Profiler::m_fragmented_measurements = nullptr;
-vector<Stopwatch>* Profiler::m_continuous_measurements = nullptr;
+std::unordered_map<std::string, Stopwatch> Profiler::m_runtime_measurements;
+vector<Stopwatch>* Profiler::m_compile_time_measurements = nullptr;
+bool Profiler::m_initialized = false;
 }  // namespace clp

components/core/src/clp/Profiler.hpp

@@ -1,65 +1,56 @@
 #ifndef CLP_PROFILER_HPP
 #define CLP_PROFILER_HPP
 
+#if defined(PROF_ENABLED) || defined(PROF_TEST_ENABLED)
+    #define PROF_ACTIVE 1
+#else
+    #define PROF_ACTIVE 0
+#endif
+
 #include <array>
+#include <unordered_map>
 #include <vector>
 
+#include <spdlog/spdlog.h>
+
 #include "Stopwatch.hpp"
 #include "type_utils.hpp"
 
 namespace clp {
 /**
  * Class to time code.
  *
- * There are two types of measurements:
- * - Continuous measurements where a user needs to time a single, continuous operation.
- * - Fragmented measurements where a user needs to time multiple, separated instances of an
- *   operation. For example if we want to get the total run time taken for inserting entries into a
- *   dictionary, we could wrap the insertion with a fragmented measurement.
+ * A Measurement can be taken over a single continuous operation, or called multiple times to
+ * accumulate fragemented measurements into a single total run time.
  *
- * To add a measurement, add it to the ContinuousMeasurementIndex or FragmentedMeasurementIndex
- * enums and add a corresponding enable flag to cContinuousMeasurementEnabled or
- * cFragmentedMeasurementEnabled. The flags allow enabling/disabling specific measurements such that
- * a disabled measurement will not affect the performance of the program (except for extra heap
- * storage).
- *
- * To log a measurement, use LOG_CONTINUOUS_MEASUREMENT or LOG_FRAGMENTED_MEASUREMENT, passing in
- * the relevant measurement index enum.
+ * There are two ways to add a measurement:
+ * 1. For measurements that are taken a small number of times use a runtime measurement.
+ * 2. For measurements that are in hot loops, use a compile-time measurement, such that when it is
+ *    disabled it has zero-overhead. In this case to add a measurement, add it to the
+ *    MeasurementIndex enum and add a corresponding enable flag to cMeasurementEnabled. The flags
+ *    allow enabling/disabling specific measurements such that a disabled measurement will not
+ *    affect the performance of the program (except for extra heap storage).
  *
  * Two implementation details allow this class to avoid inducing overhead when profiling is
  * disabled:
- * - All methods bodies are defined in the header, guarded by `if constexpr (PROF_ENABLED)`. When
+ * - All methods bodies are defined in the header, guarded by `if constexpr (PROF_ACTIVE)`. When
  *   profiling is disabled, the compiler will detect the empty body and won't add any code to the
  *   binary; if the methods were instead defined in the .cpp file, the compiler would still generate
  *   an empty method.
- * - The methods use the measurement enum as a template parameter to indicate which measurement the
- *   method call is for. So at compile-time, for each measurement, the compiler can use the enable
- *   flag to determine whether to generate code to do the measurement or whether to do nothing.
+ * - The compile-time methods use the measurement enum as a template parameter to indicate which
+ *   measurement the method call is for. So at compile-time, for each measurement, the compiler can
+ *   use the enable flag to determine whether to generate code to do the measurement or whether to
+ *   do nothing.
  */
 class Profiler {
 public:
-    // Types
-    enum class ContinuousMeasurementIndex : size_t {
-        Compression = 0,
-        ParseLogFile,
-        Search,
-        Length
-    };
-    enum class FragmentedMeasurementIndex : size_t {
+    enum class CompileTimeMeasurementIndex : uint8_t {
         Length
     };
 
-    // Constants
     // NOTE: We use lambdas so that we can programmatically initialize the constexpr array
-    static constexpr auto cContinuousMeasurementEnabled = []() {
-        std::array<bool, enum_to_underlying_type(ContinuousMeasurementIndex::Length)> enabled{};
-        enabled[enum_to_underlying_type(ContinuousMeasurementIndex::Compression)] = true;
-        enabled[enum_to_underlying_type(ContinuousMeasurementIndex::ParseLogFile)] = true;
-        enabled[enum_to_underlying_type(ContinuousMeasurementIndex::Search)] = true;
-        return enabled;
-    }();
-    static constexpr auto cFragmentedMeasurementEnabled = []() {
-        std::array<bool, enum_to_underlying_type(FragmentedMeasurementIndex::Length)> enabled{};
+    static constexpr auto cMeasurementEnabled = []() {
+        std::array<bool, enum_to_underlying_type(CompileTimeMeasurementIndex::Length)> enabled{};
         return enabled;
     }();
 
@@ -68,110 +59,133 @@ class Profiler {
      * Static initializer for class. This must be called before using the class.
      */
     static void init() {
-        if constexpr (PROF_ENABLED) {
-            m_continuous_measurements = new std::vector<Stopwatch>(
-                    enum_to_underlying_type(ContinuousMeasurementIndex::Length)
-            );
-            m_fragmented_measurements = new std::vector<Stopwatch>(
-                    enum_to_underlying_type(FragmentedMeasurementIndex::Length)
+        if constexpr (PROF_ACTIVE) {
+            if (m_initialized) {
+                return;
+            }
+            m_initialized = true;
+            m_compile_time_measurements = new std::vector<Stopwatch>(
+                    enum_to_underlying_type(CompileTimeMeasurementIndex::Length)
             );
         }
     }
 
-    template <ContinuousMeasurementIndex index>
-    static void start_continuous_measurement() {
-        if constexpr (PROF_ENABLED && cContinuousMeasurementEnabled[enum_to_underlying_type(index)])
-        {
-            auto& stopwatch = (*m_continuous_measurements)[enum_to_underlying_type(index)];
-            stopwatch.reset();
-            stopwatch.start();
+    static auto check_init() -> bool {
+        if constexpr (PROF_ACTIVE) {
+            if (false == m_initialized) {
+                SPDLOG_ERROR("Profiler used without calling Profiler::init()");
+            }
+            return m_initialized;
         }
+        return false;
     }
 
-    template <ContinuousMeasurementIndex index>
-    static void stop_continuous_measurement() {
-        if constexpr (PROF_ENABLED && cContinuousMeasurementEnabled[enum_to_underlying_type(index)])
-        {
-            (*m_continuous_measurements)[enum_to_underlying_type(index)].stop();
+    static auto check_runtime_timer_exists(std::string const& name) -> bool {
+        if constexpr (PROF_ACTIVE) {
+            if (false == m_runtime_measurements.contains(name)) {
+                SPDLOG_ERROR("Attempt to get runtime measurment of non existent timer {}", name);
+                return false;
+            }
+            return true;
         }
+        return false;
     }
 
-    template <ContinuousMeasurementIndex index>
-    static double get_continuous_measurement_in_seconds() {
-        if constexpr (PROF_ENABLED) {
-            return (*m_continuous_measurements)[enum_to_underlying_type(index)]
-                    .get_time_taken_in_seconds();
+    static auto start_runtime_measurement(std::string const& name) -> void {
+        if constexpr (PROF_ACTIVE) {
+            // implicitly creates the timer if it doesn't exist yet
+            m_runtime_measurements[name].start();
+        }
+    }
+
+    static auto stop_runtime_measurement(std::string const& name) -> void {
+        if constexpr (PROF_ACTIVE) {
+            if (false == check_runtime_timer_exists(name)) {
+                return;
+            }
+            m_runtime_measurements[name].stop();
+        }
+    }
+
+    static auto reset_runtime_measurements() -> void {
+        if constexpr (PROF_ACTIVE) {
+            m_runtime_measurements.clear();
+        }
+    }
+
+    static auto get_runtime_measurement_in_seconds(std::string const& name) -> double {
+        if constexpr (PROF_ACTIVE) {
+            if (false == check_runtime_timer_exists(name)) {
+                return 0;
+            }
+            return m_runtime_measurements[name].get_time_taken_in_seconds();
         } else {
             return 0;
         }
     }
 
-    template <FragmentedMeasurementIndex index>
-    static void start_fragmented_measurement() {
-        if constexpr (PROF_ENABLED && cFragmentedMeasurementEnabled[enum_to_underlying_type(index)])
-        {
-            (*m_fragmented_measurements)[enum_to_underlying_type(index)].start();
+    static auto get_runtime_call_count(std::string const& name) -> uint32_t {
+        if constexpr (PROF_ACTIVE) {
+            if (false == check_runtime_timer_exists(name)) {
+                return 0;
+            }
+            return m_runtime_measurements[name].get_call_count();
+        } else {
+            return 0;
         }
     }
 
-    template <FragmentedMeasurementIndex index>
-    static void stop_fragmented_measurement() {
-        if constexpr (PROF_ENABLED && cFragmentedMeasurementEnabled[enum_to_underlying_type(index)])
-        {
-            (*m_fragmented_measurements)[enum_to_underlying_type(index)].stop();
+    static auto get_runtime_measurements() -> std::unordered_map<std::string, Stopwatch> const& {
+        return m_runtime_measurements;
+    }
+
+    template <CompileTimeMeasurementIndex index>
+    static auto start_compile_time_measurement() -> void {
+        if constexpr (PROF_ACTIVE && cMeasurementEnabled[enum_to_underlying_type(index)]) {
+            if (false == check_init()) {
+                return;
+            }
+            (*m_compile_time_measurements)[enum_to_underlying_type(index)].start();
         }
     }
 
-    template <FragmentedMeasurementIndex index>
-    static void reset_fragmented_measurement() {
-        if constexpr (PROF_ENABLED && cFragmentedMeasurementEnabled[enum_to_underlying_type(index)])
-        {
-            (*m_fragmented_measurements)[enum_to_underlying_type(index)].reset();
+    template <CompileTimeMeasurementIndex index>
+    static auto stop_compile_time_measurement() -> void {
+        if constexpr (PROF_ACTIVE && cMeasurementEnabled[enum_to_underlying_type(index)]) {
+            if (false == check_init()) {
+                return;
+            }
+            (*m_compile_time_measurements)[enum_to_underlying_type(index)].stop();
         }
     }
 
-    template <FragmentedMeasurementIndex index>
-    static double get_fragmented_measurement_in_seconds() {
-        if constexpr (PROF_ENABLED) {
-            return (*m_fragmented_measurements)[enum_to_underlying_type(index)]
+    template <CompileTimeMeasurementIndex index>
+    static auto reset_compile_time_measurement() -> void {
+        if constexpr (PROF_ACTIVE && cMeasurementEnabled[enum_to_underlying_type(index)]) {
+            if (false == check_init()) {
+                return;
+            }
+            (*m_compile_time_measurements)[enum_to_underlying_type(index)].reset();
+        }
+    }
+
+    template <CompileTimeMeasurementIndex index>
+    static auto get_compile_time_measurement_in_seconds() -> double {
+        if constexpr (PROF_ACTIVE && cMeasurementEnabled[enum_to_underlying_type(index)]) {
+            if (false == check_init()) {
+                return 0;
+            }
+            return (*m_compile_time_measurements)[enum_to_underlying_type(index)]
                     .get_time_taken_in_seconds();
         } else {
             return 0;
         }
     }
 
 private:
-    static std::vector<Stopwatch>* m_fragmented_measurements;
-    static std::vector<Stopwatch>* m_continuous_measurements;
+    static std::unordered_map<std::string, Stopwatch> m_runtime_measurements;
+    static std::vector<Stopwatch>* m_compile_time_measurements;
+    static bool m_initialized;
 };
 }  // namespace clp
-
-// Macros to log the measurements
-// NOTE: We use macros so that we can add the measurement index to the log (not easy to do with
-// templates).
-#define LOG_CONTINUOUS_MEASUREMENT(x) \
-    if (PROF_ENABLED \
-        && ::clp::Profiler::cContinuousMeasurementEnabled[enum_to_underlying_type(x)]) \
-    { \
-        SPDLOG_INFO( \
-                "{} took {} s", \
-                #x, \
-                ::clp::Profiler::get_continuous_measurement_in_seconds<x>() \
-        ); \
-    }
-#define LOG_FRAGMENTED_MEASUREMENT(x) \
-    if (PROF_ENABLED \
-        && ::clp::Profiler::cFragmentedMeasurementEnabled[enum_to_underlying_type(x)]) \
-    { \
-        SPDLOG_INFO( \
-                "{} took {} s", \
-                #x, \
-                ::clp::Profiler::get_fragmented_measurement_in_seconds<x>() \
-        ); \
-    }
-#define PROFILER_SPDLOG_INFO(...) \
-    if (PROF_ENABLED) { \
-        SPDLOG_INFO(__VA_ARGS__); \
-    }
-
 #endif  // CLP_PROFILER_HPP