diff options
Diffstat (limited to 'builtin/profiler')
| -rw-r--r-- | builtin/profiler/init.lua | 72 | ||||
| -rw-r--r-- | builtin/profiler/instrumentation.lua | 232 | ||||
| -rw-r--r-- | builtin/profiler/reporter.lua | 277 | ||||
| -rw-r--r-- | builtin/profiler/sampling.lua | 206 |
4 files changed, 787 insertions, 0 deletions
diff --git a/builtin/profiler/init.lua b/builtin/profiler/init.lua new file mode 100644 index 000000000..c1597d280 --- /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 000000000..4311215b2 --- /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 000000000..5b38ed4df --- /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 000000000..1d1ef256d --- /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 |