Builtin profiler: Capture Tracy zones; And small improvements (#16479)

* Feature: Use the builtin profiler to automatically make zones for mod callback functions.
* Doc: Basic doc for builtin profiler, and better `/profiler` chatcommand help.
* Fix: `register_functions` (table of callback register function names), and `entity_instrumentation` is no longer outdated.
* Fix: Builtin profiler output is no longer printed to debug.txt or to file in world with translation escapes.
* Fix: Entity callback name generation used `obj_def.label` (normally non-existing field), now it uses the entity name.
* Small code improvements, like use of new `Settings.get_bool` with default.

.luacheckrc

@@ -20,6 +20,7 @@ read_globals = {
 	"profiler",
 	"Settings",
 	"ValueNoise", "ValueNoiseMap",
+	"tracy",
 
 	string = {fields = {"split", "trim"}},
 	table  = {fields = {"copy", "copy_with_metatables", "getn", "indexof", "keyof", "insert_all"}},

builtin/game/register.lua

@@ -584,6 +584,7 @@ core.unregister_biome = make_wrap_deregistration(core.register_biome,
 local make_registration = builtin_shared.make_registration
 local make_registration_reverse = builtin_shared.make_registration_reverse
 
+-- keep in sync with profiler/instrumentation.lua
 core.registered_on_chat_messages, core.register_on_chat_message = make_registration()
 core.registered_on_chatcommands, core.register_on_chatcommand = make_registration()
 core.registered_globalsteps, core.register_globalstep = make_registration()

builtin/profiler/init.lua

@@ -4,18 +4,10 @@
 
 local S = core.get_translator("__builtin")
 
-local function get_bool_default(name, default)
-	local val = core.settings:get_bool(name)
-	if val == nil then
-		return default
-	end
-	return val
-end
-
 local profiler_path = core.get_builtin_path().."profiler"..DIR_DELIM
 local profiler = {}
 local sampler = assert(loadfile(profiler_path .. "sampling.lua"))(profiler)
-local instrumentation  = assert(loadfile(profiler_path .. "instrumentation.lua"))(profiler, sampler, get_bool_default)
+local instrumentation  = assert(loadfile(profiler_path .. "instrumentation.lua"))(profiler, sampler)
 local reporter = dofile(profiler_path .. "reporter.lua")
 profiler.instrument = instrumentation.instrument
 
@@ -24,14 +16,17 @@ profiler.instrument = instrumentation.instrument
 -- Is called later, after `core.register_chatcommand` was set up.
 --
 function profiler.init_chatcommand()
-	local instrument_profiler = get_bool_default("instrument.profiler", false)
+	local instrument_profiler = core.settings:get_bool("instrument.profiler", false)
 	if instrument_profiler then
 		instrumentation.init_chatcommand()
 	end
 
 	local param_usage = S("print [<filter>] | dump [<filter>] | save [<format> [<filter>]] | reset")
 	core.register_chatcommand("profiler", {
-		description = S("Handle the profiler and profiling data"),
+		description = S("Handle the profiler and profiling data. "
+			.. "Can output to chat (print), action log (dump), or file in world (save). "
+			.. "Format can be one of txt, csv, lua, json, json_pretty (structures may be subject to change). "
+			.. "Filter is a lua pattern used to limit output to matching mod names."),
 		params = param_usage,
 		privs = { server=true },
 		func = function(name, param)
@@ -39,10 +34,10 @@ function profiler.init_chatcommand()
 			local args = arg0 and string.split(arg0, " ")
 
 			if command == "dump" then
-				core.log("action", reporter.print(sampler.profile, arg0))
+				core.log("action", reporter.print(sampler.profile, arg0, false))
 				return true, S("Statistics written to action log.")
 			elseif command == "print" then
-				return true, reporter.print(sampler.profile, arg0)
+				return true, reporter.print(sampler.profile, arg0, true)
 			elseif command == "save" then
 				return reporter.save(sampler.profile, args[1] or "txt", args[2])
 			elseif command == "reset" then
@@ -50,9 +45,7 @@ function profiler.init_chatcommand()
 				return true, S("Statistics were reset.")
 			end
 
-			return false,
+			return false
-				S("Usage: @1", param_usage) .. "\n" ..
-				S("Format can be one of txt, csv, lua, json, json_pretty (structures may be subject to change).")
 		end
 	})
 

builtin/profiler/instrumentation.lua

@@ -2,35 +2,57 @@
 -- Copyright (C) 2016 T4im
 -- SPDX-License-Identifier: LGPL-2.1-or-later
 
-local format, pairs, type = string.format, pairs, type
+local format, ipairs, type = string.format, ipairs, type
 local core, get_current_modname = core, core.get_current_modname
-local profiler, sampler, get_bool_default = ...
+local profiler, sampler = ...
 
-local instrument_builtin = get_bool_default("instrument.builtin", false)
+local instrument_builtin = core.settings:get_bool("instrument.builtin", false)
 
+local do_measure = core.settings:get_bool("profiler.measure", true)
+local do_tracy = core.settings:get_bool("profiler.tracy", false)
+if do_tracy and not core.global_exists("tracy") then
+	core.log("warning", "profiler.tracy is enabled, but `tracy` was not found. Did you build with Tracy?")
+	do_tracy = false
+end
+
+-- keep in sync with game/register.lua
 local register_functions = {
-	register_globalstep = 0,
+	"register_on_player_hpchange",
-	register_playerevent = 0,
+
-	register_on_placenode = 0,
+	"register_on_chat_message",
-	register_on_dignode = 0,
+	"register_on_chatcommand",
-	register_on_punchnode = 0,
+	"register_globalstep",
-	register_on_generated = 0,
+	"register_playerevent",
-	register_on_newplayer = 0,
+	"register_on_mods_loaded",
-	register_on_dieplayer = 0,
+	"register_on_shutdown",
-	register_on_respawnplayer = 0,
+	"register_on_punchnode",
-	register_on_prejoinplayer = 0,
+	"register_on_placenode",
-	register_on_joinplayer = 0,
+	"register_on_dignode",
-	register_on_leaveplayer = 0,
+	"register_on_generated",
-	register_on_cheat = 0,
+	"register_on_newplayer",
-	register_on_chat_message = 0,
+	"register_on_dieplayer",
-	register_on_player_receive_fields = 0,
+	"register_on_respawnplayer",
-	register_on_craft = 0,
+	"register_on_prejoinplayer",
-	register_craft_predict = 0,
+	"register_on_joinplayer",
-	register_on_protection_violation = 0,
+	"register_on_leaveplayer",
-	register_on_item_eat = 0,
+	"register_on_player_receive_fields",
-	register_on_punchplayer = 0,
+	"register_on_cheat",
-	register_on_player_hpchange = 0,
+	"register_on_craft",
-	register_on_mapblocks_changed = 0,
+	"register_craft_predict",
+	"register_on_protection_violation",
+	"register_on_item_eat",
+	"register_on_item_pickup",
+	"register_on_punchplayer",
+	"register_on_priv_grant",
+	"register_on_priv_revoke",
+	"register_on_authplayer",
+	"register_can_bypass_userlimit",
+	"register_on_modchannel_message",
+	"register_on_player_inventory_action",
+	"register_allow_player_inventory_action",
+	"register_on_rightclickplayer",
+	"register_on_liquid_transformed",
+	"register_on_mapblocks_changed",
 }
 
 local function regex_escape(s)
@@ -38,27 +60,13 @@ local function regex_escape(s)
 end
 
 ---
--- Create an unique instrument name.
+-- Format `filepath#linenumber` of function, with a relative filepath.
--- Generate a missing label with a running index number.
 --
-local counts = {}
+-- FIXME: these paths are not canonicalized (i.e. can be .../luanti/bin/..)
 local worldmods_path = regex_escape(core.get_worldpath())
 local user_path = regex_escape(core.get_user_path())
 local builtin_path = regex_escape(core.get_builtin_path())
-local function generate_name(def)
+local function generate_source_location(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
 	local info = debug.getinfo(def.func)
 	local modpath = regex_escape(core.get_modpath(def.mod) or "")
 	local source = info.source
@@ -68,7 +76,32 @@ local function generate_name(def)
 	source = source:gsub(worldmods_path, "")
 	source = source:gsub(builtin_path, "builtin" .. DIR_DELIM)
 	source = source:gsub(user_path, "")
-	return format("%s[%d] %s#%s", class or func_name, index, source, info.linedefined)
+	return string.format("%s#%s", source, info.linedefined)
+end
+
+---
+-- Create an unique instrument name.
+-- Generate a missing label with a running index number.
+-- Returns name, name_has_source.
+--
+local generate_name_counts = {}
+local function generate_name(def)
+	local class, label, func_name = def.class, def.label, def.func_name
+	local source = generate_source_location(def)
+
+	if label then
+		if class or func_name then
+			return format("%s '%s' %s", class or "", label, func_name or ""):trim(), false
+		end
+		return format("%s", label):trim(), false
+	elseif label == false then
+		return format("%s", class or func_name):trim(), false
+	else
+		local index_id = def.mod .. (class or func_name)
+		local index = generate_name_counts[index_id] or 1
+		generate_name_counts[index_id] = index + 1
+		return format("%s[%d] %s", class or func_name, index, source), true
+	end
 end
 
 ---
@@ -80,6 +113,10 @@ local function measure(modname, instrument_name, start, ...)
 	log(modname, instrument_name, time() - start)
 	return ...
 end
+local function tracy_ZoneEnd_and_return(...)
+	tracy.ZoneEnd()
+	return ...
+end
 --- Automatically instrument a function to measure and log to the sampler.
 -- def = {
 -- 		mod = "",
@@ -94,22 +131,38 @@ local function instrument(def)
 	end
 	def.mod = def.mod or get_current_modname() or "??"
 	local modname = def.mod
-	local instrument_name = generate_name(def)
+	local instrument_name, name_has_source = generate_name(def)
+	local instrument_name_with_source = name_has_source and instrument_name or
+		string.format("%s %s", instrument_name, generate_source_location(def))
 	local func = def.func
 
 	if not instrument_builtin and modname == "*builtin*" then
 		return func
 	end
 
-	return function(...)
+	-- These tail-calls allows passing all return values of `func_o`
-		-- 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 func(...)
+	-- `tracy_ZoneEnd_and_return` / `measure` will be executed after `func_o(...)`
-		local start = time()
+
-		return measure(modname, instrument_name, start, func(...))
+	if do_tracy then
+		local func_o = func
+		func = function(...)
+			tracy.ZoneBeginN(instrument_name_with_source)
+			return tracy_ZoneEnd_and_return(func_o(...))
 		end
+	end
+
+	if do_measure then
+		local func_o = func
+		func = function(...)
+			local start = time()
+			return measure(modname, instrument_name, start, func_o(...))
+		end
+	end
+
+	return func
 end
 
 local function can_be_called(func)
@@ -135,7 +188,6 @@ 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
@@ -144,7 +196,7 @@ local function instrument_register(func, func_name)
 end
 
 local function init_chatcommand()
-	if get_bool_default("instrument.chatcommand", true) then
+	if core.settings:get_bool("instrument.chatcommand", true) then
 		local orig_register_chatcommand = core.register_chatcommand
 		core.register_chatcommand = function(cmd, def)
 			def.func = instrument {
@@ -160,7 +212,7 @@ end
 -- Start instrumenting selected functions
 --
 local function init()
-	if get_bool_default("instrument.entity", true) then
+	if core.settings:get_bool("instrument.entity", true) then
 		-- Explicitly declare entity api-methods.
 		-- Simple iteration would ignore lookup via __index.
 		local entity_instrumentation = {
@@ -168,26 +220,30 @@ local function init()
 			"on_deactivate",
 			"on_step",
 			"on_punch",
+			"on_death",
 			"on_rightclick",
+			"on_attach_child",
+			"on_detach_child",
+			"on_detach",
 			"get_staticdata",
 		}
 		-- Wrap register_entity() to instrument them on registration.
 		local orig_register_entity = core.register_entity
-		core.register_entity = function(name, prototype)
+		core.register_entity = function(name, def)
 			local modname = get_current_modname()
-			for _, func_name in pairs(entity_instrumentation) do
+			for _, func_name in ipairs(entity_instrumentation) do
-				prototype[func_name] = instrument {
+				def[func_name] = instrument {
-					func = prototype[func_name],
+					func = def[func_name],
 					mod = modname,
 					func_name = func_name,
-					label = prototype.label,
+					label = name,
 				}
 			end
-			orig_register_entity(name,prototype)
+			orig_register_entity(name, def)
 		end
 	end
 
-	if get_bool_default("instrument.abm", true) then
+	if core.settings:get_bool("instrument.abm", true) then
 		-- Wrap register_abm() to automatically instrument abms.
 		local orig_register_abm = core.register_abm
 		core.register_abm = function(spec)
@@ -200,7 +256,7 @@ local function init()
 		end
 	end
 
-	if get_bool_default("instrument.lbm", true) then
+	if core.settings:get_bool("instrument.lbm", true) then
 		-- Wrap register_lbm() to automatically instrument lbms.
 		local orig_register_lbm = core.register_lbm
 		core.register_lbm = function(spec)
@@ -214,13 +270,13 @@ local function init()
 		end
 	end
 
-	if get_bool_default("instrument.global_callback", true) then
+	if core.settings:get_bool("instrument.global_callback", true) then
-		for func_name, _ in pairs(register_functions) do
+		for _, func_name in ipairs(register_functions) do
 			core[func_name] = instrument_register(core[func_name], func_name)
 		end
 	end
 
-	if get_bool_default("instrument.profiler", false) then
+	if core.settings:get_bool("instrument.profiler", false) then
 		-- Measure overhead of instrumentation, but keep it down for functions
 		-- So keep the `return` for better optimization.
 		profiler.empty_instrument = instrument {
@@ -233,7 +289,6 @@ local function init()
 end
 
 return {
-	register_functions = register_functions,
 	instrument = instrument,
 	init = init,
 	init_chatcommand = init_chatcommand,

builtin/profiler/reporter.lua

@@ -168,7 +168,7 @@ local CsvFormatter = Formatter:new {
 	end
 }
 
-local function format_statistics(profile, format, filter)
+local function format_statistics(profile, format, filter, enable_translation)
 	local formatter
 	if format == "csv" then
 		formatter = CsvFormatter:new {
@@ -180,16 +180,20 @@ local function format_statistics(profile, format, filter)
 		}
 	end
 	formatter:format(filter)
-	return formatter:flush()
+	local out = formatter:flush()
+	if not enable_translation then
+		out = core.get_translated_string("en", out)
+	end
+	return out
 end
 
 ---
 -- Format the profile ready for display and
 -- @return string to be printed to the console
 --
-function reporter.print(profile, filter)
+function reporter.print(profile, filter, enable_translation)
 	if filter == "" then filter = nil end
-	return format_statistics(profile, "txt", filter)
+	return format_statistics(profile, "txt", filter, enable_translation)
 end
 
 ---
@@ -215,7 +219,7 @@ local function serialize_profile(profile, format, filter)
 		end
 	end
 	-- Fall back to textual formats.
-	return format_statistics(profile, format, filter)
+	return format_statistics(profile, format, filter, false)
 end
 
 local worldpath = core.get_worldpath()

builtin/settingtypes.txt

@@ -1943,6 +1943,14 @@ enable_mod_channels (Mod channels) [server] bool false
 #    Useful for mod developers and server operators.
 profiler.load (Load the game profiler) bool false
 
+#    Disable if you only want to instrument with Tracy.
+profiler.measure (Measure time samples) bool true
+
+#    Capture Tracy zones with the profiler's instrumentation.
+#    You need to build with Tracy to use this, see doc/developing/profiling.md
+#    for details.
+profiler.tracy (Capture Tracy zones) 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

doc/developing/profiling.md

@@ -1,5 +1,16 @@
 # Profiling
 
+## Using builtin's mod profiler
+
+Builtin has a profiler for callbacks registered by mods. It measures how much
+time each callback took per server-step (on average / min / max).
+
+To start, enable the `profiler.load` setting.
+(There are more settings, see `profiler.*` and `instrument.*`.)
+
+Use the `profiler` chatcommand to look at the results.
+
+
 ## Profiling Luanti on Linux with perf
 
 We will be using a tool called "perf", which you can get by installing `perf` or `linux-perf` or `linux-tools-common`.
@@ -65,13 +76,16 @@ Build Luanti with `-DDBUILD_WITH_TRACY=1`, this will fetch Tracy for building
 the Tracy client. And use `FETCH_TRACY_GIT_TAG` to get a version matching your
 Tracy server, e.g. `-DFETCH_TRACY_GIT_TAG=v0.11.0` if it's `0.11.0`.
 
-To actually use Tracy, you also have to enable it with Tracy's build options:
+To actually use Tracy, you also have to enable it with Tracy's build options
-```
+(`-DTRACY_ENABLE=1`).
--DTRACY_ENABLE=1 -DTRACY_ONLY_LOCALHOST=1
-```
 
 See Tracy's documentation for more build options.
 
+TL;DR:
+```
+-DDBUILD_WITH_TRACY=1 -DFETCH_TRACY_GIT_TAG=<your_version> -DTRACY_ENABLE=1 -DTRACY_ONLY_LOCALHOST=1
+```
+
 ### Using in C++
 
 Start the Tracy server and Luanti. You should see Luanti in the menu.
@@ -87,3 +101,6 @@ See Tracy's official documentation for more information.
 
 Note: The whole Tracy Lua API is accessible to all mods. And we don't check if it
 is or becomes insecure. Run untrusted mods at your own risk.
+
+Enable `profiler.load` and `profiler.tracy` to automatically instrument mod
+callback functions.