minetest/builtin/profiler/reporter.lua
Tim d7060c212f Builtin/profiler: Replace game profiler (#4245)
Use the setting "profiler.load" to enable profiling.
Other settings can be found in settingtypes.txt.

* /profiler print [filter] - report statistics to in-game console
* /profiler dump [filter] - report statistics to STDOUT and debug.txt
* /profiler save [format [filter]] - saves statistics to a file in your worldpath
	* txt (default) - same treetable format as used by the dump and print commands
	* csv - ready for spreadsheet import
	* json - useful for adhoc D3 visualizations
	* json_pretty - line wrapped and intended json for humans
	* lua - serialized lua table of the profile-data, for adhoc scripts
* /profiler reset - reset all gathered profile data.
	This can be helpful to discard of any startup measurements that often spike during loading or to get more useful min-values.

[filter] allows limiting the output of the data via substring/pattern matching against the modname.

Note: Serialized data structures might be subject to change with changed or added measurements.
	csv might be the most stable, due to flat structure.

Changes to the previous version include:

* Updated and extended API monitoring
* Correct calculation of average (mean) values (undistorted by idleness)
* Reduce instrumentation overhead.
* Fix crashes related to missing parameters for the future and occasional DIV/0's.
* Prevent issues caused by timetravel (overflow, timejump, NTP corrections)
* Prevent modname clashes with internal names.
* Measure each instrumentation individually and label based on registration order.
* Labeling of ABM's and LBM's for easier classification.
  Giving several ABM's or LBM's the same label will treat them as one.
  Missing labels will be autogenerated based on name or registration order.
* Configurable instrumentation and reporting. Skip e.g. builtin if you don't need it.
* Profile the profiler to measure instrumentation overhead.
2016-07-12 21:51:10 +02:00

278 lines
7.4 KiB
Lua

--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