Add Lua execution profiler Util.DebugExecutionTime() (#267)

Adds `Util.DebugExecutionTime()`, which returns a table of
`function_name: milliseconds`, in which each function's execution time
is averaged over all time.

You can call this function like so:
```lua
-- event to print the debug times
MP.RegisterEvent("printStuff", "printStuff")
-- prints the execution time of all event handlers
function printStuff()
	print(Util.DebugExecutionTime())
end
-- run every 5 seconds (or 10, or 60, whatever makes sense for you
MP.CreateEventTimer("printStuff", 5000)
```

Pretty print function:
```lua
function printDebugExecutionTime()
    local stats = Util.DebugExecutionTime()
    local pretty = "DebugExecutionTime:\n"
    local longest = 0
    for name, t in pairs(stats) do
        if #name > longest then
            longest = #name
        end
    end
    for name, t in pairs(stats) do
        pretty = pretty .. string.format("%" .. longest + 1 .. "s: %12f +/- %12f (min: %12f, max: %12f) (called %d time(s))\n", name, t.mean, t.stdev, t.min, t.max, t.n)
    end
    print(pretty)
end
```

`Util.DebugExecutionTime()` returns a table, where each key is an event
handler function name, and each value is a table consisting of `mean`
(simple average), `stddev` (standard deviation aka mean of the
variance), `min` and `max`, all in milliseconds, as well as `n` as the
number of samples taken.

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)

include/Profiling.h

@@ -0,0 +1,72 @@
+#pragma once
+
+#include <boost/thread/synchronized_value.hpp>
+#include <chrono>
+#include <cstddef>
+#include <limits>
+#include <unordered_map>
+
+namespace prof {
+
+using Duration = std::chrono::duration<double, std::milli>;
+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<double>::max() };
+    double m_max { std::numeric_limits<double>::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<std::string, Stats> all_stats();
+
+private:
+    boost::synchronized_value<std::unordered_map<std::string, UnitExecutionTime>> m_map;
+};
+
+}

include/TLuaEngine.h

@@ -18,9 +18,11 @@
 
 #pragma once
 
+#include "Profiling.h"
 #include "TNetwork.h"
 #include "TServer.h"
 #include <any>
+#include <chrono>
 #include <condition_variable>
 #include <filesystem>
 #include <initializer_list>
@@ -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<std::string, prof::TimePoint> mProfileStarts;
+
         std::string mName;
         TLuaStateId mStateId;
         lua_State* mState;

src/Profiling.cpp

@@ -0,0 +1,60 @@
+#include "Profiling.h"
+#include <limits>
+
+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<std::string, prof::Stats> prof::UnitProfileCollection::all_stats() {
+    auto map = m_map.synchronize();
+    std::unordered_map<std::string, Stats> 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;
+}
+

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 <chrono>
 #include <condition_variable>
+#include <fmt/core.h>
 #include <nlohmann/json.hpp>
 #include <random>
 #include <thread>
@@ -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);
             }
         }
     }