diff options
| -rw-r--r-- | builtin/game/chatcommands.lua | 19 | ||||
| -rw-r--r-- | builtin/game/init.lua | 6 | ||||
| -rw-r--r-- | builtin/game/mod_profiling.lua | 356 | ||||
| -rw-r--r-- | builtin/profiler/init.lua | 72 | ||||
| -rw-r--r-- | builtin/profiler/instrumentation.lua | 232 | ||||
| -rw-r--r-- | builtin/profiler/reporter.lua | 277 | ||||
| -rw-r--r-- | builtin/profiler/sampling.lua | 206 | ||||
| -rw-r--r-- | builtin/settingtypes.txt | 57 | ||||
| -rw-r--r-- | doc/lua_api.txt | 6 |
9 files changed, 851 insertions, 380 deletions
diff --git a/builtin/game/chatcommands.lua b/builtin/game/chatcommands.lua index 22755386b..24792bc8a 100644 --- a/builtin/game/chatcommands.lua +++ b/builtin/game/chatcommands.lua @@ -14,19 +14,6 @@ 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 @@ -51,6 +38,12 @@ core.register_on_chat_message(function(name, message) return true -- Handled chat message end) +if core.setting_getbool("profiler.load") then + -- Run after register_chatcommand and its register_on_chat_message + -- Before any chattcommands that should be profiled + profiler.init_chatcommand() +end + -- Parses a "range" string in the format of "here (number)" or -- "(x1, y1, z1) (x2, y2, z2)", returning two position vectors local function parse_range_str(player_name, str) diff --git a/builtin/game/init.lua b/builtin/game/init.lua index a6cfa3bf8..2f9f90315 100644 --- a/builtin/game/init.lua +++ b/builtin/game/init.lua @@ -9,8 +9,8 @@ dofile(gamepath.."constants.lua") dofile(gamepath.."item.lua") dofile(gamepath.."register.lua") -if core.setting_getbool("mod_profiling") then - dofile(gamepath.."mod_profiling.lua") +if core.setting_getbool("profiler.load") then + profiler = dofile(scriptpath.."profiler"..DIR_DELIM.."init.lua") end dofile(gamepath.."item_entity.lua") @@ -26,3 +26,5 @@ dofile(gamepath.."features.lua") dofile(gamepath.."voxelarea.lua") dofile(gamepath.."forceloading.lua") dofile(gamepath.."statbars.lua") + +profiler = nil diff --git a/builtin/game/mod_profiling.lua b/builtin/game/mod_profiling.lua deleted file mode 100644 index df2d10221..000000000 --- a/builtin/game/mod_profiling.lua +++ /dev/null @@ -1,356 +0,0 @@ --- 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() - local retval = mod_statistics.entity_callbacks[cbid](self) - local delta = core.get_us_time() -starttime - mod_statistics.log_time(cbid, modname, delta) - return retval - 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/builtin/profiler/init.lua b/builtin/profiler/init.lua new file mode 100644 index 000000000..c1597d280 --- /dev/null +++ b/builtin/profiler/init.lua @@ -0,0 +1,72 @@ +--Minetest +--Copyright (C) 2016 T4im +-- +--This program is free software; you can redistribute it and/or modify +--it under the terms of the GNU Lesser General Public License as published by +--the Free Software Foundation; either version 2.1 of the License, or +--(at your option) any later version. +-- +--This program is distributed in the hope that it will be useful, +--but WITHOUT ANY WARRANTY; without even the implied warranty of +--MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +--GNU Lesser General Public License for more details. +-- +--You should have received a copy of the GNU Lesser General Public License along +--with this program; if not, write to the Free Software Foundation, Inc., +--51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA. + +local profiler_path = core.get_builtin_path()..DIR_DELIM.."profiler"..DIR_DELIM +local profiler = {} +local sampler = assert(loadfile(profiler_path .. "sampling.lua"))(profiler) +local instrumentation = assert(loadfile(profiler_path .. "instrumentation.lua"))(profiler, sampler) +local reporter = dofile(profiler_path .. "reporter.lua") +profiler.instrument = instrumentation.instrument + +--- +-- Delayed registration of the /profiler chat command +-- Is called later, after `core.register_chatcommand` was set up. +-- +function profiler.init_chatcommand() + local instrument_profiler = core.setting_getbool("instrument.profiler") or false + if instrument_profiler then + instrumentation.init_chatcommand() + end + + local param_usage = "print [filter] | dump [filter] | save [format [filter]] | reset" + core.register_chatcommand("profiler", { + description = "handle the profiler and profiling data", + params = param_usage, + privs = { server=true }, + func = function(name, param) + local command, arg0 = string.match(param, "([^ ]+) ?(.*)") + local args = arg0 and string.split(arg0, " ") + + if command == "dump" then + core.log("action", reporter.print(sampler.profile, arg0)) + return true, "Statistics written to action log" + elseif command == "print" then + return true, reporter.print(sampler.profile, arg0) + elseif command == "save" then + return reporter.save(sampler.profile, args[1] or "txt", args[2]) + elseif command == "reset" then + sampler.reset() + return true, "Statistics were reset" + end + + return false, string.format( + "Usage: %s\n" .. + "Format can be one of txt, csv, lua, json, json_pretty (structures may be subject to change).", + param_usage + ) + end + }) + + if not instrument_profiler then + instrumentation.init_chatcommand() + end +end + +sampler.init() +instrumentation.init() + +return profiler diff --git a/builtin/profiler/instrumentation.lua b/builtin/profiler/instrumentation.lua new file mode 100644 index 000000000..4311215b2 --- /dev/null +++ b/builtin/profiler/instrumentation.lua @@ -0,0 +1,232 @@ +--Minetest +--Copyright (C) 2016 T4im +-- +--This program is free software; you can redistribute it and/or modify +--it under the terms of the GNU Lesser General Public License as published by +--the Free Software Foundation; either version 2.1 of the License, or +--(at your option) any later version. +-- +--This program is distributed in the hope that it will be useful, +--but WITHOUT ANY WARRANTY; without even the implied warranty of +--MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +--GNU Lesser General Public License for more details. +-- +--You should have received a copy of the GNU Lesser General Public License along +--with this program; if not, write to the Free Software Foundation, Inc., +--51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA. + +local format, pairs, type = string.format, pairs, type +local core, get_current_modname = core, core.get_current_modname +local profiler, sampler = ... +local instrument_builtin = core.setting_getbool("instrument.builtin") or false + +local register_functions = { + register_globalstep = 0, + register_playerevent = 0, + register_on_placenode = 0, + register_on_dignode = 0, + register_on_punchnode = 0, + register_on_generated = 0, + register_on_newplayer = 0, + register_on_dieplayer = 0, + register_on_respawnplayer = 0, + register_on_prejoinplayer = 0, + register_on_joinplayer = 0, + register_on_leaveplayer = 0, + register_on_cheat = 0, + register_on_chat_message = 0, + register_on_player_receive_fields = 0, + register_on_craft = 0, + register_craft_predict = 0, + register_on_protection_violation = 0, + register_on_item_eat = 0, + register_on_punchplayer = 0, + register_on_player_hpchange = 0, +} + +--- +-- Create an unique instrument name. +-- Generate a missing label with a running index number. +-- +local counts = {} +local function generate_name(def) + local class, label, func_name = def.class, def.label, def.func_name + if label then + if class or func_name then + return format("%s '%s' %s", class or "", label, func_name or ""):trim() + end + return format("%s", label):trim() + elseif label == false then + return format("%s", class or func_name):trim() + end + + local index_id = def.mod .. (class or func_name) + local index = counts[index_id] or 1 + counts[index_id] = index + 1 + return format("%s[%d] %s", class or func_name, index, class and func_name or ""):trim() +end + +--- +-- Keep `measure` and the closure in `instrument` lean, as these, and their +-- directly called functions are the overhead that is caused by instrumentation. +-- +local time, log = core.get_us_time, sampler.log +local function measure(modname, instrument_name, start, ...) + log(modname, instrument_name, time() - start) + return ... +end +--- Automatically instrument a function to measure and log to the sampler. +-- def = { +-- mod = "", +-- class = "", +-- func_name = "", +-- -- if nil, will create a label based on registration order +-- label = "" | false, +-- } +local function instrument(def) + if not def or not def.func then + return + end + def.mod = def.mod or get_current_modname() + local modname = def.mod + local instrument_name = generate_name(def) + local func = def.func + + if not instrument_builtin and modname == "*builtin*" then + return func + end + + return function(...) + -- This tail-call allows passing all return values of `func` + -- also called https://en.wikipedia.org/wiki/Continuation_passing_style + -- Compared to table creation and unpacking it won't lose `nil` returns + -- and is expected to be faster + -- `measure` will be executed after time() and func(...) + return measure(modname, instrument_name, time(), func(...)) + end +end + +local function can_be_called(func) + -- It has to be a function or callable table + return type(func) == "function" or + ((type(func) == "table" or type(func) == "userdata") and + getmetatable(func) and getmetatable(func).__call) +end + +local function assert_can_be_called(func, func_name, level) + if not can_be_called(func) then + -- Then throw an *helpful* error, by pointing on our caller instead of us. + error(format("Invalid argument to %s. Expected function-like type instead of '%s'.", func_name, type(func)), level + 1) + end +end + +--- +-- Wraps a registration function `func` in such a way, +-- that it will automatically instrument any callback function passed as first argument. +-- +local function instrument_register(func, func_name) + local register_name = func_name:gsub("^register_", "", 1) + return function(callback, ...) + assert_can_be_called(callback, func_name, 2) + register_functions[func_name] = register_functions[func_name] + 1 + return func(instrument { + func = callback, + func_name = register_name + }), ... + end +end + +local function init_chatcommand() + if core.setting_getbool("instrument.chatcommand") or true then + local orig_register_chatcommand = core.register_chatcommand + core.register_chatcommand = function(cmd, def) + def.func = instrument { + func = def.func, + label = "/" .. cmd, + } + orig_register_chatcommand(cmd, def) + end + end +end + +--- +-- Start instrumenting selected functions +-- +local function init() + local is_set = core.setting_getbool + if is_set("instrument.entity") or true then + -- Explicitly declare entity api-methods. + -- Simple iteration would ignore lookup via __index. + local entity_instrumentation = { + "on_activate", + "on_step", + "on_punch", + "rightclick", + "get_staticdata", + } + -- Wrap register_entity() to instrument them on registration. + local orig_register_entity = core.register_entity + core.register_entity = function(name, prototype) + local modname = get_current_modname() + for _, func_name in pairs(entity_instrumentation) do + prototype[func_name] = instrument { + func = prototype[func_name], + mod = modname, + func_name = func_name, + label = prototype.label, + } + end + orig_register_entity(name,prototype) + end + end + + if is_set("instrument.abm") or true then + -- Wrap register_abm() to automatically instrument abms. + local orig_register_abm = core.register_abm + core.register_abm = function(spec) + spec.action = instrument { + func = spec.action, + class = "ABM", + label = spec.label, + } + orig_register_abm(spec) + end + end + + if is_set("instrument.lbm") or true then + -- Wrap register_lbm() to automatically instrument lbms. + local orig_register_lbm = core.register_lbm + core.register_lbm = function(spec) + spec.action = instrument { + func = spec.action, + class = "LBM", + label = spec.label or spec.name, + } + orig_register_lbm(spec) + end + end + + if is_set("instrument.global_callback") or true then + for func_name, _ in pairs(register_functions) do + core[func_name] = instrument_register(core[func_name], func_name) + end + end + + if is_set("instrument.profiler") or false then + -- Measure overhead of instrumentation, but keep it down for functions + -- So keep the `return` for better optimization. + profiler.empty_instrument = instrument { + func = function() return end, + mod = "*profiler*", + class = "Instrumentation overhead", + label = false, + } + end +end + +return { + register_functions = register_functions, + instrument = instrument, + init = init, + init_chatcommand = init_chatcommand, +} diff --git a/builtin/profiler/reporter.lua b/builtin/profiler/reporter.lua new file mode 100644 index 000000000..5b38ed4df --- /dev/null +++ b/builtin/profiler/reporter.lua @@ -0,0 +1,277 @@ +--Minetest +--Copyright (C) 2016 T4im +-- +--This program is free software; you can redistribute it and/or modify +--it under the terms of the GNU Lesser General Public License as published by +--the Free Software Foundation; either version 2.1 of the License, or +--(at your option) any later version. +-- +--This program is distributed in the hope that it will be useful, +--but WITHOUT ANY WARRANTY; without even the implied warranty of +--MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +--GNU Lesser General Public License for more details. +-- +--You should have received a copy of the GNU Lesser General Public License along +--with this program; if not, write to the Free Software Foundation, Inc., +--51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA. + +local DIR_DELIM, LINE_DELIM = DIR_DELIM, "\n" +local table, unpack, string, pairs, io, os = table, unpack, string, pairs, io, os +local rep, sprintf, tonumber = string.rep, string.format, tonumber +local core, setting_get = core, core.setting_get +local reporter = {} + +--- +-- Shorten a string. End on an ellipsis if shortened. +-- +local function shorten(str, length) + if str and str:len() > length then + return "..." .. str:sub(-(length-3)) + end + return str +end + +local function filter_matches(filter, text) + return not filter or string.match(text, filter) +end + +local function format_number(number, fmt) + number = tonumber(number) + if not number then + return "N/A" + end + return sprintf(fmt or "%d", number) +end + +local Formatter = { + new = function(self, object) + object = object or {} + object.out = {} -- output buffer + self.__index = self + return setmetatable(object, self) + end, + __tostring = function (self) + return table.concat(self.out, LINE_DELIM) + end, + print = function(self, text, ...) + if (...) then + text = sprintf(text, ...) + end + + if text then + -- Avoid format unicode issues. + text = text:gsub("Ms", "µs") + end + + table.insert(self.out, text or LINE_DELIM) + end, + flush = function(self) + table.insert(self.out, LINE_DELIM) + local text = table.concat(self.out, LINE_DELIM) + self.out = {} + return text + end +} + +local widths = { 55, 9, 9, 9, 5, 5, 5 } +local txt_row_format = sprintf(" %%-%ds | %%%ds | %%%ds | %%%ds | %%%ds | %%%ds | %%%ds", unpack(widths)) + +local HR = {} +for i=1, #widths do + HR[i]= rep("-", widths[i]) +end +-- ' | ' should break less with github than '-+-', when people are pasting there +HR = sprintf("-%s-", table.concat(HR, " | ")) + +local TxtFormatter = Formatter:new { + format_row = function(self, modname, instrument_name, statistics) + local label + if instrument_name then + label = shorten(instrument_name, widths[1] - 5) + label = sprintf(" - %s %s", label, rep(".", widths[1] - 5 - label:len())) + else -- Print mod_stats + label = shorten(modname, widths[1] - 2) .. ":" + end + + self:print(txt_row_format, label, + format_number(statistics.time_min), + format_number(statistics.time_max), + format_number(statistics:get_time_avg()), + format_number(statistics.part_min, "%.1f"), + format_number(statistics.part_max, "%.1f"), + format_number(statistics:get_part_avg(), "%.1f") + ) + end, + format = function(self, filter) + local profile = self.profile + self:print("Values below show absolute/relative times spend per server step by the instrumented function.") + self:print("A total of %d samples were taken", profile.stats_total.samples) + + if filter then + self:print("The output is limited to '%s'", filter) + end + + self:print() + self:print( + txt_row_format, + "instrumentation", "min Ms", "max Ms", "avg Ms", "min %", "max %", "avg %" + ) + self:print(HR) + for modname,mod_stats in pairs(profile.stats) do + if filter_matches(filter, modname) then + self:format_row(modname, nil, mod_stats) + + if mod_stats.instruments ~= nil then + for instrument_name, instrument_stats in pairs(mod_stats.instruments) do + self:format_row(nil, instrument_name, instrument_stats) + end + end + end + end + self:print(HR) + if not filter then + self:format_row("total", nil, profile.stats_total) + end + end +} + +local CsvFormatter = Formatter:new { + format_row = function(self, modname, instrument_name, statistics) + self:print( + "%q,%q,%d,%d,%d,%d,%d,%f,%f,%f", + modname, instrument_name, + statistics.samples, + statistics.time_min, + statistics.time_max, + statistics:get_time_avg(), + statistics.time_all, + statistics.part_min, + statistics.part_max, + statistics:get_part_avg() + ) + end, + format = function(self, filter) + self:print( + "%q,%q,%q,%q,%q,%q,%q,%q,%q,%q", + "modname", "instrumentation", + "samples", + "time min µs", + "time max µs", + "time avg µs", + "time all µs", + "part min %", + "part max %", + "part avg %" + ) + for modname, mod_stats in pairs(self.profile.stats) do + if filter_matches(filter, modname) then + self:format_row(modname, "*", mod_stats) + + if mod_stats.instruments ~= nil then + for instrument_name, instrument_stats in pairs(mod_stats.instruments) do + self:format_row(modname, instrument_name, instrument_stats) + end + end + end + end + end +} + +local function format_statistics(profile, format, filter) + local formatter + if format == "csv" then + formatter = CsvFormatter:new { + profile = profile + } + else + formatter = TxtFormatter:new { + profile = profile + } + end + formatter:format(filter) + return formatter:flush() +end + +--- +-- Format the profile ready for display and +-- @return string to be printed to the console +-- +function reporter.print(profile, filter) + if filter == "" then filter = nil end + return format_statistics(profile, "txt", filter) +end + +--- +-- Serialize the profile data and +-- @return serialized data to be saved to a file +-- +local function serialize_profile(profile, format, filter) + if format == "lua" or format == "json" or format == "json_pretty" then + local stats = filter and {} or profile.stats + if filter then + for modname, mod_stats in pairs(profile.stats) do + if filter_matches(filter, modname) then + stats[modname] = mod_stats + end + end + end + if format == "lua" then + return core.serialize(stats) + elseif format == "json" then + return core.write_json(stats) + elseif format == "json_pretty" then + return core.write_json(stats, true) + end + end + -- Fall back to textual formats. + return format_statistics(profile, format, filter) +end + +local worldpath = core.get_worldpath() +local function get_save_path(format, filter) + local report_path = setting_get("profiler.report_path") or "" + if report_path ~= "" then + core.mkdir(sprintf("%s%s%s", worldpath, DIR_DELIM, report_path)) + end + return (sprintf( + "%s/%s/profile-%s%s.%s", + worldpath, + report_path, + os.date("%Y%m%dT%H%M%S"), + filter and ("-" .. filter) or "", + format + ):gsub("[/\\]+", DIR_DELIM))-- Clean up delims +end + +--- +-- Save the profile to the world path. +-- @return success, log message +-- +function reporter.save(profile, format, filter) + if not format or format == "" then + format = setting_get("profiler.default_report_format") or "txt" + end + if filter == "" then + filter = nil + end + + local path = get_save_path(format, filter) + + local output, io_err = io.open(path, "w") + if not output then + return false, "Saving of profile failed with: " .. io_err + end + local content, err = serialize_profile(profile, format, filter) + if not content then + output:close() + return false, "Saving of profile failed with: " .. err + end + output:write(content) + output:close() + + local logmessage = "Profile saved to " .. path + core.log("action", logmessage) + return true, logmessage +end + +return reporter diff --git a/builtin/profiler/sampling.lua b/builtin/profiler/sampling.lua new file mode 100644 index 000000000..1d1ef256d --- /dev/null +++ b/builtin/profiler/sampling.lua @@ -0,0 +1,206 @@ +--Minetest +--Copyright (C) 2016 T4im +-- +--This program is free software; you can redistribute it and/or modify +--it under the terms of the GNU Lesser General Public License as published by +--the Free Software Foundation; either version 2.1 of the License, or +--(at your option) any later version. +-- +--This program is distributed in the hope that it will be useful, +--but WITHOUT ANY WARRANTY; without even the implied warranty of +--MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +--GNU Lesser General Public License for more details. +-- +--You should have received a copy of the GNU Lesser General Public License along +--with this program; if not, write to the Free Software Foundation, Inc., +--51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA. +local setmetatable = setmetatable +local pairs, format = pairs, string.format +local min, max, huge = math.min, math.max, math.huge +local core = core + +local profiler = ... +-- Split sampler and profile up, to possibly allow for rotation later. +local sampler = {} +local profile +local stats_total +local logged_time, logged_data + +local _stat_mt = { + get_time_avg = function(self) + return self.time_all/self.samples + end, + get_part_avg = function(self) + if not self.part_all then + return 100 -- Extra handling for "total" + end + return self.part_all/self.samples + end, +} +_stat_mt.__index = _stat_mt + +function sampler.reset() + -- Accumulated logged time since last sample. + -- This helps determining, the relative time a mod used up. + logged_time = 0 + -- The measurements taken through instrumentation since last sample. + logged_data = {} + + profile = { + -- Current mod statistics (max/min over the entire mod lifespan) + -- Mod specific instrumentation statistics are nested within. + stats = {}, + -- Current stats over all mods. + stats_total = setmetatable({ + samples = 0, + time_min = huge, + time_max = 0, + time_all = 0, + part_min = 100, + part_max = 100 + }, _stat_mt) + } + stats_total = profile.stats_total + + -- Provide access to the most recent profile. + sampler.profile = profile +end + +--- +-- Log a measurement for the sampler to pick up later. +-- Keep `log` and its often called functions lean. +-- It will directly add to the instrumentation overhead. +-- +function sampler.log(modname, instrument_name, time_diff) + if time_diff <= 0 then + if time_diff < 0 then + -- This **might** have happened on a semi-regular basis with huge mods, + -- resulting in negative statistics (perhaps midnight time jumps or ntp corrections?). + core.log("warning", format( + "Time travel of %s::%s by %dµs.", + modname, instrument_name, time_diff + )) + end + -- Throwing these away is better, than having them mess with the overall result. + return + end + + local mod_data = logged_data[modname] + if mod_data == nil then + mod_data = {} + logged_data[modname] = mod_data + end + + mod_data[instrument_name] = (mod_data[instrument_name] or 0) + time_diff + -- Update logged time since last sample. + logged_time = logged_time + time_diff +end + +--- +-- Return a requested statistic. +-- Initialize if necessary. +-- +local function get_statistic(stats_table, name) + local statistic = stats_table[name] + if statistic == nil then + statistic = setmetatable({ + samples = 0, + time_min = huge, + time_max = 0, + time_all = 0, + part_min = 100, + part_max = 0, + part_all = 0, + }, _stat_mt) + stats_table[name] = statistic + end + return statistic +end + +--- +-- Update a statistic table +-- +local function update_statistic(stats_table, time) + stats_table.samples = stats_table.samples + 1 + + -- Update absolute time (µs) spend by the subject + stats_table.time_min = min(stats_table.time_min, time) + stats_table.time_max = max(stats_table.time_max, time) + stats_table.time_all = stats_table.time_all + time + + -- Update relative time (%) of this sample spend by the subject + local current_part = (time/logged_time) * 100 + stats_table.part_min = min(stats_table.part_min, current_part) + stats_table.part_max = max(stats_table.part_max, current_part) + stats_table.part_all = stats_table.part_all + current_part +end + +--- +-- Sample all logged measurements each server step. +-- Like any globalstep function, this should not be too heavy, +-- but does not add to the instrumentation overhead. +-- +local function sample(dtime) + -- Rare, but happens and is currently of no informational value. + if logged_time == 0 then + return + end + + for modname, instruments in pairs(logged_data) do + local mod_stats = get_statistic(profile.stats, modname) + if mod_stats.instruments == nil then + -- Current statistics for each instrumentation component + mod_stats.instruments = {} + end + + local mod_time = 0 + for instrument_name, time in pairs(instruments) do + if time > 0 then + mod_time = mod_time + time + local instrument_stats = get_statistic(mod_stats.instruments, instrument_name) + + -- Update time of this sample spend by the instrumented function. + update_statistic(instrument_stats, time) + -- Reset logged data for the next sample. + instruments[instrument_name] = 0 + end + end + + -- Update time of this sample spend by this mod. + update_statistic(mod_stats, mod_time) + end + + -- Update the total time spend over all mods. + stats_total.time_min = min(stats_total.time_min, logged_time) + stats_total.time_max = max(stats_total.time_max, logged_time) + stats_total.time_all = stats_total.time_all + logged_time + + stats_total.samples = stats_total.samples + 1 + logged_time = 0 +end + +--- +-- Setup empty profile and register the sampling function +-- +function sampler.init() + sampler.reset() + + if core.setting_getbool("instrument.profiler") then + core.register_globalstep(function() + if logged_time == 0 then + return + end + return profiler.empty_instrument() + end) + core.register_globalstep(profiler.instrument { + func = sample, + mod = "*profiler*", + class = "Sampler (update stats)", + label = false, + }) + else + core.register_globalstep(sample) + end +end + +return sampler diff --git a/builtin/settingtypes.txt b/builtin/settingtypes.txt index 0b9d29a33..b5878dfe8 100644 --- a/builtin/settingtypes.txt +++ b/builtin/settingtypes.txt @@ -790,15 +790,6 @@ movement_gravity (Gravity) float 9.81 # - error: abort on usage of deprecated call (suggested for mod developers). deprecated_lua_api_handling (Deprecated Lua API handling) enum legacy legacy,log,error -# Useful for mod developers. -mod_profiling (Mod profiling) bool false - -# Detailed mod profile data. Useful for mod developers. -detailed_profiling (Detailed mod profiling) bool false - -# Profiler data print interval. 0 = disable. Useful for developers. -profiler_print_interval (Profiling print interval) int 0 - # Number of extra blocks that can be loaded by /clearobjects at once. # This is a trade-off between sqlite transaction overhead and # memory consumption (4096=100MB, as a rule of thumb). @@ -1163,6 +1154,51 @@ secure.trusted_mods (Trusted mods) string # allow them to upload and download data to/from the internet. secure.http_mods (HTTP Mods) string +[*Advanced] + +[**Profiling] +# Load the game profiler to collect game profiling data. +# Provides a /profiler command to access the compiled profile. +# Useful for mod developers and server operators. +profiler.load (Load the game profiler) bool false + +# The default format in which profiles are being saved, +# when calling `/profiler save [format]` without format. +profiler.default_report_format (Default report format) enum txt txt,csv,lua,json,json_pretty + +# The file path relative to your worldpath in which profiles will be saved to. +# +profiler.report_path (Report path) string "" + +[***Instrumentation] + +# Instrument the methods of entities on registration. +instrument.entity (Entity methods) bool true + +# Instrument the action function of Active Block Modifiers on registration. +instrument.abm (Active Block Modifiers) bool true + +# Instrument the action function of Loading Block Modifiers on registration. +instrument.lbm (Loading Block Modifiers) bool true + +# Instrument chatcommands on registration. +instrument.chatcommand (Chatcommands) bool true + +# Instrument global callback functions on registration. +# (anything you pass to a minetest.register_*() function) +instrument.global_callback (Global callbacks) bool true + +[****Advanced] +# Instrument builtin. +# This is usually only needed by core/builtin contributors +instrument.builtin (Builtin) bool false + +# Have the profiler instrument itself: +# * Instrument an empty function. +# This estimates the overhead, that instrumentation is adding (+1 function call). +# * Instrument the sampler being used to update the statistics. +instrument.profiler (Profiler) bool false + [Client and Server] # Name of the player. @@ -1218,3 +1254,6 @@ modstore_download_url (Modstore download URL) string https://forum.minetest.net/ modstore_listmods_url (Modstore mods list URL) string https://forum.minetest.net/mmdb/mods/ modstore_details_url (Modstore details URL) string https://forum.minetest.net/mmdb/mod/*/ + +# Print the engine's profiling data in regular intervals (in seconds). 0 = disable. Useful for developers. +profiler_print_interval (Engine profiling data print interval) int 0 diff --git a/doc/lua_api.txt b/doc/lua_api.txt index 12b0a9299..e1077a2bb 100644 --- a/doc/lua_api.txt +++ b/doc/lua_api.txt @@ -3423,6 +3423,9 @@ Definition tables ### ABM (ActiveBlockModifier) definition (`register_abm`) { + label = "Lava cooling", + -- ^ Descriptive label for profiling purposes (optional). + -- Definitions with identical labels will be listed as one. -- In the following two fields, also group:groupname will work. nodenames = {"default:lava_source"}, neighbors = {"default:water_source", "default:water_flowing"}, -- Any of these --[[ @@ -3439,6 +3442,9 @@ Definition tables ### LBM (LoadingBlockModifier) definition (`register_lbm`) { + label = "Upgrade legacy doors", + -- ^ Descriptive label for profiling purposes (optional). + -- Definitions with identical labels will be listed as one. name = "modname:replace_legacy_door", nodenames = {"default:lava_source"}, -- ^ List of node names to trigger the LBM on. |