diff --git a/CMakeLists.txt b/CMakeLists.txt index 2f4e273..c51779d 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -49,6 +49,7 @@ set(PRJ_HEADERS include/TServer.h include/VehicleData.h include/Env.h + include/Profiling.h ) # add all source files (.cpp) to this, except the one with main() set(PRJ_SOURCES @@ -72,6 +73,7 @@ set(PRJ_SOURCES src/TServer.cpp src/VehicleData.cpp src/Env.cpp + src/Profiling.cpp ) find_package(Lua REQUIRED) diff --git a/include/Profiling.h b/include/Profiling.h new file mode 100644 index 0000000..c0b23c8 --- /dev/null +++ b/include/Profiling.h @@ -0,0 +1,72 @@ +#pragma once + +#include +#include +#include +#include +#include + +namespace prof { + +using Duration = std::chrono::duration; +using TimePoint = std::chrono::high_resolution_clock::time_point; + +/// Returns the current time. +TimePoint now(); + +/// Returns a sub-millisecond resolution duration between start and end. +Duration duration(const TimePoint& start, const TimePoint& end); + +struct Stats { + double mean; + double stdev; + double min; + double max; + size_t n; +}; + +/// Calculates and stores the moving average over K samples of execution time data +/// for some single unit of code. Threadsafe. +struct UnitExecutionTime { + UnitExecutionTime(); + + /// Adds a sample to the collection, overriding the oldest sample if needed. + void add_sample(const Duration& dur); + + /// Calculates the mean duration over the `measurement_count()` measurements, + /// as well as the standard deviation. + Stats stats() const; + + /// Returns the number of elements the moving average is calculated over. + size_t measurement_count() const; + +private: + mutable std::mutex m_mtx {}; + size_t m_total_calls {}; + double m_sum {}; + // sum of measurements squared (for running stdev) + double m_measurement_sqr_sum {}; + double m_min { std::numeric_limits::max() }; + double m_max { std::numeric_limits::min() }; +}; + +/// Holds profiles for multiple units by name. Threadsafe. +struct UnitProfileCollection { + /// Adds a sample to the collection, overriding the oldest sample if needed. + void add_sample(const std::string& unit, const Duration& duration); + + /// Calculates the mean duration over the `measurement_count()` measurements, + /// as well as the standard deviation. + Stats stats(const std::string& unit); + + /// Returns the number of elements the moving average is calculated over. + size_t measurement_count(const std::string& unit); + + /// Returns the stats for all stored units. + std::unordered_map all_stats(); + +private: + boost::synchronized_value> m_map; +}; + +} diff --git a/include/TLuaEngine.h b/include/TLuaEngine.h index b4c14b0..a6c8c8f 100644 --- a/include/TLuaEngine.h +++ b/include/TLuaEngine.h @@ -18,9 +18,11 @@ #pragma once +#include "Profiling.h" #include "TNetwork.h" #include "TServer.h" #include +#include #include #include #include @@ -253,6 +255,9 @@ private: sol::table Lua_FS_ListFiles(const std::string& Path); sol::table Lua_FS_ListDirectories(const std::string& Path); + prof::UnitProfileCollection mProfile {}; + std::unordered_map mProfileStarts; + std::string mName; TLuaStateId mStateId; lua_State* mState; diff --git a/src/Profiling.cpp b/src/Profiling.cpp new file mode 100644 index 0000000..f6a41d8 --- /dev/null +++ b/src/Profiling.cpp @@ -0,0 +1,60 @@ +#include "Profiling.h" +#include + +prof::Duration prof::duration(const TimePoint& start, const TimePoint& end) { + return end - start; +} +prof::TimePoint prof::now() { + return std::chrono::high_resolution_clock::now(); +} +prof::Stats prof::UnitProfileCollection::stats(const std::string& unit) { + return m_map->operator[](unit).stats(); +} + +size_t prof::UnitProfileCollection::measurement_count(const std::string& unit) { + return m_map->operator[](unit).measurement_count(); +} + +void prof::UnitProfileCollection::add_sample(const std::string& unit, const Duration& duration) { + m_map->operator[](unit).add_sample(duration); +} + +prof::Stats prof::UnitExecutionTime::stats() const { + std::unique_lock lock(m_mtx); + Stats result {}; + // calculate sum + result.n = m_total_calls; + result.max = m_min; + result.min = m_max; + // calculate mean: mean = sum_x / n + result.mean = m_sum / double(m_total_calls); + // calculate stdev: stdev = sqrt((sum_x2 / n) - (mean * mean)) + result.stdev = std::sqrt((m_measurement_sqr_sum / double(result.n)) - (result.mean * result.mean)); + return result; +} + +void prof::UnitExecutionTime::add_sample(const Duration& dur) { + std::unique_lock lock(m_mtx); + m_sum += dur.count(); + m_measurement_sqr_sum += dur.count() * dur.count(); + m_min = std::min(dur.count(), m_min); + m_max = std::max(dur.count(), m_max); + ++m_total_calls; +} + +prof::UnitExecutionTime::UnitExecutionTime() { +} + +std::unordered_map prof::UnitProfileCollection::all_stats() { + auto map = m_map.synchronize(); + std::unordered_map result {}; + for (const auto& [name, time] : *map) { + result[name] = time.stats(); + } + return result; +} +size_t prof::UnitExecutionTime::measurement_count() const { + std::unique_lock lock(m_mtx); + return m_total_calls; +} + diff --git a/src/TLuaEngine.cpp b/src/TLuaEngine.cpp index b16f283..4b1e92c 100644 --- a/src/TLuaEngine.cpp +++ b/src/TLuaEngine.cpp @@ -22,11 +22,13 @@ #include "CustomAssert.h" #include "Http.h" #include "LuaAPI.h" +#include "Profiling.h" #include "TLuaPlugin.h" #include "sol/object.hpp" #include #include +#include #include #include #include @@ -895,6 +897,30 @@ TLuaEngine::StateThreadData::StateThreadData(const std::string& Name, TLuaStateI UtilTable.set_function("RandomIntRange", [this](int64_t min, int64_t max) -> int64_t { return std::uniform_int_distribution(min, max)(mMersenneTwister); }); + UtilTable.set_function("DebugExecutionTime", [this]() -> sol::table { + sol::state_view StateView(mState); + sol::table Result = StateView.create_table(); + auto stats = mProfile.all_stats(); + for (const auto& [name, stat] : stats) { + Result[name] = StateView.create_table(); + Result[name]["mean"] = stat.mean; + Result[name]["stdev"] = stat.stdev; + Result[name]["min"] = stat.min; + Result[name]["max"] = stat.max; + Result[name]["n"] = stat.n; + } + return Result; + }); + UtilTable.set_function("DebugStartProfile", [this](const std::string& name) { + mProfileStarts[name] = prof::now(); + }); + UtilTable.set_function("DebugStopProfile", [this](const std::string& name) { + if (!mProfileStarts.contains(name)) { + beammp_lua_errorf("DebugStopProfile('{}') failed, because a profile for '{}' wasn't started", name, name); + return; + } + mProfile.add_sample(name, prof::duration(mProfileStarts.at(name), prof::now())); + }); auto HttpTable = StateView.create_named_table("Http"); HttpTable.set_function("CreateConnection", [this](const std::string& host, uint16_t port) { @@ -1032,6 +1058,7 @@ void TLuaEngine::StateThreadData::operator()() { std::chrono::milliseconds(500), [&]() -> bool { return !mStateFunctionQueue.empty(); }); if (NotExpired) { + auto ProfStart = prof::now(); auto TheQueuedFunction = std::move(mStateFunctionQueue.front()); mStateFunctionQueue.erase(mStateFunctionQueue.begin()); Lock.unlock(); @@ -1090,6 +1117,9 @@ void TLuaEngine::StateThreadData::operator()() { Result->ErrorMessage = BeamMPFnNotFoundError; // special error kind that we can ignore later Result->MarkAsReady(); } + auto ProfEnd = prof::now(); + auto ProfDuration = prof::duration(ProfStart, ProfEnd); + mProfile.add_sample(FnName, ProfDuration); } } }