diff --git a/components/core/CMakeLists.txt b/components/core/CMakeLists.txt index c27c8fc877..0bbcc1ce9b 100644 --- a/components/core/CMakeLists.txt +++ b/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() diff --git a/components/core/src/clp/Profiler.cpp b/components/core/src/clp/Profiler.cpp index 784fbdd613..bc64a07e92 100644 --- a/components/core/src/clp/Profiler.cpp +++ b/components/core/src/clp/Profiler.cpp @@ -1,11 +1,9 @@ #include "Profiler.hpp" -#include - -using std::unique_ptr; using std::vector; namespace clp { -vector* Profiler::m_fragmented_measurements = nullptr; -vector* Profiler::m_continuous_measurements = nullptr; +std::unordered_map Profiler::m_runtime_measurements; +vector* Profiler::m_compile_time_measurements = nullptr; +bool Profiler::m_initialized = false; } // namespace clp diff --git a/components/core/src/clp/Profiler.hpp b/components/core/src/clp/Profiler.hpp index 68500a219b..67e0f07e85 100644 --- a/components/core/src/clp/Profiler.hpp +++ b/components/core/src/clp/Profiler.hpp @@ -1,9 +1,19 @@ #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 +#include +#include #include +#include + #include "Stopwatch.hpp" #include "type_utils.hpp" @@ -11,129 +21,171 @@ 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 fragmented 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 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 enabled{}; + static constexpr auto cMeasurementEnabled = []() { + std::array enabled{}; return enabled; }(); // Methods /** - * Static initializer for class. This must be called before using the class. + * Static initializer for class. This must be called before using compile-time measurements. + * This is meant to be process lifetime storage, so the vector is never freed. */ static void init() { - if constexpr (PROF_ENABLED) { - m_continuous_measurements = new std::vector( - enum_to_underlying_type(ContinuousMeasurementIndex::Length) - ); - m_fragmented_measurements = new std::vector( - enum_to_underlying_type(FragmentedMeasurementIndex::Length) + if constexpr (PROF_ACTIVE) { + if (m_initialized) { + return; + } + m_initialized = true; + m_compile_time_measurements = new std::vector( + enum_to_underlying_type(CompileTimeMeasurementIndex::Length) ); } } - template - 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) { + static bool s_logged{false}; + if (false == s_logged) { + s_logged = true; + SPDLOG_ERROR("Profiler used without calling Profiler::init()"); + } + } + return m_initialized; } + return false; } - template - 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)) { + static std::unordered_set s_logged_names; + if (false == s_logged_names.contains(name)) { + s_logged_names.insert(name); + SPDLOG_ERROR("Attempt to get non-existent runtime measurement: {}", name); + } + return false; + } + return true; } + return false; } - template - 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 - 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 - 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 const& { + return m_runtime_measurements; + } + + template + 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 - 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 + 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 - static double get_fragmented_measurement_in_seconds() { - if constexpr (PROF_ENABLED) { - return (*m_fragmented_measurements)[enum_to_underlying_type(index)] + template + 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 + 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; @@ -141,37 +193,9 @@ class Profiler { } private: - static std::vector* m_fragmented_measurements; - static std::vector* m_continuous_measurements; + static std::unordered_map m_runtime_measurements; + static std::vector* 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() \ - ); \ - } -#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() \ - ); \ - } -#define PROFILER_SPDLOG_INFO(...) \ - if (PROF_ENABLED) { \ - SPDLOG_INFO(__VA_ARGS__); \ - } - #endif // CLP_PROFILER_HPP diff --git a/components/core/src/clp/ProfilerReporter.hpp b/components/core/src/clp/ProfilerReporter.hpp new file mode 100644 index 0000000000..c4c5b28112 --- /dev/null +++ b/components/core/src/clp/ProfilerReporter.hpp @@ -0,0 +1,94 @@ +#ifndef CLP_PROFILER_REPORTER_HPP +#define CLP_PROFILER_REPORTER_HPP + +#include +#include +#include + +#include + +#include "Profiler.hpp" +#include "Stopwatch.hpp" + +namespace clp { +/** + * RAII helper for automatically reporting all runtime measurements at scope exit. + * + * This class is designed to simplify the reporting of runtime measurements captured using the + * `Profiler` class. + * + * Features: + * - Prints runtime measurements (total time, call count, average time) when the object is + * destructed. This is the default behavior if no sink is provided in the constructor. + * - Can write measurements to a user provided sink when the object is destructed. + * - The sink will be cleared before reporting. + * - Printing will not occur if writing to a sink. + * - Supports disabling certain scopes so neither printed nor written to sink. + * + * Usage: + * - Define a `ProfilerReporter` at any logical unit that encompasses all operations you want to + * profile. A common place is in the `main()` function of an executable. + * - If `ScopedProfiler` or `Profiler` is used in the same scope as `ProfilerReporter`, + * `ProfilerReporter` must be declared first, such that its destructor is called last. + * - Once the object is destructed (scope exit), the runtime measurments are reported. + * + * Notes: + * - Only runtime measurements (those tracked by string names) are reported. This class is + * primarily designed to work in tandem with the `ScopedProfiler` class. + * - Copy and move operations are removed to prevent accidental multiple reporting. + */ +class ProfilerReporter { +public: + explicit ProfilerReporter(std::unordered_set disabled_scopes = {}) { + set_disabled_scopes(std::move(disabled_scopes)); + } + + explicit ProfilerReporter( + std::unordered_map& sink, + std::unordered_set disabled_scopes = {} + ) + : m_sink(&sink) { + set_disabled_scopes(std::move(disabled_scopes)); + } + + ~ProfilerReporter() { + if (nullptr != m_sink) { + m_sink->clear(); + for (auto const& [name, stopwatch] : Profiler::get_runtime_measurements()) { + if (false == m_disabled_scopes.contains(name)) { + m_sink->insert({name, stopwatch}); + } + } + return; + } + + SPDLOG_INFO("---MEASUREMENTS START---"); + for (auto const& [name, stopwatch] : Profiler::get_runtime_measurements()) { + if (m_disabled_scopes.contains(name)) { + continue; + } + auto total{stopwatch.get_time_taken_in_seconds()}; + auto calls{stopwatch.get_call_count()}; + auto avg{calls > 0 ? total / calls : 0.0}; + + SPDLOG_INFO("{}: total {:.3f} s | calls {} | avg {:.3f} s", name, total, calls, avg); + } + SPDLOG_INFO("----MEASUREMENTS END----"); + } + + ProfilerReporter(ProfilerReporter const&) = delete; + ProfilerReporter& operator=(ProfilerReporter const&) = delete; + ProfilerReporter(ProfilerReporter&&) = delete; + ProfilerReporter& operator=(ProfilerReporter&&) = delete; + +private: + auto set_disabled_scopes(std::unordered_set disabled_scopes) -> void { + m_disabled_scopes = std::move(disabled_scopes); + } + + std::unordered_map* m_sink{nullptr}; + std::unordered_set m_disabled_scopes; +}; +} // namespace clp + +#endif // CLP_PROFILER_REPORTER_HPP diff --git a/components/core/src/clp/ScopedProfiler.hpp b/components/core/src/clp/ScopedProfiler.hpp new file mode 100644 index 0000000000..e663531aba --- /dev/null +++ b/components/core/src/clp/ScopedProfiler.hpp @@ -0,0 +1,53 @@ +#ifndef CLP_SCOPED_PROFILER_HPP +#define CLP_SCOPED_PROFILER_HPP + +#include + +#include "Profiler.hpp" + +namespace clp { +/** + * RAII wrapper to measure the execution time of a code scope. + * + * This class starts a runtime measurement in its constructor and stops it in its destructor. It + * reports the measured time to the corresponding slot in the profiler. Use this class when you want + * to measure a single logical phase of your program (e.g., a method) without calling start/stop. + * + * Usage for a logical phase: + * - Use macro PROFILE_SCOPE(`name`) at the top of the logical phase, ideally this is always done + * at the top of a method for organization and clarity. + * - Set `DPROF_ENABLED=1` in `cmakelists`. + * + * Notes: + * - Safe with early returns and exceptions because stopping occurs in the destructor. + * - All measurements respect `PROF_ENABLED`, so no code is generated when profiling is disabled. + */ +class ScopedProfiler { +public: + ScopedProfiler(std::string const& name) : m_name(name) { + Profiler::start_runtime_measurement(name); + } + + ~ScopedProfiler() { Profiler::stop_runtime_measurement(m_name); } + + ScopedProfiler(ScopedProfiler const&) = delete; + ScopedProfiler& operator=(ScopedProfiler const&) = delete; + ScopedProfiler(ScopedProfiler&&) = delete; + ScopedProfiler& operator=(ScopedProfiler&&) = delete; + +private: + std::string m_name; +}; +} // namespace clp + +#define CLP_CONCAT_IMPL(x, y) x##y + +#define CLP_CONCAT(x, y) CLP_CONCAT_IMPL(x, y) + +#if PROF_ACTIVE + #define PROFILE_SCOPE(x) ::clp::ScopedProfiler CLP_CONCAT(__clp_profile_scope_, __LINE__)(x) +#else + #define PROFILE_SCOPE(x) ((void)0) +#endif + +#endif // CLP_SCOPED_PROFILER_HPP diff --git a/components/core/src/clp/Stopwatch.cpp b/components/core/src/clp/Stopwatch.cpp index 4c645b2025..b97deb71d6 100644 --- a/components/core/src/clp/Stopwatch.cpp +++ b/components/core/src/clp/Stopwatch.cpp @@ -1,5 +1,8 @@ #include "Stopwatch.hpp" +#include +#include + namespace clp { Stopwatch::Stopwatch() { reset(); @@ -14,14 +17,21 @@ void Stopwatch::stop() { auto time_taken = end - m_begin; m_time_taken += time_taken; + + m_call_count++; } void Stopwatch::reset() { m_time_taken = std::chrono::steady_clock::duration::zero(); + m_call_count = 0; } -double Stopwatch::get_time_taken_in_seconds() { +auto Stopwatch::get_time_taken_in_seconds() const -> double { std::chrono::duration time_taken_in_seconds = m_time_taken; return time_taken_in_seconds.count(); } + +auto Stopwatch::get_call_count() const -> uint32_t { + return m_call_count; +} } // namespace clp diff --git a/components/core/src/clp/Stopwatch.hpp b/components/core/src/clp/Stopwatch.hpp index 0b87911ebb..4002e02e7f 100644 --- a/components/core/src/clp/Stopwatch.hpp +++ b/components/core/src/clp/Stopwatch.hpp @@ -2,8 +2,7 @@ #define CLP_STOPWATCH_HPP #include -#include -#include +#include namespace clp { class Stopwatch { @@ -16,12 +15,15 @@ class Stopwatch { void stop(); void reset(); - double get_time_taken_in_seconds(); + [[nodiscard]] auto get_time_taken_in_seconds() const -> double; + + [[nodiscard]] auto get_call_count() const -> uint32_t; private: // Variables std::chrono::time_point m_begin; std::chrono::duration m_time_taken; + uint32_t m_call_count{0}; }; } // namespace clp diff --git a/components/core/src/clp/clg/clg.cpp b/components/core/src/clp/clg/clg.cpp index 7122a948a4..a7a1f90e33 100644 --- a/components/core/src/clp/clg/clg.cpp +++ b/components/core/src/clp/clg/clg.cpp @@ -13,6 +13,8 @@ #include "../Grep.hpp" #include "../GrepCore.hpp" #include "../Profiler.hpp" +#include "../ProfilerReporter.hpp" +#include "../ScopedProfiler.hpp" #include "../spdlog_with_specializations.hpp" #include "../streaming_archive/Constants.hpp" #include "../Utils.hpp" @@ -31,6 +33,7 @@ using clp::GrepCore; using clp::load_lexer_from_file; using clp::logtype_dictionary_id_t; using clp::Profiler; +using clp::ProfilerReporter; using clp::Query; using clp::segment_id_t; using clp::streaming_archive::MetadataDB; @@ -475,6 +478,9 @@ static void print_result_binary( } int main(int argc, char const* argv[]) { + ProfilerReporter profiler_reporter; + PROFILE_SCOPE("clg::main"); + // Program-wide initialization try { auto stderr_logger = spdlog::stderr_logger_st("stderr"); @@ -484,7 +490,6 @@ int main(int argc, char const* argv[]) { // NOTE: We can't log an exception if the logger couldn't be constructed return -1; } - Profiler::init(); clp::TimestampPattern::init(); CommandLineArguments command_line_args("clg"); @@ -499,8 +504,6 @@ int main(int argc, char const* argv[]) { break; } - Profiler::start_continuous_measurement(); - auto add_implicit_wildcards = [](string const& search_string) -> string { return clean_up_wildcard_search_string('*' + search_string + '*'); }; @@ -612,9 +615,5 @@ int main(int argc, char const* argv[]) { } global_metadata_db->close(); - - Profiler::stop_continuous_measurement(); - LOG_CONTINUOUS_MEASUREMENT(Profiler::ContinuousMeasurementIndex::Search) - return 0; } diff --git a/components/core/src/clp/clo/clo.cpp b/components/core/src/clp/clo/clo.cpp index 94b9e793b6..a315275be0 100644 --- a/components/core/src/clp/clo/clo.cpp +++ b/components/core/src/clp/clo/clo.cpp @@ -15,7 +15,7 @@ #include "../Grep.hpp" #include "../GrepCore.hpp" #include "../ir/constants.hpp" -#include "../Profiler.hpp" +#include "../ProfilerReporter.hpp" #include "../spdlog_with_specializations.hpp" #include "../Utils.hpp" #include "CommandLineArguments.hpp" @@ -42,6 +42,7 @@ using clp::GrepCore; using clp::ir::cIrFileExtension; using clp::load_lexer_from_file; using clp::logtype_dictionary_id_t; +using clp::ProfilerReporter; using clp::Query; using clp::segment_id_t; using clp::streaming_archive::MetadataDB; @@ -571,6 +572,8 @@ static bool search_archive( } int main(int argc, char const* argv[]) { + ProfilerReporter profiler_reporter; + // Program-wide initialization try { auto stderr_logger = spdlog::stderr_logger_st("stderr"); @@ -580,7 +583,6 @@ int main(int argc, char const* argv[]) { // NOTE: We can't log an exception if the logger couldn't be constructed return -1; } - clp::Profiler::init(); clp::TimestampPattern::init(); CommandLineArguments command_line_args("clo"); diff --git a/components/core/src/clp/clp/CMakeLists.txt b/components/core/src/clp/clp/CMakeLists.txt index 3bc229137b..e23369a06c 100644 --- a/components/core/src/clp/clp/CMakeLists.txt +++ b/components/core/src/clp/clp/CMakeLists.txt @@ -91,12 +91,14 @@ set( ../Platform.hpp ../Profiler.cpp ../Profiler.hpp + ../ProfilerReporter.hpp ../Query.cpp ../Query.hpp ../ReaderInterface.cpp ../ReaderInterface.hpp ../ReadOnlyMemoryMappedFile.cpp ../ReadOnlyMemoryMappedFile.hpp + ../ScopedProfiler.hpp ../spdlog_with_specializations.hpp ../SQLiteDB.cpp ../SQLiteDB.hpp diff --git a/components/core/src/clp/clp/FileCompressor.cpp b/components/core/src/clp/clp/FileCompressor.cpp index b685b22ac9..631aadf577 100644 --- a/components/core/src/clp/clp/FileCompressor.cpp +++ b/components/core/src/clp/clp/FileCompressor.cpp @@ -18,6 +18,7 @@ #include "../ir/utils.hpp" #include "../LogSurgeonReader.hpp" #include "../Profiler.hpp" +#include "../ScopedProfiler.hpp" #include "../streaming_archive/writer/utils.hpp" #include "../utf8_utils.hpp" #include "utils.hpp" @@ -122,10 +123,7 @@ bool FileCompressor::compress_file( streaming_archive::writer::Archive& archive_writer, bool use_heuristic ) { - string file_name = std::filesystem::canonical(file_to_compress.get_path()).string(); - - PROFILER_SPDLOG_INFO("Start parsing {}", file_name) - Profiler::start_continuous_measurement(); + PROFILE_SCOPE("FileCompressor::compress_file"); BufferedReader buffered_file_reader{make_unique(file_to_compress.get_path())}; @@ -179,11 +177,6 @@ bool FileCompressor::compress_file( succeeded = false; } } - - Profiler::stop_continuous_measurement(); - LOG_CONTINUOUS_MEASUREMENT(Profiler::ContinuousMeasurementIndex::ParseLogFile) - PROFILER_SPDLOG_INFO("Done parsing {}", file_name) - return succeeded; } diff --git a/components/core/src/clp/clp/run.cpp b/components/core/src/clp/clp/run.cpp index e1e73bf11f..b0f5dac153 100644 --- a/components/core/src/clp/clp/run.cpp +++ b/components/core/src/clp/clp/run.cpp @@ -5,7 +5,8 @@ #include #include -#include "../Profiler.hpp" +#include "../ProfilerReporter.hpp" +#include "../ScopedProfiler.hpp" #include "../spdlog_with_specializations.hpp" #include "../Utils.hpp" #include "CommandLineArguments.hpp" @@ -13,12 +14,16 @@ #include "decompression.hpp" #include "utils.hpp" +using clp::ProfilerReporter; using std::string; using std::unordered_set; using std::vector; namespace clp::clp { int run(int argc, char const* argv[]) { + ProfilerReporter profiler_reporter; + PROFILE_SCOPE("clp::main"); + // Program-wide initialization try { auto stderr_logger = spdlog::stderr_logger_st("stderr"); @@ -28,7 +33,6 @@ int run(int argc, char const* argv[]) { // NOTE: We can't log an exception if the logger couldn't be constructed return -1; } - Profiler::init(); TimestampPattern::init(); CommandLineArguments command_line_args("clp"); @@ -45,8 +49,6 @@ int run(int argc, char const* argv[]) { vector input_paths = command_line_args.get_input_paths(); - Profiler::start_continuous_measurement(); - // Read input paths from file if necessary if (false == command_line_args.get_path_list_path().empty()) { if (false == read_input_paths(command_line_args.get_path_list_path(), input_paths)) { @@ -173,10 +175,6 @@ int run(int argc, char const* argv[]) { SPDLOG_ERROR("Command {} not implemented.", enum_to_underlying_type(command)); return -1; } - - Profiler::stop_continuous_measurement(); - LOG_CONTINUOUS_MEASUREMENT(Profiler::ContinuousMeasurementIndex::Compression) - return 0; } } // namespace clp::clp diff --git a/components/core/tests/test-ProfilerReporter.cpp b/components/core/tests/test-ProfilerReporter.cpp new file mode 100644 index 0000000000..c8735d9fd3 --- /dev/null +++ b/components/core/tests/test-ProfilerReporter.cpp @@ -0,0 +1,96 @@ +#include +#include +#include +#include + +#include + +#include +#include +#include +#include + +using clp::Profiler; +using clp::ProfilerReporter; +using clp::ScopedProfiler; +using clp::Stopwatch; +using std::string; +using std::unordered_map; + +using Sink = unordered_map; +using ExpectedSink = unordered_map>; + +constexpr double cTimerMarginOfError{0.1}; + +auto check_sink(Sink const& actual_sink, ExpectedSink const& expected_sink) { + for (auto const& [name, expected] : expected_sink) { + auto expected_time{expected.first}; + auto expected_calls{expected.second}; + + REQUIRE(actual_sink.contains(name)); + auto const actual_time{actual_sink.at(name).get_time_taken_in_seconds()}; + auto const actual_calls{actual_sink.at(name).get_call_count()}; + REQUIRE(actual_time >= expected_time); + REQUIRE(actual_time < expected_time + cTimerMarginOfError); + REQUIRE(actual_calls == expected_calls); + } +} + +TEST_CASE("profiler_reporter_reports_runtime_measurements", "[ProfilerReporter][Stopwatch]") { + Sink sink0; + Sink sink1; + Sink sink2; + Sink sink3; + + Profiler::reset_runtime_measurements(); + { + ProfilerReporter profiler0(sink0); + PROFILE_SCOPE("scope0"); + + { + ProfilerReporter profiler1(sink1); + PROFILE_SCOPE("scope1"); + std::this_thread::sleep_for(std::chrono::milliseconds(10)); + } + + { + ProfilerReporter profiler2(sink2); + PROFILE_SCOPE("scope2"); + std::this_thread::sleep_for(std::chrono::milliseconds(20)); + } + + { + ProfilerReporter profiler3(sink3); + PROFILE_SCOPE("scope2"); + std::this_thread::sleep_for(std::chrono::milliseconds(50)); + } + + std::this_thread::sleep_for(std::chrono::milliseconds(100)); + } + + check_sink(sink1, {{"scope0", {0, 0}}, {"scope1", {0.01, 1}}}); + check_sink(sink2, {{"scope0", {0, 0}}, {"scope1", {0.01, 1}}, {"scope2", {0.02, 1}}}); + check_sink(sink3, {{"scope0", {0, 0}}, {"scope1", {0.01, 1}}, {"scope2", {0.07, 2}}}); + check_sink(sink0, {{"scope0", {0.18, 1}}, {"scope1", {0.01, 1}}, {"scope2", {0.07, 2}}}); +} + +TEST_CASE("profiler_reporter_respects_disable_scopes", "[ProfilerReporter][Stopwatch]") { + Sink sink; + + Profiler::reset_runtime_measurements(); + { + ProfilerReporter profiler(sink, {"scope1"}); + + PROFILE_SCOPE("scope0"); + std::this_thread::sleep_for(std::chrono::milliseconds(10)); + + PROFILE_SCOPE("scope1"); + std::this_thread::sleep_for(std::chrono::milliseconds(20)); + + PROFILE_SCOPE("scope2"); + std::this_thread::sleep_for(std::chrono::milliseconds(30)); + } + + REQUIRE_FALSE(sink.contains("scope1")); + check_sink(sink, {{"scope0", {0.01, 1}}, {"scope2", {0.03, 1}}}); +} diff --git a/components/core/tests/test-ScopedProfiler.cpp b/components/core/tests/test-ScopedProfiler.cpp new file mode 100644 index 0000000000..c528dd8166 --- /dev/null +++ b/components/core/tests/test-ScopedProfiler.cpp @@ -0,0 +1,72 @@ +#include +#include + +#include + +#include +#include +#include + +using clp::Profiler; +using clp::ScopedProfiler; + +constexpr auto cName{"ProfileName"}; + +TEST_CASE("macro_is_set", "[ScopedProfiler]") { + REQUIRE(PROF_ACTIVE == 1); +} + +TEST_CASE("scoped_profiler_starts_and_stops_timer_automatically", "[ScopedProfiler][Stopwatch]") { + Profiler::init(); + Profiler::reset_runtime_measurements(); + + { + ScopedProfiler profiler(cName); + std::this_thread::sleep_for(std::chrono::milliseconds(50)); + } + + auto const measured{Profiler::get_runtime_measurement_in_seconds(cName)}; + auto const calls{Profiler::get_runtime_call_count(cName)}; + REQUIRE(measured >= 0.05); + REQUIRE(measured < 0.14); + REQUIRE(calls == 1); +} + +TEST_CASE("scoped_profiler_accumulates_across_multiple_scopes", "[ScopedProfiler][Stopwatch]") { + Profiler::init(); + Profiler::reset_runtime_measurements(); + + { + ScopedProfiler profiler(cName); + std::this_thread::sleep_for(std::chrono::milliseconds(20)); + } + + std::this_thread::sleep_for(std::chrono::milliseconds(200)); + + { + ScopedProfiler profiler(cName); + std::this_thread::sleep_for(std::chrono::milliseconds(30)); + } + + auto const measured{Profiler::get_runtime_measurement_in_seconds(cName)}; + auto const calls{Profiler::get_runtime_call_count(cName)}; + REQUIRE(measured >= 0.05); + REQUIRE(measured < 0.14); + REQUIRE(calls == 2); +} + +TEST_CASE("scoped_profiler_macro_works", "[ScopedProfiler][Stopwatch]") { + Profiler::init(); + Profiler::reset_runtime_measurements(); + + { + PROFILE_SCOPE(cName); + std::this_thread::sleep_for(std::chrono::milliseconds(50)); + } + + auto const measured{Profiler::get_runtime_measurement_in_seconds(cName)}; + auto const calls{Profiler::get_runtime_call_count(cName)}; + REQUIRE(measured >= 0.05); + REQUIRE(measured < 0.14); + REQUIRE(calls == 1); +} diff --git a/components/core/tests/test-Stopwatch.cpp b/components/core/tests/test-Stopwatch.cpp index 1a58df8661..66e0b3cb44 100644 --- a/components/core/tests/test-Stopwatch.cpp +++ b/components/core/tests/test-Stopwatch.cpp @@ -1,4 +1,5 @@ -#include +#include +#include #include @@ -15,7 +16,7 @@ TEST_CASE("Stopwatch", "[Stopwatch]") { SECTION("Test reset()") { // Measure some work stopwatch.start(); - sleep(1); + std::this_thread::sleep_for(std::chrono::milliseconds(50)); stopwatch.stop(); stopwatch.reset(); @@ -27,30 +28,30 @@ TEST_CASE("Stopwatch", "[Stopwatch]") { SECTION("Test single measurement") { // Measure some work stopwatch.start(); - sleep(1); + std::this_thread::sleep_for(std::chrono::milliseconds(50)); stopwatch.stop(); double time_taken = stopwatch.get_time_taken_in_seconds(); - REQUIRE(time_taken >= 1.0); - REQUIRE(time_taken < 1.1); + REQUIRE(time_taken >= 0.05); + REQUIRE(time_taken < 0.1); } SECTION("Test multiple measurements") { // Measure some work stopwatch.start(); - sleep(1); + std::this_thread::sleep_for(std::chrono::milliseconds(50)); stopwatch.stop(); // Do some other work - sleep(1); + std::this_thread::sleep_for(std::chrono::milliseconds(200)); // Measure some work again stopwatch.start(); - sleep(2); + std::this_thread::sleep_for(std::chrono::milliseconds(100)); stopwatch.stop(); double time_taken = stopwatch.get_time_taken_in_seconds(); - REQUIRE(time_taken >= 3.0); - REQUIRE(time_taken < 3.1); + REQUIRE(time_taken >= 0.15); + REQUIRE(time_taken < 0.25); } }