1 -- Minetest: builtin/game/mod_profiling.lua
3 local mod_statistics = {}
4 mod_statistics.step_total = 0
5 mod_statistics.data = {}
6 mod_statistics.stats = {}
7 mod_statistics.stats["total"] = {
16 local replacement_table = {
17 "register_globalstep",
18 "register_on_placenode",
19 "register_on_dignode",
20 "register_on_punchnode",
21 "register_on_generated",
22 "register_on_newplayer",
23 "register_on_dieplayer",
24 "register_on_respawnplayer",
25 "register_on_prejoinplayer",
26 "register_on_joinplayer",
27 "register_on_leaveplayer",
29 "register_on_chat_message",
30 "register_on_player_receive_fields",
31 "register_on_mapgen_init",
33 "register_craft_predict",
34 "register_on_item_eat"
37 --------------------------------------------------------------------------------
38 function mod_statistics.log_time(type, modname, time_in_us)
40 if modname == nil then
44 if mod_statistics.data[modname] == nil then
45 mod_statistics.data[modname] = {}
48 if mod_statistics.data[modname][type] == nil then
49 mod_statistics.data[modname][type] = 0
52 mod_statistics.data[modname][type] =
53 mod_statistics.data[modname][type] + time_in_us
54 mod_statistics.step_total = mod_statistics.step_total + time_in_us
57 --------------------------------------------------------------------------------
58 function mod_statistics.update_statistics(dtime)
59 for modname,types in pairs(mod_statistics.data) do
61 if mod_statistics.stats[modname] == nil then
62 mod_statistics.stats[modname] = {
73 for type,time in pairs(types) do
74 modtime = modtime + time
75 if mod_statistics.stats[modname].types == nil then
76 mod_statistics.stats[modname].types = {}
78 if mod_statistics.stats[modname].types[type] == nil then
79 mod_statistics.stats[modname].types[type] = {
89 local toupdate = mod_statistics.stats[modname].types[type]
92 toupdate.min_us = math.min(time, toupdate.min_us)
93 toupdate.max_us = math.max(time, toupdate.max_us)
94 --TODO find better algorithm
95 toupdate.avg_us = toupdate.avg_us * 0.99 + modtime * 0.01
97 --update percentage values
98 local cur_per = (time/mod_statistics.step_total) * 100
99 toupdate.min_per = math.min(toupdate.min_per, cur_per)
101 toupdate.max_per = math.max(toupdate.max_per, cur_per)
103 --TODO find better algorithm
104 toupdate.avg_per = toupdate.avg_per * 0.99 + cur_per * 0.01
106 mod_statistics.data[modname][type] = 0
111 mod_statistics.stats[modname].min_us =
112 math.min(modtime, mod_statistics.stats[modname].min_us)
113 mod_statistics.stats[modname].max_us =
114 math.max(modtime, mod_statistics.stats[modname].max_us)
115 --TODO find better algorithm
116 mod_statistics.stats[modname].avg_us =
117 mod_statistics.stats[modname].avg_us * 0.99 + modtime * 0.01
119 --update percentage values
120 local cur_per = (modtime/mod_statistics.step_total) * 100
121 mod_statistics.stats[modname].min_per =
122 math.min(mod_statistics.stats[modname].min_per, cur_per)
124 mod_statistics.stats[modname].max_per =
125 math.max(mod_statistics.stats[modname].max_per, cur_per)
127 --TODO find better algorithm
128 mod_statistics.stats[modname].avg_per =
129 mod_statistics.stats[modname].avg_per * 0.99 + cur_per * 0.01
133 mod_statistics.stats["total"].min_us =
134 math.min(mod_statistics.step_total, mod_statistics.stats["total"].min_us)
135 mod_statistics.stats["total"].max_us =
136 math.max(mod_statistics.step_total, mod_statistics.stats["total"].max_us)
137 --TODO find better algorithm
138 mod_statistics.stats["total"].avg_us =
139 mod_statistics.stats["total"].avg_us * 0.99 +
140 mod_statistics.step_total * 0.01
142 mod_statistics.step_total = 0
145 --------------------------------------------------------------------------------
146 local function build_callback(log_id, fct)
147 return function( toregister )
148 local modname = core.get_current_modname()
151 local starttime = core.get_us_time()
152 -- note maximum 10 return values are supported unless someone finds
153 -- a way to store a variable lenght return value list
154 local r0, r1, r2, r3, r4, r5, r6, r7, r8, r9 = toregister(...)
155 local delta = core.get_us_time() - starttime
156 mod_statistics.log_time(log_id, modname, delta)
157 return r0, r1, r2, r3, r4, r5, r6, r7, r8, r9
163 --------------------------------------------------------------------------------
164 function profiling_print_log(cmd, filter)
166 print("Filter:" .. dump(filter))
168 core.log("action", "Values below show times/percentages per server step.")
169 core.log("action", "Following suffixes are used for entities:")
170 core.log("action", "\t#oa := on_activate, #os := on_step, #op := on_punch, #or := on_rightclick, #gs := get_staticdata")
172 string.format("%16s | %25s | %10s | %10s | %10s | %9s | %9s | %9s",
173 "modname", "type" , "min µs", "max µs", "avg µs", "min %", "max %", "avg %")
176 "-----------------+---------------------------+-----------+" ..
177 "-----------+-----------+-----------+-----------+-----------")
178 for modname,statistics in pairs(mod_statistics.stats) do
179 if modname ~= "total" then
181 if (filter == "") or (modname == filter) then
182 if modname:len() > 16 then
183 modname = "..." .. modname:sub(-13)
187 string.format("%16s | %25s | %9d | %9d | %9d | %9d | %9d | %9d",
197 if core.setting_getbool("detailed_profiling") then
198 if statistics.types ~= nil then
199 for type,typestats in pairs(statistics.types) do
201 if type:len() > 25 then
202 type = "..." .. type:sub(-22)
207 "%16s | %25s | %9d | %9d | %9d | %9d | %9d | %9d",
224 "-----------------+---------------------------+-----------+" ..
225 "-----------+-----------+-----------+-----------+-----------")
229 string.format("%16s | %25s | %9d | %9d | %9d | %9d | %9d | %9d",
232 mod_statistics.stats["total"].min_us,
233 mod_statistics.stats["total"].max_us,
234 mod_statistics.stats["total"].avg_us,
235 mod_statistics.stats["total"].min_per,
236 mod_statistics.stats["total"].max_per,
237 mod_statistics.stats["total"].avg_per)
240 core.log("action", " ")
245 --------------------------------------------------------------------------------
246 local function initialize_profiling()
247 core.log("action", "Initialize tracing")
249 mod_statistics.entity_callbacks = {}
251 -- first register our own globalstep handler
252 core.register_globalstep(mod_statistics.update_statistics)
254 local rp_register_entity = core.register_entity
255 core.register_entity = function(name, prototype)
256 local modname = core.get_current_modname()
257 local new_on_activate = nil
258 local new_on_step = nil
259 local new_on_punch = nil
260 local new_rightclick = nil
261 local new_get_staticdata = nil
263 if prototype.on_activate ~= nil then
264 local cbid = name .. "#oa"
265 mod_statistics.entity_callbacks[cbid] = prototype.on_activate
266 new_on_activate = function(self, staticdata, dtime_s)
267 local starttime = core.get_us_time()
268 mod_statistics.entity_callbacks[cbid](self, staticdata, dtime_s)
269 local delta = core.get_us_time() -starttime
270 mod_statistics.log_time(cbid, modname, delta)
274 if prototype.on_step ~= nil then
275 local cbid = name .. "#os"
276 mod_statistics.entity_callbacks[cbid] = prototype.on_step
277 new_on_step = function(self, dtime)
278 local starttime = core.get_us_time()
279 mod_statistics.entity_callbacks[cbid](self, dtime)
280 local delta = core.get_us_time() -starttime
281 mod_statistics.log_time(cbid, modname, delta)
285 if prototype.on_punch ~= nil then
286 local cbid = name .. "#op"
287 mod_statistics.entity_callbacks[cbid] = prototype.on_punch
288 new_on_punch = function(self, hitter)
289 local starttime = core.get_us_time()
290 mod_statistics.entity_callbacks[cbid](self, hitter)
291 local delta = core.get_us_time() -starttime
292 mod_statistics.log_time(cbid, modname, delta)
296 if prototype.rightclick ~= nil then
297 local cbid = name .. "#rc"
298 mod_statistics.entity_callbacks[cbid] = prototype.rightclick
299 new_rightclick = function(self, clicker)
300 local starttime = core.get_us_time()
301 mod_statistics.entity_callbacks[cbid](self, clicker)
302 local delta = core.get_us_time() -starttime
303 mod_statistics.log_time(cbid, modname, delta)
307 if prototype.get_staticdata ~= nil then
308 local cbid = name .. "#gs"
309 mod_statistics.entity_callbacks[cbid] = prototype.get_staticdata
310 new_get_staticdata = function(self)
311 local starttime = core.get_us_time()
312 mod_statistics.entity_callbacks[cbid](self)
313 local delta = core.get_us_time() -starttime
314 mod_statistics.log_time(cbid, modname, delta)
318 prototype.on_activate = new_on_activate
319 prototype.on_step = new_on_step
320 prototype.on_punch = new_on_punch
321 prototype.rightclick = new_rightclick
322 prototype.get_staticdata = new_get_staticdata
324 rp_register_entity(name,prototype)
327 for i,v in ipairs(replacement_table) do
328 local to_replace = core[v]
329 core[v] = build_callback(v, to_replace)
332 local rp_register_abm = core.register_abm
333 core.register_abm = function(spec)
335 local modname = core.get_current_modname()
337 local replacement_spec = {
338 nodenames = spec.nodenames,
339 neighbors = spec.neighbors,
340 interval = spec.interval,
341 chance = spec.chance,
342 action = function(pos, node, active_object_count, active_object_count_wider)
343 local starttime = core.get_us_time()
344 spec.action(pos, node, active_object_count, active_object_count_wider)
345 local delta = core.get_us_time() - starttime
346 mod_statistics.log_time("abm", modname, delta)
349 rp_register_abm(replacement_spec)
352 core.log("action", "Mod profiling initialized")
355 initialize_profiling()