New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Mod profiling support #1557
Closed
Closed
Mod profiling support #1557
Changes from all commits
Commits
File filter
Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
There are no files selected for viewing
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Original file line number | Diff line number | Diff line change |
---|---|---|
@@ -0,0 +1,353 @@ | ||
-- 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", | ||
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") | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. tracing -> profiling |
||
|
||
mod_statistics.entity_callbacks = {} | ||
|
||
-- first register our own globalstep handler | ||
core.register_globalstep(mod_statistics.update_statistics) | ||
|
||
local rp_register_entity = core.register_entity | ||
core.register_entity = function(name, prototype) | ||
local modname = core.get_current_modname() | ||
local new_on_activate = nil | ||
local new_on_step = nil | ||
local new_on_punch = nil | ||
local new_rightclick = nil | ||
local new_get_staticdata = nil | ||
|
||
if prototype.on_activate ~= nil then | ||
local cbid = name .. "#oa" | ||
mod_statistics.entity_callbacks[cbid] = prototype.on_activate | ||
new_on_activate = function(self, staticdata, dtime_s) | ||
local starttime = core.get_us_time() | ||
mod_statistics.entity_callbacks[cbid](self, staticdata, dtime_s) | ||
local delta = core.get_us_time() -starttime | ||
mod_statistics.log_time(cbid, modname, delta) | ||
end | ||
end | ||
|
||
if prototype.on_step ~= nil then | ||
local cbid = name .. "#os" | ||
mod_statistics.entity_callbacks[cbid] = prototype.on_step | ||
new_on_step = function(self, dtime) | ||
local starttime = core.get_us_time() | ||
mod_statistics.entity_callbacks[cbid](self, dtime) | ||
local delta = core.get_us_time() -starttime | ||
mod_statistics.log_time(cbid, modname, delta) | ||
end | ||
end | ||
|
||
if prototype.on_punch ~= nil then | ||
local cbid = name .. "#op" | ||
mod_statistics.entity_callbacks[cbid] = prototype.on_punch | ||
new_on_punch = function(self, hitter) | ||
local starttime = core.get_us_time() | ||
mod_statistics.entity_callbacks[cbid](self, hitter) | ||
local delta = core.get_us_time() -starttime | ||
mod_statistics.log_time(cbid, modname, delta) | ||
end | ||
end | ||
|
||
if prototype.rightclick ~= nil then | ||
local cbid = name .. "#rc" | ||
mod_statistics.entity_callbacks[cbid] = prototype.rightclick | ||
new_rightclick = function(self, clicker) | ||
local starttime = core.get_us_time() | ||
mod_statistics.entity_callbacks[cbid](self, clicker) | ||
local delta = core.get_us_time() -starttime | ||
mod_statistics.log_time(cbid, modname, delta) | ||
end | ||
end | ||
|
||
if prototype.get_staticdata ~= nil then | ||
local cbid = name .. "#gs" | ||
mod_statistics.entity_callbacks[cbid] = prototype.get_staticdata | ||
new_get_staticdata = function(self) | ||
local starttime = core.get_us_time() | ||
mod_statistics.entity_callbacks[cbid](self) | ||
local delta = core.get_us_time() -starttime | ||
mod_statistics.log_time(cbid, modname, delta) | ||
end | ||
end | ||
|
||
prototype.on_activate = new_on_activate | ||
prototype.on_step = new_on_step | ||
prototype.on_punch = new_on_punch | ||
prototype.rightclick = new_rightclick | ||
prototype.get_staticdata = new_get_staticdata | ||
|
||
rp_register_entity(name,prototype) | ||
end | ||
|
||
for i,v in ipairs(replacement_table) do | ||
local to_replace = core[v] | ||
core[v] = build_callback(v, to_replace) | ||
end | ||
|
||
local rp_register_abm = core.register_abm | ||
core.register_abm = function(spec) | ||
|
||
local modname = core.get_current_modname() | ||
|
||
local replacement_spec = { | ||
nodenames = spec.nodenames, | ||
neighbors = spec.neighbors, | ||
interval = spec.interval, | ||
chance = spec.chance, | ||
action = function(pos, node, active_object_count, active_object_count_wider) | ||
local starttime = core.get_us_time() | ||
spec.action(pos, node, active_object_count, active_object_count_wider) | ||
local delta = core.get_us_time() - starttime | ||
mod_statistics.log_time("abm", modname, delta) | ||
end | ||
} | ||
rp_register_abm(replacement_spec) | ||
end | ||
|
||
core.log("action", "Mod tracing initialized") | ||
end | ||
|
||
initialize_profiling() |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Oops, something went wrong.
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
space between comma and next argument