measure overlay framework time

separate from the widget time

Author: myk002

plugins/lua/overlay.lua

@@ -17,6 +17,7 @@ local timers_start_ms = dfhack.getTickCount()
 function reset_timers()
     timers = {}
     timers_start_ms = dfhack.getTickCount()
+    reset_framework_timer()
 end
 function print_timers()
     local elapsed = dfhack.getTickCount() - timers_start_ms
@@ -37,10 +38,14 @@ function print_timers()
         ))
     end
     print()
-    print(('elapsed time: %10d ms (%dm %ds)'):format(
+    print(('elapsed time:   %10d ms (%dm %ds)'):format(
         elapsed, elapsed // 60000, (elapsed % 60000) // 1000
     ))
-    print(('widget time:  %10d ms (%.2f%% of elapsed time)'):format(
+    local framework_time = get_framework_timer() - sum
+    print(('framework time: %10d ms (%.2f%% of elapsed time)'):format(
+        framework_time, (framework_time * 100) / elapsed
+    ))
+    print(('widget time:    %10d ms (%.2f%% of elapsed time)'):format(
         sum, (sum * 100) / elapsed
     ))
 end

plugins/overlay.cpp

@@ -19,6 +19,7 @@
 
 #include "Debug.h"
 #include "LuaTools.h"
+#include "MemAccess.h"
 #include "PluginManager.h"
 #include "VTableInterpose.h"
 
@@ -40,6 +41,11 @@ namespace DFHack {
 
 static df::coord2d screenSize;
 
+// instrumentation
+uint32_t total_overlay_ms = 0;
+static uint32_t get_framework_timer()   { return total_overlay_ms; }
+static void     reset_framework_timer() { total_overlay_ms = 0;    }
+
 static void call_overlay_lua(color_ostream *out, const char *fn_name,
         int nargs = 0, int nres = 0,
         Lua::LuaLambda && args_lambda = Lua::DEFAULT_LUA_LAMBDA,
@@ -48,6 +54,8 @@ static void call_overlay_lua(color_ostream *out, const char *fn_name,
 
     CoreSuspender guard;
 
+    uint32_t start_ms = Core::getInstance().p->getTickCount();
+
     auto L = Lua::Core::State;
     Lua::StackUnwinder top(L);
 
@@ -57,6 +65,8 @@ static void call_overlay_lua(color_ostream *out, const char *fn_name,
     Lua::CallLuaModuleFunction(*out, L, "plugins.overlay", fn_name, nargs, nres,
                                std::forward<Lua::LuaLambda&&>(args_lambda),
                                std::forward<Lua::LuaLambda&&>(res_lambda));
+
+    total_overlay_ms += Core::getInstance().p->getTickCount() - start_ms;
 }
 
 template<class T>
@@ -198,3 +208,9 @@ DFhackCExport command_result plugin_onupdate (color_ostream &out) {
     call_overlay_lua(&out, "update_hotspot_widgets");
     return CR_OK;
 }
+
+DFHACK_PLUGIN_LUA_FUNCTIONS {
+    DFHACK_LUA_FUNCTION(get_framework_timer),
+    DFHACK_LUA_FUNCTION(reset_framework_timer),
+    DFHACK_LUA_END
+};