Skip to content

Commit

Permalink
Mod profiling support
Browse files Browse the repository at this point in the history 
Config settings:
profiling = true/false (gather statistics)
detailed_profiling = true/false (break mod times to callbacks)

Chat commands:
save_mod_profile saves current statistics in debug.txt and shows on console (on default loglevel)
  • Loading branch information
sapier authored and sapier committed Aug 19, 2014
1 parent 4caa00c commit c24e075
Show file tree
Hide file tree
Showing 7 changed files with 391 additions and 0 deletions.
13 changes: 13 additions & 0 deletions builtin/game/chatcommands.lua
View file
Expand Up @@ -13,6 +13,19 @@ function core.register_chatcommand(cmd, def)
core.chatcommands[cmd] = def
end

if core.setting_getbool("mod_profiling") then
local tracefct = profiling_print_log
profiling_print_log = nil
core.register_chatcommand("save_mod_profile",
{
params = "",
description = "save mod profiling data to logfile " ..
"(depends on default loglevel)",
func = tracefct,
privs = { server=true }
})
end

core.register_on_chat_message(function(name, message)
local cmd, param = string.match(message, "^/([^ ]+) *(.*)")
if not param then
Expand Down
5 changes: 5 additions & 0 deletions builtin/game/init.lua
View file
Expand Up @@ -7,6 +7,11 @@ dofile(commonpath.."vector.lua")

dofile(gamepath.."item.lua")
dofile(gamepath.."register.lua")

if core.setting_getbool("mod_profiling") then
dofile(gamepath.."mod_profiling.lua")
end

dofile(gamepath.."item_entity.lua")
dofile(gamepath.."deprecated.lua")
dofile(gamepath.."misc.lua")
Expand Down
355 changes: 355 additions & 0 deletions builtin/game/mod_profiling.lua
View file
@@ -0,0 +1,355 @@
-- Minetest: builtin/game/mod_profiling.lua

local mod_statistics = {}
mod_statistics.step_total = 0
mod_statistics.data = {}
mod_statistics.stats = {}
mod_statistics.stats["total"] = {
min_us = math.huge,
max_us = 0,
avg_us = 0,
min_per = 100,
max_per = 100,
avg_per = 100
}

local replacement_table = {
"register_globalstep",
"register_on_placenode",
"register_on_dignode",
"register_on_punchnode",
"register_on_generated",
"register_on_newplayer",
"register_on_dieplayer",
"register_on_respawnplayer",
"register_on_prejoinplayer",
"register_on_joinplayer",
"register_on_leaveplayer",
"register_on_cheat",
"register_on_chat_message",
"register_on_player_receive_fields",
"register_on_mapgen_init",
"register_on_craft",
"register_craft_predict",
"register_on_item_eat"
}

--------------------------------------------------------------------------------
function mod_statistics.log_time(type, modname, time_in_us)

if modname == nil then
modname = "builtin"
end

if mod_statistics.data[modname] == nil then
mod_statistics.data[modname] = {}
end

if mod_statistics.data[modname][type] == nil then
mod_statistics.data[modname][type] = 0
end

mod_statistics.data[modname][type] =
mod_statistics.data[modname][type] + time_in_us
mod_statistics.step_total = mod_statistics.step_total + time_in_us
end

--------------------------------------------------------------------------------
function mod_statistics.update_statistics(dtime)
for modname,types in pairs(mod_statistics.data) do

if mod_statistics.stats[modname] == nil then
mod_statistics.stats[modname] = {
min_us = math.huge,
max_us = 0,
avg_us = 0,
min_per = 100,
max_per = 0,
avg_per = 0
}
end

local modtime = 0
for type,time in pairs(types) do
modtime = modtime + time
if mod_statistics.stats[modname].types == nil then
mod_statistics.stats[modname].types = {}
end
if mod_statistics.stats[modname].types[type] == nil then
mod_statistics.stats[modname].types[type] = {
min_us = math.huge,
max_us = 0,
avg_us = 0,
min_per = 100,
max_per = 0,
avg_per = 0
}
end

local toupdate = mod_statistics.stats[modname].types[type]

--update us values
toupdate.min_us = math.min(time, toupdate.min_us)
toupdate.max_us = math.max(time, toupdate.max_us)
--TODO find better algorithm
toupdate.avg_us = toupdate.avg_us * 0.99 + modtime * 0.01

--update percentage values
local cur_per = (time/mod_statistics.step_total) * 100
toupdate.min_per = math.min(toupdate.min_per, cur_per)

toupdate.max_per = math.max(toupdate.max_per, cur_per)

--TODO find better algorithm
toupdate.avg_per = toupdate.avg_per * 0.99 + cur_per * 0.01

mod_statistics.data[modname][type] = 0
end

--per mod statistics
--update us values
mod_statistics.stats[modname].min_us =
math.min(modtime, mod_statistics.stats[modname].min_us)
mod_statistics.stats[modname].max_us =
math.max(modtime, mod_statistics.stats[modname].max_us)
--TODO find better algorithm
mod_statistics.stats[modname].avg_us =
mod_statistics.stats[modname].avg_us * 0.99 + modtime * 0.01

--update percentage values
local cur_per = (modtime/mod_statistics.step_total) * 100
mod_statistics.stats[modname].min_per =
math.min(mod_statistics.stats[modname].min_per, cur_per)

mod_statistics.stats[modname].max_per =
math.max(mod_statistics.stats[modname].max_per, cur_per)

--TODO find better algorithm
mod_statistics.stats[modname].avg_per =
mod_statistics.stats[modname].avg_per * 0.99 + cur_per * 0.01
end

--update "total"
mod_statistics.stats["total"].min_us =
math.min(mod_statistics.step_total, mod_statistics.stats["total"].min_us)
mod_statistics.stats["total"].max_us =
math.max(mod_statistics.step_total, mod_statistics.stats["total"].max_us)
--TODO find better algorithm
mod_statistics.stats["total"].avg_us =
mod_statistics.stats["total"].avg_us * 0.99 +
mod_statistics.step_total * 0.01

mod_statistics.step_total = 0
end

--------------------------------------------------------------------------------
local function build_callback(log_id, fct)
return function( toregister )
local modname = core.get_current_modname()

fct(function(...)
local starttime = core.get_us_time()
-- note maximum 10 return values are supported unless someone finds
-- a way to store a variable lenght return value list
local r0, r1, r2, r3, r4, r5, r6, r7, r8, r9 = toregister(...)
local delta = core.get_us_time() - starttime
mod_statistics.log_time(log_id, modname, delta)
return r0, r1, r2, r3, r4, r5, r6, r7, r8, r9
end
)
end
end

--------------------------------------------------------------------------------
function profiling_print_log(cmd, filter)

print("Filter:" .. dump(filter))

core.log("action", "Values below show times/percentages per server step.")
core.log("action", "Following suffixes are used for entities:")
core.log("action", "\t#oa := on_activate, #os := on_step, #op := on_punch, #or := on_rightclick, #gs := get_staticdata")
core.log("action",
string.format("%16s | %25s | %10s | %10s | %10s | %9s | %9s | %9s",
"modname", "type" , "min µs", "max µs", "avg µs", "min %", "max %", "avg %")
)
core.log("action",
"-----------------+---------------------------+-----------+" ..
"-----------+-----------+-----------+-----------+-----------")
for modname,statistics in pairs(mod_statistics.stats) do
if modname ~= "total" then

if (filter == "") or (modname == filter) then
if modname:len() > 16 then
modname = "..." .. modname:sub(-13)
end

core.log("action",
string.format("%16s | %25s | %9d | %9d | %9d | %9d | %9d | %9d",
modname,
" ",
statistics.min_us,
statistics.max_us,
statistics.avg_us,
statistics.min_per,
statistics.max_per,
statistics.avg_per)
)
if core.setting_getbool("detailed_profiling") then
if statistics.types ~= nil then
for type,typestats in pairs(statistics.types) do

if type:len() > 25 then
type = "..." .. type:sub(-22)
end

core.log("action",
string.format(
"%16s | %25s | %9d | %9d | %9d | %9d | %9d | %9d",
" ",
type,
typestats.min_us,
typestats.max_us,
typestats.avg_us,
typestats.min_per,
typestats.max_per,
typestats.avg_per)
)
end
end
end
end
end
end
core.log("action",
"-----------------+---------------------------+-----------+" ..
"-----------+-----------+-----------+-----------+-----------")

if filter == "" then
core.log("action",
string.format("%16s | %25s | %9d | %9d | %9d | %9d | %9d | %9d",
"total",
" ",
mod_statistics.stats["total"].min_us,
mod_statistics.stats["total"].max_us,
mod_statistics.stats["total"].avg_us,
mod_statistics.stats["total"].min_per,
mod_statistics.stats["total"].max_per,
mod_statistics.stats["total"].avg_per)
)
end
core.log("action", " ")

return true
end

--------------------------------------------------------------------------------
local function initialize_profiling()
core.log("action", "Initialize tracing")

mod_statistics.entity_callbacks = {}

-- first register our own globalstep handler
core.register_globalstep(mod_statistics.update_statistics)

local rp_register_entity = core.register_entity
core.register_entity = function(name, prototype)
local modname = core.get_current_modname()
local new_on_activate = nil
local new_on_step = nil
local new_on_punch = nil
local new_rightclick = nil
local new_get_staticdata = nil

if prototype.on_activate ~= nil then
local cbid = name .. "#oa"
mod_statistics.entity_callbacks[cbid] = prototype.on_activate
new_on_activate = function(self, staticdata, dtime_s)
local starttime = core.get_us_time()
mod_statistics.entity_callbacks[cbid](self, staticdata, dtime_s)

This comment has been minimized.

Sign in to view

Copy link
@HybridDog

HybridDog May 25, 2016 •
edited

Contributor

What would happen if you execute prototype.on_activate here?
local delta = core.get_us_time() -starttime
mod_statistics.log_time(cbid, modname, delta)
end
end

This comment has been minimized.

Sign in to view

Copy link
@HybridDog

HybridDog May 25, 2016 •
edited

Contributor

@sapier, mod profiling causes stack overflow crashes for me if mods override entities

minetest.register_entity("lam:ent", {
    on_activate = function()
        do_sth()
    end
})

local ent = minetest.registered_entities["lam:ent"]
local old_activate = ent.on_activate
ent.on_activate = function(...)
    old_activate(...)
    do_supplement()
end
minetest.register_entity(":lam:ent", ent)

--[[ unwrapped:
on_activate = function(self, staticdata, dtime_s)
    local starttime = core.get_us_time()
        local starttime = core.get_us_time()
            local starttime = core.get_us_time()
                […] aborts due to stack overflow
                    do_sth()
                […]
            local delta = core.get_us_time() -starttime
            mod_statistics.log_time(cbid, modname, delta)
        local delta = core.get_us_time() -starttime
        mod_statistics.log_time(cbid, modname, delta)
        do_supplement()
    local delta = core.get_us_time() -starttime
    mod_statistics.log_time(cbid, modname, delta)
end--]]

This comment has been minimized.

Sign in to view

Copy link
@rubenwardy

rubenwardy May 25, 2016

Member

I assume do_sth() and do_supplement() are just print statements?

This comment has been minimized.

Sign in to view

Copy link
@HybridDog

HybridDog May 25, 2016

Contributor

They're just dummies, do_supplement() can e.g. set some variable to something
https://github.com/HybridDog/pipeworks/blob/hversion/vacuum_tubes.lua#L243

if prototype.on_step ~= nil then
local cbid = name .. "#os"
mod_statistics.entity_callbacks[cbid] = prototype.on_step
new_on_step = function(self, dtime)
local starttime = core.get_us_time()
mod_statistics.entity_callbacks[cbid](self, dtime)
local delta = core.get_us_time() -starttime
mod_statistics.log_time(cbid, modname, delta)
end
end

if prototype.on_punch ~= nil then
local cbid = name .. "#op"
mod_statistics.entity_callbacks[cbid] = prototype.on_punch
new_on_punch = function(self, hitter)
local starttime = core.get_us_time()
mod_statistics.entity_callbacks[cbid](self, hitter)
local delta = core.get_us_time() -starttime
mod_statistics.log_time(cbid, modname, delta)
end
end

if prototype.rightclick ~= nil then
local cbid = name .. "#rc"
mod_statistics.entity_callbacks[cbid] = prototype.rightclick
new_rightclick = function(self, clicker)
local starttime = core.get_us_time()
mod_statistics.entity_callbacks[cbid](self, clicker)
local delta = core.get_us_time() -starttime
mod_statistics.log_time(cbid, modname, delta)
end
end

if prototype.get_staticdata ~= nil then
local cbid = name .. "#gs"
mod_statistics.entity_callbacks[cbid] = prototype.get_staticdata
new_get_staticdata = function(self)
local starttime = core.get_us_time()
mod_statistics.entity_callbacks[cbid](self)
local delta = core.get_us_time() -starttime
mod_statistics.log_time(cbid, modname, delta)
end
end

prototype.on_activate = new_on_activate
prototype.on_step = new_on_step
prototype.on_punch = new_on_punch
prototype.rightclick = new_rightclick
prototype.get_staticdata = new_get_staticdata

rp_register_entity(name,prototype)
end

for i,v in ipairs(replacement_table) do
local to_replace = core[v]
core[v] = build_callback(v, to_replace)
end

local rp_register_abm = core.register_abm
core.register_abm = function(spec)

local modname = core.get_current_modname()

local replacement_spec = {
nodenames = spec.nodenames,
neighbors = spec.neighbors,
interval = spec.interval,
chance = spec.chance,
action = function(pos, node, active_object_count, active_object_count_wider)
local starttime = core.get_us_time()
spec.action(pos, node, active_object_count, active_object_count_wider)
local delta = core.get_us_time() - starttime
mod_statistics.log_time("abm", modname, delta)
end
}
rp_register_abm(replacement_spec)
end

core.log("action", "Mod profiling initialized")
end

initialize_profiling()
2 changes: 2 additions & 0 deletions doc/lua_api.txt
View file
Expand Up @@ -1535,6 +1535,8 @@ minetest.set_node_level(pos, level)
^ set level of leveled node, default level = 1, if totallevel > maxlevel returns rest (total-max).
minetest.add_node_level(pos, level)
^ increase level of leveled node by level, default level = 1, if totallevel > maxlevel returns rest (total-max). can be negative for decreasing
minetest.get_time_us()
^ get time in microseconds

Inventory:
minetest.get_inventory(location) -> InvRef
Expand Down

0 comments on commit c24e075

Please sign in to comment.