diff --git a/builtin/game/chatcommands.lua b/builtin/game/chatcommands.lua
index 22755386b2dea85ef964830f328464ea8b221ce1..24792bc8a3e0a920a235e03272e41cc075745fe9 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 a6cfa3bf88cda6fc16bd62f6aac1533b1eae4fba..2f9f90315c440688d73539acebeece0471418184 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 df2d10221de28c2cd19bda51e01161f64fbe9895..0000000000000000000000000000000000000000
--- 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 0000000000000000000000000000000000000000..c1597d280bf73f0a18cc2e2d7b554bcf8cbc6533
--- /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 0000000000000000000000000000000000000000..4311215b299e7fa4c07be141ee7799ff20611e80
--- /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 0000000000000000000000000000000000000000..5b38ed4dfd34a318918c95beca7eca2c0ee0fa6c
--- /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 0000000000000000000000000000000000000000..1d1ef256d80625fc9500967ebb04cbfa4167e3d4
--- /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 0b9d29a3320eec555aaee6db565b767f5785cda2..b5878dfe89d5ebbe6840a0152eaea2a00c7e7008 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 12b0a9299c889688ecda8c1c0664201bf1545409..e1077a2bbf6eded867f54eac301216fca12aab1b 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.