index : minetest.git	gpcf lifo-fixes release
	modified minetest for gpcfs purposes	gpcf

aboutsummaryrefslogtreecommitdiff

log msg author committer range

path: root/builtin/profiler/init.lua

	Commit message (Collapse)	Author	Age
*	Translate builtin (#10693)	Wuzzy	2021-03-05
| | | | |	This PR is the second attempt to translate builtin. Server-sent translation files can be added to `builtin/locale/`, whereas client-side translations depend on gettext.
*	Create a filesystem abstraction layer for CSM and only allow accessing files ↵	red-001	2017-06-30
| | | | | | | | | | | | | | | | | |	that are scanned into it. (#5965) * Load client-side mods into memory before executing them. This removes the remaining filesystem access that client-sided mods had and it will hopefully make then more secure. * Lua Virtual filesystem: don't load the files into memory just scan the filenames into memory. * Fix the issues with backtrace * fix most of the issues * fix code style. * add a comment
*	Use a settings object for the main settings	ShadowNinja	2017-05-06
| | | | | | |	This unifies the settings APIs. This also unifies the sync and async registration APIs, since the async registration API did not support adding non-functions to the API table.
*	Builtin/profiler: Replace game profiler (#4245)	Tim	2016-07-12
	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.

generated by cgit v1.2.3 (git 2.39.1) at 2025-02-19 00:46:59 +0000

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