From 811cdff8d1bd7ec35ea0d67efb4c1919d5e65302 Mon Sep 17 00:00:00 2001 From: Brett Date: Sat, 4 Mar 2023 11:42:24 -0500 Subject: [PATCH] refactor profiler code is now much more clean -removed ugly nested loops -used functions to reduce code clutter and duplcation removed redundant functions cleaned up sort and improved names --- include/blt/profiling/profiler.h | 46 +++++-- src/blt/profiling/profiler.cpp | 227 +++++++++++++++---------------- src/tests/nbt_tests.h | 10 +- src/tests/profiling_tests.h | 2 - src/tests/queue_tests.h | 101 +++++++++++++- 5 files changed, 247 insertions(+), 139 deletions(-) diff --git a/include/blt/profiling/profiler.h b/include/blt/profiling/profiler.h index 2bd6748..c1054d9 100644 --- a/include/blt/profiling/profiler.h +++ b/include/blt/profiling/profiler.h @@ -12,9 +12,10 @@ #include #include #include +#include /** - * Defines several disableable macros (#define BLT_DISABLE_PROFILING). If you do not use these macros profiling will not be disableable + * Defines several disableable macros (#define BLT_DISABLE_PROFILING). If you do not use these macros profiling cannot be disabled! */ namespace blt::profiling { @@ -42,18 +43,18 @@ namespace blt::profiling { capture_interval getInterval(const std::string& profileName, const std::string& intervalName); - std::vector getAllIntervals(const std::string& profileName, const std::string& intervalName); + std::vector getAllIntervals( + const std::string& profileName, const std::string& intervalName + ); profile getProfile(const std::string& profileName); void printProfile( - const std::string& profileName, blt::logging::LOG_LEVEL loggingLevel = logging::NONE, bool averageHistory = false, - bool ignoreNegatives = true + const std::string& profileName, logging::LOG_LEVEL loggingLevel = logging::NONE, + bool averageHistory = false, bool ignoreNegatives = true ); - void printOrderedProfile( - const std::string& profileName, logging::LOG_LEVEL loggingLevel = logging::NONE, bool averageHistory = false, bool ignoreNegatives = true - ); + void writeProfile(std::ofstream& out, const std::string& profileName); void discardProfiles(); @@ -66,7 +67,8 @@ namespace blt::profiling { std::string m_Profile; std::string m_Interval; public: - scoped_interval(std::string profile, std::string interval): m_Profile(std::move(profile)), m_Interval(std::move(interval)) { + scoped_interval(std::string profile, std::string interval): + m_Profile(std::move(profile)), m_Interval(std::move(interval)) { blt::profiling::startInterval(m_Profile, m_Interval); } @@ -82,15 +84,31 @@ namespace blt::profiling { #define BLT_START_INTERVAL(profileName, intervalName) #define BLT_END_INTERVAL(profileName, intervalName) #define BLT_POINT(profileName, pointName) - #define BLT_PRINT_PROFILE(profileName, ...) #define BLT_PRINT_ORDERED(profileName, ...) + #define BLT_WRITE_ORDERED(profileName, ...) #else +/** + * Starts an interval to be measured, when ended the row will be added to the specified profile. + */ #define BLT_START_INTERVAL(profileName, intervalName) blt::profiling::startInterval(profileName, intervalName) +/** + * Ends an interval, adds the interval to the profile. + */ #define BLT_END_INTERVAL(profileName, intervalName) blt::profiling::endInterval(profileName, intervalName) +/** + * Measures this exact point in time. + */ #define BLT_POINT(profileName, pointName) blt::profiling::point(profileName, pointName) +/** + * Prints the profile order from least time to most time. + * @param profileName the profile to print + * @param loggingLevel blt::logging::LOG_LEVEL to log with (default: NONE) + * @param averageHistory use the historical collection of interval rows in an average or just the latest? (default: false) + * @param ignoreNegatives ignore negative time values (default: true) + */ #define BLT_PRINT_PROFILE(profileName, ...) blt::profiling::printProfile(profileName, ##__VA_ARGS__) - #define BLT_PRINT_ORDERED(profileName, ...) blt::profiling::printOrderedProfile(profileName, ##__VA_ARGS__) -#endif - -#define BLT_INTERVAL_START(profileName, intervalName) BLT_START_INTERVAL(profileName, intervalName) -#define BLT_INTERVAL_END(profileName, intervalName) BLT_END_INTERVAL(profileName, intervalName) \ No newline at end of file +/** + * writes the profile to an output stream, ordered from least time to most time, in CSV format. + */ + #define BLT_WRITE_PROFILE(stream, profileName) blt::profiling::writeProfile(stream, profileName, true) +#endif \ No newline at end of file diff --git a/src/blt/profiling/profiler.cpp b/src/blt/profiling/profiler.cpp index 18ccaa3..b5888eb 100644 --- a/src/blt/profiling/profiler.cpp +++ b/src/blt/profiling/profiler.cpp @@ -18,6 +18,109 @@ namespace blt::profiling { std::mutex profileLock{}; std::unordered_map profiles; + struct IntervalComparable { + long difference; + std::string name; + + IntervalComparable(long difference, std::string name): + difference(difference), name(std::move(name)) {} + }; + + inline void print(const std::vector& lines, logging::LOG_LEVEL level) { + auto& logger = logging::getLoggerFromLevel(level); + for (const auto& line : lines) + logger << line; + } + + /** + * Copy-sorts the unordered vector into the ordered vector, min -> max + */ + inline void orderIntervals( + const std::unordered_map& unordered, + std::vector& ordered + ) { + // copy + for (const auto& i : unordered) + ordered.emplace_back(i.second.end - i.second.start, i.first); + + // sort + std::sort( + ordered.begin(), ordered.end(), + [&](const IntervalComparable& c1, const IntervalComparable& c2) -> bool { + return c1.difference < c2.difference; + } + ); + } + + inline void averageIntervals( + const std::unordered_map>& intervals, + std::unordered_map& averagedIntervals + ) { + for (const auto& i : intervals) { + const auto& name = i.first; + const auto& interval_vec = i.second; + long total_difference = 0; + + for (const auto& value : interval_vec) + total_difference += value.end - value.start; + + total_difference /= (long)interval_vec.size(); + + std::string new_name = "("; + new_name += std::to_string(interval_vec.size()); + new_name += ") "; + new_name += name; + + // can exploit how the order func works by supplying the difference into end, + // which sorts correctly despite not being a true interval. + averagedIntervals.insert({new_name, capture_interval{0, total_difference}}); + } + } + + void writeProfile(std::ofstream& out, const std::string& profileName, bool ordered) { + + } + + void printProfile( + const std::string& profileName, logging::LOG_LEVEL loggingLevel, bool averageHistory, + bool ignoreNegatives + ) { + auto& profile = profiles[profileName]; + const auto& intervals = profile.intervals; + const auto& points = profile.points; + + std::vector ordered_vector; + std::unordered_map averaged_intervals; + + if (averageHistory) + averageIntervals(profile.historicalIntervals, averaged_intervals); + + orderIntervals(averageHistory ? averaged_intervals : intervals, ordered_vector); + + string::TableFormatter formatter{profileName}; + formatter.addColumn({"Order"}); + formatter.addColumn({"Interval"}); + formatter.addColumn({"Time (ns)"}); + formatter.addColumn({"Time (ms)"}); + + int index = 1; + for (const auto& interval : ordered_vector) { + formatter.addRow( + {std::to_string(index++), interval.name, std::to_string(interval.difference), + std::to_string((double)interval.difference / 1000000.0)} + ); + } + + std::vector updatedLines; + const auto& lines = formatter.createTable(true, true); + for (const auto& line : lines) + updatedLines.emplace_back(line + "\n"); + + print(updatedLines, loggingLevel); + } + +// --- small helper functions below --- + void startInterval(const std::string& profileName, const std::string& intervalName) { std::scoped_lock lock(profileLock); capture_interval interval{}; @@ -28,7 +131,9 @@ namespace blt::profiling { void endInterval(const std::string& profileName, const std::string& intervalName) { std::scoped_lock lock(profileLock); profiles[profileName].intervals[intervalName].end = system::getCurrentTimeNanoseconds(); - profiles[profileName].historicalIntervals[intervalName].push_back(profiles[profileName].intervals[intervalName]); + profiles[profileName].historicalIntervals[intervalName].push_back( + profiles[profileName].intervals[intervalName] + ); } void point(const std::string& profileName, const std::string& pointName) { @@ -47,121 +152,6 @@ namespace blt::profiling { return profiles[profileName]; } - inline void print(const std::vector& lines, logging::LOG_LEVEL level) { - auto& logger = logging::getLoggerFromLevel(level); - for (const auto& line : lines) - logger << line; - } - - void printProfile(const std::string& profileName, blt::logging::LOG_LEVEL loggingLevel, bool averageHistory, bool ignoreNegatives) { - string::TableFormatter formatter{profileName}; - formatter.addColumn({"Interval"}); - formatter.addColumn({"Time (ns)"}); - formatter.addColumn({"Time (ms)"}); - - auto& profile = profiles[profileName]; - const auto& intervals = profile.intervals; - const auto& points = profile.points; - - for (const auto& interval : intervals) { - if (averageHistory) { - const auto& history = profile.historicalIntervals[interval.first]; - long total_difference = 0; - for (const auto& h_interval : history) { - const auto difference = h_interval.end - h_interval.start; - if (ignoreNegatives && difference < 0) - continue; - total_difference += difference; - } - total_difference /= (long) history.size(); - std::string name = "("; - name += std::to_string(history.size()); - name += ") "; - name += interval.first; - formatter.addRow({name, std::to_string(total_difference), std::to_string((double) total_difference / 1000000.0)}); - } else { - const auto difference = interval.second.end - interval.second.start; - if (ignoreNegatives && difference < 0) - continue; - formatter.addRow({interval.first, std::to_string(difference), std::to_string((double) difference / 1000000.0)}); - } - } - - std::vector updatedLines; - const auto& lines = formatter.createTable(true, true); - for (const auto& line : lines) - updatedLines.emplace_back(line + "\n"); - - print(updatedLines, loggingLevel); - } - - struct timeOrderContainer { - long difference; - std::string name; - - timeOrderContainer(long difference, std::string name): difference(difference), name(std::move(name)) {} - }; - - inline bool timeCompare(const timeOrderContainer& container1, const timeOrderContainer& container2) { - return container1.difference < container2.difference; - } - - void printOrderedProfile(const std::string& profileName, logging::LOG_LEVEL loggingLevel, bool averageHistory, bool ignoreNegatives) { - auto& profile = profiles[profileName]; - const auto& intervals = profile.intervals; - const auto& points = profile.points; - - std::vector unorderedIntervalVector; - - // TODO: refactor to reduce nesting - - for (const auto& interval : intervals) { - if (averageHistory) { - const auto& history = profile.historicalIntervals[interval.first]; - long total_difference = 0; - for (const auto& h_interval : history) { - const auto difference = h_interval.end - h_interval.start; - if (ignoreNegatives && difference < 0) - continue; - total_difference += difference; - } - total_difference /= (long) history.size(); - std::string name = "("; - name += std::to_string(history.size()); - name += ") "; - name += interval.first; - unorderedIntervalVector.emplace_back(total_difference, name); - } else { - const auto difference = interval.second.end - interval.second.start; - if (ignoreNegatives && difference < 0) - continue; - unorderedIntervalVector.emplace_back(difference, interval.first); - } - } - - std::sort(unorderedIntervalVector.begin(), unorderedIntervalVector.end(), timeCompare); - - string::TableFormatter formatter{profileName}; - formatter.addColumn({"Order"}); - formatter.addColumn({"Interval"}); - formatter.addColumn({"Time (ns)"}); - formatter.addColumn({"Time (ms)"}); - - int index = 1; - for (const auto& interval : unorderedIntervalVector) { - formatter.addRow( - {std::to_string(index++), interval.name, std::to_string(interval.difference), std::to_string(interval.difference / 1000000.0)} - ); - } - - std::vector updatedLines; - const auto& lines = formatter.createTable(true, true); - for (const auto& line : lines) - updatedLines.emplace_back(line + "\n"); - - print(updatedLines, loggingLevel); - } - void discardProfiles() { profiles = {}; } @@ -175,7 +165,10 @@ namespace blt::profiling { profiles[profileName].points = {}; } - std::vector getAllIntervals(const std::string& profileName, const std::string& intervalName) { + std::vector getAllIntervals( + const std::string& profileName, const std::string& intervalName + ) { return profiles[profileName].historicalIntervals[intervalName]; } + } \ No newline at end of file diff --git a/src/tests/nbt_tests.h b/src/tests/nbt_tests.h index efa3295..1f3857f 100644 --- a/src/tests/nbt_tests.h +++ b/src/tests/nbt_tests.h @@ -112,11 +112,11 @@ inline void nbt_read_tests(){ BLT_INFO("NBT Block %s Stream Correctly? %s;\n", size_str.c_str(), nbt_block_large_correct ? "True" : "False"); } - BLT_PRINT_ORDERED("nbt read"); + BLT_PRINT_PROFILE("nbt read"); BLT_TRACE("{BLANK_LINE}"); - BLT_PRINT_ORDERED("nbt read block"); + BLT_PRINT_PROFILE("nbt read block"); BLT_TRACE("{BLANK_LINE}"); - BLT_PRINT_ORDERED("nbt read individual"); + BLT_PRINT_PROFILE("nbt read individual"); delete[] read_buffer; delete[] read_block_buffer; @@ -177,9 +177,9 @@ inline void nbt_write_tests(){ BLT_INFO("NBT %s Individual Write Correctly? %s;\n", size_str.c_str(), results ? "True" : "False"); } - BLT_PRINT_ORDERED("nbt write individual"); + BLT_PRINT_PROFILE("nbt write individual"); BLT_TRACE(""); - BLT_PRINT_ORDERED("nbt write block"); + BLT_PRINT_PROFILE("nbt write block"); } inline void nbt_tests(){ diff --git a/src/tests/profiling_tests.h b/src/tests/profiling_tests.h index 11cfb55..05852dc 100644 --- a/src/tests/profiling_tests.h +++ b/src/tests/profiling_tests.h @@ -40,8 +40,6 @@ static void runProfilingAndTableTests() { BLT_PRINT_PROFILE("Help", blt::logging::LOG_LEVEL::TRACE); BLT_TRACE(""); - BLT_PRINT_ORDERED("Help", blt::logging::LOG_LEVEL::TRACE); - BLT_TRACE(""); blt::string::TableFormatter formatter; formatter.addColumn(blt::string::TableColumn{"Test1"}); diff --git a/src/tests/queue_tests.h b/src/tests/queue_tests.h index cfcaba3..b7e83a0 100644 --- a/src/tests/queue_tests.h +++ b/src/tests/queue_tests.h @@ -8,10 +8,109 @@ #define BLT_TESTS_QUEUE_TESTS_H #include +#include #include +#include +#include +#include -static inline void test_queues(){ +std::array values{}; +std::queue base_queue{}; +blt::flat_queue blt_flat_queue{}; +blt::flat_stack blt_flat_stack{}; +blt::node_queue blt_node_queue{}; + +static inline void fill_queues(){ + BLT_START_INTERVAL("Insert", "std::queue"); + for (const auto& value : values) + base_queue.push(value); + BLT_END_INTERVAL("Insert", "std::queue"); + + BLT_START_INTERVAL("Insert", "blt::flat_queue"); + for (const auto& value : values) + blt_flat_queue.push(value); + BLT_END_INTERVAL("Insert", "blt::flat_queue"); + + BLT_START_INTERVAL("Insert", "blt::flat_stack"); + for (const auto& value : values) + blt_flat_stack.push(value); + BLT_END_INTERVAL("Insert", "blt::flat_stack"); + + BLT_START_INTERVAL("Insert", "blt::node_queue"); + for (const auto& value : values) + blt_node_queue.push(value); + BLT_END_INTERVAL("Insert", "blt::node_queue"); +} + +static inline void validate(){ + bool std_valid = true; + bool flat_valid = true; + bool node_valid = true; + bool stack_valid = true; + BLT_START_INTERVAL("Access", "std::queue"); + for (const auto& value : values) { + auto front = base_queue.front(); + + if (front != value) + std_valid = false; + base_queue.pop(); + } + BLT_END_INTERVAL("Access", "std::queue"); + + BLT_START_INTERVAL("Access", "blt::flat_queue"); + for (const auto& value : values) { + auto front = blt_flat_queue.front(); + + if (front != value) + flat_valid = false; + blt_flat_queue.pop(); + } + BLT_END_INTERVAL("Access", "blt::flat_queue"); + + BLT_START_INTERVAL("Access", "blt::flat_stack"); + for (const auto& value : values) { + auto front = blt_flat_stack.top(); + + if (front != value) + stack_valid = false; + blt_flat_stack.pop(); + } + BLT_END_INTERVAL("Access", "blt::flat_stack"); + + BLT_START_INTERVAL("Access", "blt::node_queue"); + for (const auto& value : values) { + auto front = blt_node_queue.front(); + + if (front != value) + node_valid = false; + blt_node_queue.pop(); + } + BLT_END_INTERVAL("Access", "blt::node_queue"); + + if (!std_valid) + BLT_ERROR("std::queue invalid!"); + if (!flat_valid) + BLT_ERROR("blt::flat_queue invalid!"); + if (!node_valid) + BLT_ERROR("blt::node_queue invalid!"); + if (!stack_valid) + BLT_ERROR("blt::stack invalid!"); +} + +static inline void test_queues() { + blt::random rand{1, std::numeric_limits::max()}; + + for (int& value : values){ + value = rand.get(); + } + + fill_queues(); + validate(); + + + BLT_PRINT_PROFILE("Insert", blt::logging::LOG_LEVEL::INFO, true); + BLT_PRINT_PROFILE("Access", blt::logging::LOG_LEVEL::INFO, true); } #endif //BLT_TESTS_QUEUE_TESTS_H