1
0
Fork 0
mirror of https://github.com/luanti-org/luanti.git synced 2025-09-15 18:57:08 +00:00

Builtin/profiler: Replace game profiler (#4245)

Use the setting "profiler.load" to enable profiling.
Other settings can be found in settingtypes.txt.

* /profiler print [filter] - report statistics to in-game console
* /profiler dump [filter] - report statistics to STDOUT and debug.txt
* /profiler save [format [filter]] - saves statistics to a file in your worldpath
	* txt (default) - same treetable format as used by the dump and print commands
	* csv - ready for spreadsheet import
	* json - useful for adhoc D3 visualizations
	* json_pretty - line wrapped and intended json for humans
	* lua - serialized lua table of the profile-data, for adhoc scripts
* /profiler reset - reset all gathered profile data.
	This can be helpful to discard of any startup measurements that often spike during loading or to get more useful min-values.

[filter] allows limiting the output of the data via substring/pattern matching against the modname.

Note: Serialized data structures might be subject to change with changed or added measurements.
	csv might be the most stable, due to flat structure.

Changes to the previous version include:

* Updated and extended API monitoring
* Correct calculation of average (mean) values (undistorted by idleness)
* Reduce instrumentation overhead.
* Fix crashes related to missing parameters for the future and occasional DIV/0's.
* Prevent issues caused by timetravel (overflow, timejump, NTP corrections)
* Prevent modname clashes with internal names.
* Measure each instrumentation individually and label based on registration order.
* Labeling of ABM's and LBM's for easier classification.
  Giving several ABM's or LBM's the same label will treat them as one.
  Missing labels will be autogenerated based on name or registration order.
* Configurable instrumentation and reporting. Skip e.g. builtin if you don't need it.
* Profile the profiler to measure instrumentation overhead.
This commit is contained in:
Tim 2016-07-12 21:51:10 +02:00 committed by est31
parent d6865c4d8d
commit d7060c212f
9 changed files with 851 additions and 380 deletions

View file

@ -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)

View file

@ -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

View file

@ -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()