| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -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 |
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -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, | ||
| } |
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -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 |
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -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 |