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, 232 insertions, 0 deletions

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,
+}