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.

9 files changed, 851 insertions, 380 deletions

diff --git a/builtin/game/chatcommands.lua b/builtin/game/chatcommands.lua
index 22755386b..24792bc8a 100644
--- a/builtin/game/chatcommands.lua
+++ b/builtin/game/chatcommands.lua
@@ -14,19 +14,6 @@ function core.register_chatcommand(cmd, def)
 	core.chatcommands[cmd] = def
 end
 
-if core.setting_getbool("mod_profiling") then
-	local tracefct = profiling_print_log
-	profiling_print_log = nil
-	core.register_chatcommand("save_mod_profile",
-			{
-				params      = "",
-				description = "save mod profiling data to logfile " ..
-						"(depends on default loglevel)",
-				func        = tracefct,
-				privs       = { server=true }
-			})
-end
-
 core.register_on_chat_message(function(name, message)
 	local cmd, param = string.match(message, "^/([^ ]+) *(.*)")
 	if not param then
@@ -51,6 +38,12 @@ core.register_on_chat_message(function(name, message)
 	return true  -- Handled chat message
 end)
 
+if core.setting_getbool("profiler.load") then
+	-- Run after register_chatcommand and its register_on_chat_message
+	-- Before any chattcommands that should be profiled
+	profiler.init_chatcommand()
+end
+
 -- Parses a "range" string in the format of "here (number)" or
 -- "(x1, y1, z1) (x2, y2, z2)", returning two position vectors
 local function parse_range_str(player_name, str)
diff --git a/builtin/game/init.lua b/builtin/game/init.lua
index a6cfa3bf8..2f9f90315 100644
--- a/builtin/game/init.lua
+++ b/builtin/game/init.lua
@@ -9,8 +9,8 @@ dofile(gamepath.."constants.lua")
 dofile(gamepath.."item.lua")
 dofile(gamepath.."register.lua")
 
-if core.setting_getbool("mod_profiling") then
-	dofile(gamepath.."mod_profiling.lua")
+if core.setting_getbool("profiler.load") then
+	profiler = dofile(scriptpath.."profiler"..DIR_DELIM.."init.lua")
 end
 
 dofile(gamepath.."item_entity.lua")
@@ -26,3 +26,5 @@ dofile(gamepath.."features.lua")
 dofile(gamepath.."voxelarea.lua")
 dofile(gamepath.."forceloading.lua")
 dofile(gamepath.."statbars.lua")
+
+profiler = nil
diff --git a/builtin/game/mod_profiling.lua b/builtin/game/mod_profiling.lua
deleted file mode 100644
index df2d10221..000000000
--- a/builtin/game/mod_profiling.lua
+++ /dev/null
@@ -1,356 +0,0 @@
--- Minetest: builtin/game/mod_profiling.lua
-
-local mod_statistics = {}
-mod_statistics.step_total = 0
-mod_statistics.data = {}
-mod_statistics.stats = {}
-mod_statistics.stats["total"] = {
-	min_us = math.huge,
-	max_us = 0,
-	avg_us = 0,
-	min_per = 100,
-	max_per = 100,
-	avg_per = 100
-}
-
-local replacement_table = {
-	"register_globalstep",
-	"register_on_placenode",
-	"register_on_dignode",
-	"register_on_punchnode",
-	"register_on_generated",
-	"register_on_newplayer",
-	"register_on_dieplayer",
-	"register_on_respawnplayer",
-	"register_on_prejoinplayer",
-	"register_on_joinplayer",
-	"register_on_leaveplayer",
-	"register_on_cheat",
-	"register_on_chat_message",
-	"register_on_player_receive_fields",
-	"register_on_mapgen_init",
-	"register_on_craft",
-	"register_craft_predict",
-	"register_on_item_eat"
-}
-
---------------------------------------------------------------------------------
-function mod_statistics.log_time(type, modname, time_in_us)
-
-	if modname == nil then
-		modname = "builtin"
-	end
-	
-	if mod_statistics.data[modname] == nil then
-		mod_statistics.data[modname] = {}
-	end
-	
-	if mod_statistics.data[modname][type] == nil then
-		mod_statistics.data[modname][type] = 0
-	end
-	
-	mod_statistics.data[modname][type] =
-		mod_statistics.data[modname][type] + time_in_us
-	mod_statistics.step_total = mod_statistics.step_total + time_in_us
-end
-
---------------------------------------------------------------------------------
-function mod_statistics.update_statistics(dtime)
-	for modname,types in pairs(mod_statistics.data) do
-		
-		if mod_statistics.stats[modname] == nil then
-			mod_statistics.stats[modname] = {
-				min_us = math.huge,
-				max_us = 0,
-				avg_us = 0,
-				min_per = 100,
-				max_per = 0,
-				avg_per = 0
-			}
-		end
-		
-		local modtime = 0
-		for type,time in pairs(types) do
-			modtime = modtime + time
-			if mod_statistics.stats[modname].types == nil then
-				mod_statistics.stats[modname].types = {}
-			end
-			if mod_statistics.stats[modname].types[type] == nil then
-				mod_statistics.stats[modname].types[type] = {
-					min_us = math.huge,
-					max_us = 0,
-					avg_us = 0,
-					min_per = 100,
-					max_per = 0,
-					avg_per = 0
-				}
-			end
-			
-			local toupdate = mod_statistics.stats[modname].types[type]
-			
-			--update us values
-			toupdate.min_us = math.min(time, toupdate.min_us)
-			toupdate.max_us = math.max(time, toupdate.max_us)
-			--TODO find better algorithm
-			toupdate.avg_us = toupdate.avg_us * 0.99 + modtime * 0.01
-				
-			--update percentage values
-			local cur_per = (time/mod_statistics.step_total) * 100
-			toupdate.min_per = math.min(toupdate.min_per, cur_per)
-				
-			toupdate.max_per = math.max(toupdate.max_per, cur_per)
-				
-			--TODO find better algorithm
-			toupdate.avg_per = toupdate.avg_per * 0.99 + cur_per * 0.01
-			
-			mod_statistics.data[modname][type] = 0
-		end
-		
-		--per mod statistics
-		--update us values
-		mod_statistics.stats[modname].min_us =
-			math.min(modtime, mod_statistics.stats[modname].min_us)
-		mod_statistics.stats[modname].max_us =
-			math.max(modtime, mod_statistics.stats[modname].max_us)
-		--TODO find better algorithm
-		mod_statistics.stats[modname].avg_us =
-			mod_statistics.stats[modname].avg_us * 0.99 + modtime * 0.01
-			
-		--update percentage values
-		local cur_per = (modtime/mod_statistics.step_total) * 100
-		mod_statistics.stats[modname].min_per =
-			math.min(mod_statistics.stats[modname].min_per, cur_per)
-			
-		mod_statistics.stats[modname].max_per =
-			math.max(mod_statistics.stats[modname].max_per, cur_per)
-			
-		--TODO find better algorithm
-		mod_statistics.stats[modname].avg_per =
-			mod_statistics.stats[modname].avg_per * 0.99 + cur_per * 0.01
-	end
-	
-	--update "total"
-	mod_statistics.stats["total"].min_us =
-		math.min(mod_statistics.step_total, mod_statistics.stats["total"].min_us)
-	mod_statistics.stats["total"].max_us =
-		math.max(mod_statistics.step_total, mod_statistics.stats["total"].max_us)
-	--TODO find better algorithm
-	mod_statistics.stats["total"].avg_us =
-		mod_statistics.stats["total"].avg_us * 0.99 +
-		mod_statistics.step_total * 0.01
-	
-	mod_statistics.step_total = 0
-end
-
---------------------------------------------------------------------------------
-local function build_callback(log_id, fct)
-	return function( toregister )
-		local modname = core.get_current_modname()
-		
-		fct(function(...)
-			local starttime = core.get_us_time()
-			-- note maximum 10 return values are supported unless someone finds
-			-- a way to store a variable lenght return value list
-			local r0, r1, r2, r3, r4, r5, r6, r7, r8, r9 = toregister(...)
-			local delta = core.get_us_time() - starttime
-			mod_statistics.log_time(log_id, modname, delta)
-			return r0, r1, r2, r3, r4, r5, r6, r7, r8, r9
-			end
-		)
-	end
-end
-
---------------------------------------------------------------------------------
-function profiling_print_log(cmd, filter)
-
-	print("Filter:" .. dump(filter))
-
-	core.log("action", "Values below show times/percentages per server step.")
-	core.log("action", "Following suffixes are used for entities:")
-	core.log("action", "\t#oa := on_activate, #os := on_step, #op := on_punch, #or := on_rightclick, #gs := get_staticdata")
-	core.log("action",
-		string.format("%16s | %25s | %10s | %10s | %10s | %9s | %9s | %9s",
-		"modname", "type" , "min µs", "max µs", "avg µs", "min %", "max %", "avg %")
-	)
-	core.log("action",
-		"-----------------+---------------------------+-----------+" ..
-		"-----------+-----------+-----------+-----------+-----------")
-	for modname,statistics in pairs(mod_statistics.stats) do
-		if modname ~= "total" then
-		
-			if (filter == "") or (modname == filter) then
-				if modname:len() > 16 then
-					modname = "..." .. modname:sub(-13)
-				end
-			
-				core.log("action",
-					string.format("%16s | %25s | %9d | %9d | %9d | %9d | %9d | %9d",
-					modname,
-					" ",
-					statistics.min_us,
-					statistics.max_us,
-					statistics.avg_us,
-					statistics.min_per,
-					statistics.max_per,
-					statistics.avg_per)
-				)
-				if core.setting_getbool("detailed_profiling") then
-					if statistics.types ~= nil then
-						for type,typestats in pairs(statistics.types) do
-						
-							if type:len() > 25 then
-								type = "..." .. type:sub(-22)
-							end
-						
-							core.log("action",
-								string.format(
-								"%16s | %25s | %9d | %9d | %9d | %9d | %9d | %9d",
-								" ",
-								type,
-								typestats.min_us,
-								typestats.max_us,
-								typestats.avg_us,
-								typestats.min_per,
-								typestats.max_per,
-								typestats.avg_per)
-							)
-						end
-					end
-				end
-			end
-		end
-	end
-		core.log("action",
-			"-----------------+---------------------------+-----------+" ..
-			"-----------+-----------+-----------+-----------+-----------")
-			
-	if filter == "" then
-		core.log("action",
-			string.format("%16s | %25s | %9d | %9d | %9d | %9d | %9d | %9d",
-			"total",
-			" ",
-			mod_statistics.stats["total"].min_us,
-			mod_statistics.stats["total"].max_us,
-			mod_statistics.stats["total"].avg_us,
-			mod_statistics.stats["total"].min_per,
-			mod_statistics.stats["total"].max_per,
-			mod_statistics.stats["total"].avg_per)
-		)
-	end
-	core.log("action", " ")
-	
-	return true
-end
-
---------------------------------------------------------------------------------
-local function initialize_profiling()
-	core.log("action", "Initialize tracing")
-	
-	mod_statistics.entity_callbacks = {}
-	
-	-- first register our own globalstep handler
-	core.register_globalstep(mod_statistics.update_statistics)
-	
-	local rp_register_entity = core.register_entity
-	core.register_entity = function(name, prototype)
-		local modname = core.get_current_modname()
-		local new_on_activate = nil
-		local new_on_step = nil
-		local new_on_punch = nil
-		local new_rightclick = nil
-		local new_get_staticdata = nil
-		
-		if prototype.on_activate ~= nil then
-			local cbid = name .. "#oa"
-			mod_statistics.entity_callbacks[cbid] = prototype.on_activate
-			new_on_activate = function(self, staticdata, dtime_s)
-				local starttime = core.get_us_time()
-				mod_statistics.entity_callbacks[cbid](self, staticdata, dtime_s)
-				local delta = core.get_us_time() -starttime
-				mod_statistics.log_time(cbid, modname, delta)
-			end
-		end
-		
-		if prototype.on_step ~= nil then
-			local cbid = name .. "#os"
-			mod_statistics.entity_callbacks[cbid] = prototype.on_step
-			new_on_step = function(self, dtime)
-				local starttime = core.get_us_time()
-				mod_statistics.entity_callbacks[cbid](self, dtime)
-				local delta = core.get_us_time() -starttime
-				mod_statistics.log_time(cbid, modname, delta)
-			end
-		end
-	
-		if prototype.on_punch ~= nil then
-			local cbid = name .. "#op"
-			mod_statistics.entity_callbacks[cbid] = prototype.on_punch
-			new_on_punch = function(self, hitter)
-				local starttime = core.get_us_time()
-				mod_statistics.entity_callbacks[cbid](self, hitter)
-				local delta = core.get_us_time() -starttime
-				mod_statistics.log_time(cbid, modname, delta)
-			end
-		end
-		
-		if prototype.rightclick ~= nil then
-			local cbid = name .. "#rc"
-			mod_statistics.entity_callbacks[cbid] = prototype.rightclick
-			new_rightclick = function(self, clicker)
-				local starttime = core.get_us_time()
-				mod_statistics.entity_callbacks[cbid](self, clicker)
-				local delta = core.get_us_time() -starttime
-				mod_statistics.log_time(cbid, modname, delta)
-			end
-		end
-		
-		if prototype.get_staticdata ~= nil then
-			local cbid = name .. "#gs"
-			mod_statistics.entity_callbacks[cbid] = prototype.get_staticdata
-			new_get_staticdata = function(self)
-				local starttime = core.get_us_time()
-				local retval = mod_statistics.entity_callbacks[cbid](self)
-				local delta = core.get_us_time() -starttime
-				mod_statistics.log_time(cbid, modname, delta)
-				return retval
-			end
-		end
-	
-		prototype.on_activate = new_on_activate
-		prototype.on_step = new_on_step
-		prototype.on_punch = new_on_punch
-		prototype.rightclick = new_rightclick
-		prototype.get_staticdata = new_get_staticdata
-		
-		rp_register_entity(name,prototype)
-	end
-	
-	for i,v in ipairs(replacement_table) do
-		local to_replace = core[v]
-		core[v] = build_callback(v, to_replace)
-	end
-	
-	local rp_register_abm = core.register_abm
-	core.register_abm = function(spec)
-	
-		local modname = core.get_current_modname()
-	
-		local replacement_spec = {
-			nodenames = spec.nodenames,
-			neighbors = spec.neighbors,
-			interval  = spec.interval,
-			chance    = spec.chance,
-			action = function(pos, node, active_object_count, active_object_count_wider)
-				local starttime = core.get_us_time()
-				spec.action(pos, node, active_object_count, active_object_count_wider)
-				local delta = core.get_us_time() - starttime
-				mod_statistics.log_time("abm", modname, delta)
-			end
-		}
-		rp_register_abm(replacement_spec)
-	end
-	
-	core.log("action", "Mod profiling initialized")
-end
-
-initialize_profiling()
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
diff --git a/builtin/settingtypes.txt b/builtin/settingtypes.txt
index 0b9d29a33..b5878dfe8 100644
--- a/builtin/settingtypes.txt
+++ b/builtin/settingtypes.txt
@@ -790,15 +790,6 @@ movement_gravity (Gravity) float 9.81
 #    -    error: abort on usage of deprecated call (suggested for mod developers).
 deprecated_lua_api_handling (Deprecated Lua API handling) enum legacy legacy,log,error
 
-#    Useful for mod developers.
-mod_profiling (Mod profiling) bool false
-
-#    Detailed mod profile data. Useful for mod developers.
-detailed_profiling (Detailed mod profiling) bool false
-
-#    Profiler data print interval. 0 = disable. Useful for developers.
-profiler_print_interval (Profiling print interval) int 0
-
 #    Number of extra blocks that can be loaded by /clearobjects at once.
 #    This is a trade-off between sqlite transaction overhead and
 #    memory consumption (4096=100MB, as a rule of thumb).
@@ -1163,6 +1154,51 @@ secure.trusted_mods (Trusted mods) string
 #	allow them to upload and download data to/from the internet.
 secure.http_mods (HTTP Mods) string
 
+[*Advanced]
+
+[**Profiling]
+#    Load the game profiler to collect game profiling data.
+#    Provides a /profiler command to access the compiled profile.
+#    Useful for mod developers and server operators.
+profiler.load (Load the game profiler) bool false
+
+#    The default format in which profiles are being saved,
+#    when calling `/profiler save [format]` without format.
+profiler.default_report_format (Default report format) enum txt txt,csv,lua,json,json_pretty
+
+#    The file path relative to your worldpath in which profiles will be saved to.
+#
+profiler.report_path (Report path) string ""
+
+[***Instrumentation]
+
+#    Instrument the methods of entities on registration.
+instrument.entity (Entity methods) bool true
+
+#    Instrument the action function of Active Block Modifiers on registration.
+instrument.abm (Active Block Modifiers) bool true
+
+#    Instrument the action function of Loading Block Modifiers on registration.
+instrument.lbm (Loading Block Modifiers) bool true
+
+#    Instrument chatcommands on registration.
+instrument.chatcommand (Chatcommands) bool true
+
+#    Instrument global callback functions on registration.
+#    (anything you pass to a minetest.register_*() function)
+instrument.global_callback (Global callbacks) bool true
+
+[****Advanced]
+#    Instrument builtin.
+#    This is usually only needed by core/builtin contributors
+instrument.builtin (Builtin) bool false
+
+#    Have the profiler instrument itself:
+#     * Instrument an empty function.
+#       This estimates the overhead, that instrumentation is adding (+1 function call).
+#     * Instrument the sampler being used to update the statistics.
+instrument.profiler (Profiler) bool false
+
 [Client and Server]
 
 #    Name of the player.
@@ -1218,3 +1254,6 @@ modstore_download_url (Modstore download URL) string https://forum.minetest.net/
 modstore_listmods_url (Modstore mods list URL) string https://forum.minetest.net/mmdb/mods/
 
 modstore_details_url (Modstore details URL) string https://forum.minetest.net/mmdb/mod/*/
+
+#    Print the engine's profiling data in regular intervals (in seconds). 0 = disable. Useful for developers.
+profiler_print_interval (Engine profiling data print interval) int 0
diff --git a/doc/lua_api.txt b/doc/lua_api.txt
index 12b0a9299..e1077a2bb 100644
--- a/doc/lua_api.txt
+++ b/doc/lua_api.txt
@@ -3423,6 +3423,9 @@ Definition tables
 ### ABM (ActiveBlockModifier) definition (`register_abm`)
 
     {
+        label = "Lava cooling",
+    --  ^ Descriptive label for profiling purposes (optional).
+    --    Definitions with identical labels will be listed as one.
     --  In the following two fields, also group:groupname will work.
         nodenames = {"default:lava_source"},
         neighbors = {"default:water_source", "default:water_flowing"}, -- Any of these --[[
@@ -3439,6 +3442,9 @@ Definition tables
 ### LBM (LoadingBlockModifier) definition (`register_lbm`)
 
     {
+        label = "Upgrade legacy doors",
+    --  ^ Descriptive label for profiling purposes (optional).
+    --    Definitions with identical labels will be listed as one.
         name = "modname:replace_legacy_door",
         nodenames = {"default:lava_source"},
     --  ^ List of node names to trigger the LBM on.