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.

1 files changed, 206 insertions, 0 deletions

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