Initial commit

This commit is contained in:
2023-02-19 21:41:32 +01:00
commit 74d5334e72
1522 changed files with 753891 additions and 0 deletions

80
builtin/profiler/init.lua Normal file
View File

@@ -0,0 +1,80 @@
--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 S = core.get_translator("__builtin")
local function get_bool_default(name, default)
local val = core.settings:get_bool(name)
if val == nil then
return default
end
return val
end
local profiler_path = core.get_builtin_path().."profiler"..DIR_DELIM
local profiler = {}
local sampler = assert(loadfile(profiler_path .. "sampling.lua"))(profiler)
local instrumentation = assert(loadfile(profiler_path .. "instrumentation.lua"))(profiler, sampler, get_bool_default)
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 = get_bool_default("instrument.profiler", false)
if instrument_profiler then
instrumentation.init_chatcommand()
end
local param_usage = S("print [<filter>] | dump [<filter>] | save [<format> [<filter>]] | reset")
core.register_chatcommand("profiler", {
description = S("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, S("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, S("Statistics were reset.")
end
return false,
S("Usage: @1", param_usage) .. "\n" ..
S("Format can be one of txt, csv, lua, json, json_pretty (structures may be subject to change).")
end
})
if not instrument_profiler then
instrumentation.init_chatcommand()
end
end
sampler.init()
instrumentation.init()
return profiler

View File

@@ -0,0 +1,235 @@
--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, get_bool_default = ...
local instrument_builtin = get_bool_default("instrument.builtin", 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() or "??"
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 func(...)
local start = time()
return measure(modname, instrument_name, start, 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 get_bool_default("instrument.chatcommand", 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()
if get_bool_default("instrument.entity", true) then
-- Explicitly declare entity api-methods.
-- Simple iteration would ignore lookup via __index.
local entity_instrumentation = {
"on_activate",
"on_deactivate",
"on_step",
"on_punch",
"on_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 get_bool_default("instrument.abm", 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 get_bool_default("instrument.lbm", 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 get_bool_default("instrument.global_callback", true) then
for func_name, _ in pairs(register_functions) do
core[func_name] = instrument_register(core[func_name], func_name)
end
end
if get_bool_default("instrument.profiler", 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,
}

View File

@@ -0,0 +1,280 @@
--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 S = core.get_translator("__builtin")
-- Note: In this file, only messages are translated
-- but not the table itself, to keep it simple.
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, settings = core, core.settings
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(S("Values below show absolute/relative times spend per server step by the instrumented function."))
self:print(S("A total of @1 sample(s) were taken.", profile.stats_total.samples))
if filter then
self:print(S("The output is limited to '@1'.", 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 = settings: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 = settings: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, S("Saving of profile failed: @1", io_err)
end
local content, err = serialize_profile(profile, format, filter)
if not content then
output:close()
return false, S("Saving of profile failed: @1", err)
end
output:write(content)
output:close()
core.log("action", "Profile saved to " .. path)
return true, S("Profile saved to @1", path)
end
return reporter

View File

@@ -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.settings:get_bool("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