From c24e0753fc240636b2f9b1889554649e67c9046c Mon Sep 17 00:00:00 2001 From: sapier Date: Tue, 12 Aug 2014 23:07:27 +0200 Subject: [PATCH] Mod profiling support Config settings: profiling = true/false (gather statistics) detailed_profiling = true/false (break mod times to callbacks) Chat commands: save_mod_profile saves current statistics in debug.txt and shows on console (on default loglevel) --- builtin/game/chatcommands.lua | 13 ++ builtin/game/init.lua | 5 + builtin/game/mod_profiling.lua | 355 +++++++++++++++++++++++++++++++++ doc/lua_api.txt | 2 + minetest.conf.example | 5 + src/script/lua_api/l_env.cpp | 8 + src/script/lua_api/l_env.h | 3 + 7 files changed, 391 insertions(+) create mode 100644 builtin/game/mod_profiling.lua diff --git a/builtin/game/chatcommands.lua b/builtin/game/chatcommands.lua index 39425f0eb..9293e98f4 100644 --- a/builtin/game/chatcommands.lua +++ b/builtin/game/chatcommands.lua @@ -13,6 +13,19 @@ function core.register_chatcommand(cmd, def) core.chatcommands[cmd] = def end +if core.setting_getbool("mod_profiling") then + local tracefct = profiling_print_log + profiling_print_log = nil + core.register_chatcommand("save_mod_profile", + { + params = "", + description = "save mod profiling data to logfile " .. + "(depends on default loglevel)", + func = tracefct, + privs = { server=true } + }) +end + core.register_on_chat_message(function(name, message) local cmd, param = string.match(message, "^/([^ ]+) *(.*)") if not param then diff --git a/builtin/game/init.lua b/builtin/game/init.lua index b878a2664..3f82f85c7 100644 --- a/builtin/game/init.lua +++ b/builtin/game/init.lua @@ -7,6 +7,11 @@ dofile(commonpath.."vector.lua") dofile(gamepath.."item.lua") dofile(gamepath.."register.lua") + +if core.setting_getbool("mod_profiling") then + dofile(gamepath.."mod_profiling.lua") +end + dofile(gamepath.."item_entity.lua") dofile(gamepath.."deprecated.lua") dofile(gamepath.."misc.lua") diff --git a/builtin/game/mod_profiling.lua b/builtin/game/mod_profiling.lua new file mode 100644 index 000000000..0fe99e725 --- /dev/null +++ b/builtin/game/mod_profiling.lua @@ -0,0 +1,355 @@ +-- Minetest: builtin/game/mod_profiling.lua + +local mod_statistics = {} +mod_statistics.step_total = 0 +mod_statistics.data = {} +mod_statistics.stats = {} +mod_statistics.stats["total"] = { + min_us = math.huge, + max_us = 0, + avg_us = 0, + min_per = 100, + max_per = 100, + avg_per = 100 +} + +local replacement_table = { + "register_globalstep", + "register_on_placenode", + "register_on_dignode", + "register_on_punchnode", + "register_on_generated", + "register_on_newplayer", + "register_on_dieplayer", + "register_on_respawnplayer", + "register_on_prejoinplayer", + "register_on_joinplayer", + "register_on_leaveplayer", + "register_on_cheat", + "register_on_chat_message", + "register_on_player_receive_fields", + "register_on_mapgen_init", + "register_on_craft", + "register_craft_predict", + "register_on_item_eat" +} + +-------------------------------------------------------------------------------- +function mod_statistics.log_time(type, modname, time_in_us) + + if modname == nil then + modname = "builtin" + end + + if mod_statistics.data[modname] == nil then + mod_statistics.data[modname] = {} + end + + if mod_statistics.data[modname][type] == nil then + mod_statistics.data[modname][type] = 0 + end + + mod_statistics.data[modname][type] = + mod_statistics.data[modname][type] + time_in_us + mod_statistics.step_total = mod_statistics.step_total + time_in_us +end + +-------------------------------------------------------------------------------- +function mod_statistics.update_statistics(dtime) + for modname,types in pairs(mod_statistics.data) do + + if mod_statistics.stats[modname] == nil then + mod_statistics.stats[modname] = { + min_us = math.huge, + max_us = 0, + avg_us = 0, + min_per = 100, + max_per = 0, + avg_per = 0 + } + end + + local modtime = 0 + for type,time in pairs(types) do + modtime = modtime + time + if mod_statistics.stats[modname].types == nil then + mod_statistics.stats[modname].types = {} + end + if mod_statistics.stats[modname].types[type] == nil then + mod_statistics.stats[modname].types[type] = { + min_us = math.huge, + max_us = 0, + avg_us = 0, + min_per = 100, + max_per = 0, + avg_per = 0 + } + end + + local toupdate = mod_statistics.stats[modname].types[type] + + --update us values + toupdate.min_us = math.min(time, toupdate.min_us) + toupdate.max_us = math.max(time, toupdate.max_us) + --TODO find better algorithm + toupdate.avg_us = toupdate.avg_us * 0.99 + modtime * 0.01 + + --update percentage values + local cur_per = (time/mod_statistics.step_total) * 100 + toupdate.min_per = math.min(toupdate.min_per, cur_per) + + toupdate.max_per = math.max(toupdate.max_per, cur_per) + + --TODO find better algorithm + toupdate.avg_per = toupdate.avg_per * 0.99 + cur_per * 0.01 + + mod_statistics.data[modname][type] = 0 + end + + --per mod statistics + --update us values + mod_statistics.stats[modname].min_us = + math.min(modtime, mod_statistics.stats[modname].min_us) + mod_statistics.stats[modname].max_us = + math.max(modtime, mod_statistics.stats[modname].max_us) + --TODO find better algorithm + mod_statistics.stats[modname].avg_us = + mod_statistics.stats[modname].avg_us * 0.99 + modtime * 0.01 + + --update percentage values + local cur_per = (modtime/mod_statistics.step_total) * 100 + mod_statistics.stats[modname].min_per = + math.min(mod_statistics.stats[modname].min_per, cur_per) + + mod_statistics.stats[modname].max_per = + math.max(mod_statistics.stats[modname].max_per, cur_per) + + --TODO find better algorithm + mod_statistics.stats[modname].avg_per = + mod_statistics.stats[modname].avg_per * 0.99 + cur_per * 0.01 + end + + --update "total" + mod_statistics.stats["total"].min_us = + math.min(mod_statistics.step_total, mod_statistics.stats["total"].min_us) + mod_statistics.stats["total"].max_us = + math.max(mod_statistics.step_total, mod_statistics.stats["total"].max_us) + --TODO find better algorithm + mod_statistics.stats["total"].avg_us = + mod_statistics.stats["total"].avg_us * 0.99 + + mod_statistics.step_total * 0.01 + + mod_statistics.step_total = 0 +end + +-------------------------------------------------------------------------------- +local function build_callback(log_id, fct) + return function( toregister ) + local modname = core.get_current_modname() + + fct(function(...) + local starttime = core.get_us_time() + -- note maximum 10 return values are supported unless someone finds + -- a way to store a variable lenght return value list + local r0, r1, r2, r3, r4, r5, r6, r7, r8, r9 = toregister(...) + local delta = core.get_us_time() - starttime + mod_statistics.log_time(log_id, modname, delta) + return r0, r1, r2, r3, r4, r5, r6, r7, r8, r9 + end + ) + end +end + +-------------------------------------------------------------------------------- +function profiling_print_log(cmd, filter) + + print("Filter:" .. dump(filter)) + + core.log("action", "Values below show times/percentages per server step.") + core.log("action", "Following suffixes are used for entities:") + core.log("action", "\t#oa := on_activate, #os := on_step, #op := on_punch, #or := on_rightclick, #gs := get_staticdata") + core.log("action", + string.format("%16s | %25s | %10s | %10s | %10s | %9s | %9s | %9s", + "modname", "type" , "min µs", "max µs", "avg µs", "min %", "max %", "avg %") + ) + core.log("action", + "-----------------+---------------------------+-----------+" .. + "-----------+-----------+-----------+-----------+-----------") + for modname,statistics in pairs(mod_statistics.stats) do + if modname ~= "total" then + + if (filter == "") or (modname == filter) then + if modname:len() > 16 then + modname = "..." .. modname:sub(-13) + end + + core.log("action", + string.format("%16s | %25s | %9d | %9d | %9d | %9d | %9d | %9d", + modname, + " ", + statistics.min_us, + statistics.max_us, + statistics.avg_us, + statistics.min_per, + statistics.max_per, + statistics.avg_per) + ) + if core.setting_getbool("detailed_profiling") then + if statistics.types ~= nil then + for type,typestats in pairs(statistics.types) do + + if type:len() > 25 then + type = "..." .. type:sub(-22) + end + + core.log("action", + string.format( + "%16s | %25s | %9d | %9d | %9d | %9d | %9d | %9d", + " ", + type, + typestats.min_us, + typestats.max_us, + typestats.avg_us, + typestats.min_per, + typestats.max_per, + typestats.avg_per) + ) + end + end + end + end + end + end + core.log("action", + "-----------------+---------------------------+-----------+" .. + "-----------+-----------+-----------+-----------+-----------") + + if filter == "" then + core.log("action", + string.format("%16s | %25s | %9d | %9d | %9d | %9d | %9d | %9d", + "total", + " ", + mod_statistics.stats["total"].min_us, + mod_statistics.stats["total"].max_us, + mod_statistics.stats["total"].avg_us, + mod_statistics.stats["total"].min_per, + mod_statistics.stats["total"].max_per, + mod_statistics.stats["total"].avg_per) + ) + end + core.log("action", " ") + + return true +end + +-------------------------------------------------------------------------------- +local function initialize_profiling() + core.log("action", "Initialize tracing") + + mod_statistics.entity_callbacks = {} + + -- first register our own globalstep handler + core.register_globalstep(mod_statistics.update_statistics) + + local rp_register_entity = core.register_entity + core.register_entity = function(name, prototype) + local modname = core.get_current_modname() + local new_on_activate = nil + local new_on_step = nil + local new_on_punch = nil + local new_rightclick = nil + local new_get_staticdata = nil + + if prototype.on_activate ~= nil then + local cbid = name .. "#oa" + mod_statistics.entity_callbacks[cbid] = prototype.on_activate + new_on_activate = function(self, staticdata, dtime_s) + local starttime = core.get_us_time() + mod_statistics.entity_callbacks[cbid](self, staticdata, dtime_s) + local delta = core.get_us_time() -starttime + mod_statistics.log_time(cbid, modname, delta) + end + end + + if prototype.on_step ~= nil then + local cbid = name .. "#os" + mod_statistics.entity_callbacks[cbid] = prototype.on_step + new_on_step = function(self, dtime) + local starttime = core.get_us_time() + mod_statistics.entity_callbacks[cbid](self, dtime) + local delta = core.get_us_time() -starttime + mod_statistics.log_time(cbid, modname, delta) + end + end + + if prototype.on_punch ~= nil then + local cbid = name .. "#op" + mod_statistics.entity_callbacks[cbid] = prototype.on_punch + new_on_punch = function(self, hitter) + local starttime = core.get_us_time() + mod_statistics.entity_callbacks[cbid](self, hitter) + local delta = core.get_us_time() -starttime + mod_statistics.log_time(cbid, modname, delta) + end + end + + if prototype.rightclick ~= nil then + local cbid = name .. "#rc" + mod_statistics.entity_callbacks[cbid] = prototype.rightclick + new_rightclick = function(self, clicker) + local starttime = core.get_us_time() + mod_statistics.entity_callbacks[cbid](self, clicker) + local delta = core.get_us_time() -starttime + mod_statistics.log_time(cbid, modname, delta) + end + end + + if prototype.get_staticdata ~= nil then + local cbid = name .. "#gs" + mod_statistics.entity_callbacks[cbid] = prototype.get_staticdata + new_get_staticdata = function(self) + local starttime = core.get_us_time() + mod_statistics.entity_callbacks[cbid](self) + local delta = core.get_us_time() -starttime + mod_statistics.log_time(cbid, modname, delta) + end + end + + prototype.on_activate = new_on_activate + prototype.on_step = new_on_step + prototype.on_punch = new_on_punch + prototype.rightclick = new_rightclick + prototype.get_staticdata = new_get_staticdata + + rp_register_entity(name,prototype) + end + + for i,v in ipairs(replacement_table) do + local to_replace = core[v] + core[v] = build_callback(v, to_replace) + end + + local rp_register_abm = core.register_abm + core.register_abm = function(spec) + + local modname = core.get_current_modname() + + local replacement_spec = { + nodenames = spec.nodenames, + neighbors = spec.neighbors, + interval = spec.interval, + chance = spec.chance, + action = function(pos, node, active_object_count, active_object_count_wider) + local starttime = core.get_us_time() + spec.action(pos, node, active_object_count, active_object_count_wider) + local delta = core.get_us_time() - starttime + mod_statistics.log_time("abm", modname, delta) + end + } + rp_register_abm(replacement_spec) + end + + core.log("action", "Mod profiling initialized") +end + +initialize_profiling() diff --git a/doc/lua_api.txt b/doc/lua_api.txt index 3d8038f87..e027fe11d 100644 --- a/doc/lua_api.txt +++ b/doc/lua_api.txt @@ -1535,6 +1535,8 @@ minetest.set_node_level(pos, level) ^ set level of leveled node, default level = 1, if totallevel > maxlevel returns rest (total-max). minetest.add_node_level(pos, level) ^ increase level of leveled node by level, default level = 1, if totallevel > maxlevel returns rest (total-max). can be negative for decreasing +minetest.get_time_us() +^ get time in microseconds Inventory: minetest.get_inventory(location) -> InvRef diff --git a/minetest.conf.example b/minetest.conf.example index 24724ce28..78f51a517 100644 --- a/minetest.conf.example +++ b/minetest.conf.example @@ -306,6 +306,11 @@ # "error" = abort on usage of deprecated call (suggested for mod developers) #deprecated_lua_api_handling = legacy +# Mod profiler +#mod_profiling = false +# Detailed mod profile data +#detailed_profiling = false + # Profiler data print interval. #0 = disable. #profiler_print_interval = 0 #enable_mapgen_debug_info = false diff --git a/src/script/lua_api/l_env.cpp b/src/script/lua_api/l_env.cpp index 42bfc4beb..e6ca846d8 100644 --- a/src/script/lua_api/l_env.cpp +++ b/src/script/lua_api/l_env.cpp @@ -797,6 +797,13 @@ int ModApiEnvMod::l_forceload_free_block(lua_State *L) return 0; } +// get_us_time() +int ModApiEnvMod::l_get_us_time(lua_State *L) +{ + lua_pushnumber(L, porting::getTimeUs()); + return 1; +} + void ModApiEnvMod::Initialize(lua_State *L, int top) { API_FCT(set_node); @@ -834,4 +841,5 @@ void ModApiEnvMod::Initialize(lua_State *L, int top) API_FCT(transforming_liquid_add); API_FCT(forceload_block); API_FCT(forceload_free_block); + API_FCT(get_us_time); } diff --git a/src/script/lua_api/l_env.h b/src/script/lua_api/l_env.h index 420866d5d..76c6594ab 100644 --- a/src/script/lua_api/l_env.h +++ b/src/script/lua_api/l_env.h @@ -156,6 +156,9 @@ private: // stops forceloading a position static int l_forceload_free_block(lua_State *L); + // get us precision time + static int l_get_us_time(lua_State *L); + public: static void Initialize(lua_State *L, int top); };