Skip to content

Commit c24e075

Browse files
sapiersapier
sapier
authored and
sapier
committed
Mod profiling support
Config settings: profiling = true/false (gather statistics) detailed_profiling = true/false (break mod times to callbacks) Chat commands: save_mod_profile saves current statistics in debug.txt and shows on console (on default loglevel)
1 parent 4caa00c commit c24e075

File tree

7 files changed

+391
-0
lines changed

7 files changed

+391
-0
lines changed

‎builtin/game/chatcommands.lua‎

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,19 @@ function core.register_chatcommand(cmd, def)
1313
core.chatcommands[cmd] = def
1414
end
1515

16+
if core.setting_getbool("mod_profiling") then
17+
local tracefct = profiling_print_log
18+
profiling_print_log = nil
19+
core.register_chatcommand("save_mod_profile",
20+
{
21+
params = "",
22+
description = "save mod profiling data to logfile " ..
23+
"(depends on default loglevel)",
24+
func = tracefct,
25+
privs = { server=true }
26+
})
27+
end
28+
1629
core.register_on_chat_message(function(name, message)
1730
local cmd, param = string.match(message, "^/([^ ]+) *(.*)")
1831
if not param then

‎builtin/game/init.lua‎

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,11 @@ dofile(commonpath.."vector.lua")
77

88
dofile(gamepath.."item.lua")
99
dofile(gamepath.."register.lua")
10+
11+
if core.setting_getbool("mod_profiling") then
12+
dofile(gamepath.."mod_profiling.lua")
13+
end
14+
1015
dofile(gamepath.."item_entity.lua")
1116
dofile(gamepath.."deprecated.lua")
1217
dofile(gamepath.."misc.lua")

‎builtin/game/mod_profiling.lua‎

Lines changed: 355 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,355 @@
1+
-- Minetest: builtin/game/mod_profiling.lua
2+
3+
local mod_statistics = {}
4+
mod_statistics.step_total = 0
5+
mod_statistics.data = {}
6+
mod_statistics.stats = {}
7+
mod_statistics.stats["total"] = {
8+
min_us = math.huge,
9+
max_us = 0,
10+
avg_us = 0,
11+
min_per = 100,
12+
max_per = 100,
13+
avg_per = 100
14+
}
15+
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",
28+
"register_on_cheat",
29+
"register_on_chat_message",
30+
"register_on_player_receive_fields",
31+
"register_on_mapgen_init",
32+
"register_on_craft",
33+
"register_craft_predict",
34+
"register_on_item_eat"
35+
}
36+
37+
--------------------------------------------------------------------------------
38+
function mod_statistics.log_time(type, modname, time_in_us)
39+
40+
if modname == nil then
41+
modname = "builtin"
42+
end
43+
44+
if mod_statistics.data[modname] == nil then
45+
mod_statistics.data[modname] = {}
46+
end
47+
48+
if mod_statistics.data[modname][type] == nil then
49+
mod_statistics.data[modname][type] = 0
50+
end
51+
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
55+
end
56+
57+
--------------------------------------------------------------------------------
58+
function mod_statistics.update_statistics(dtime)
59+
for modname,types in pairs(mod_statistics.data) do
60+
61+
if mod_statistics.stats[modname] == nil then
62+
mod_statistics.stats[modname] = {
63+
min_us = math.huge,
64+
max_us = 0,
65+
avg_us = 0,
66+
min_per = 100,
67+
max_per = 0,
68+
avg_per = 0
69+
}
70+
end
71+
72+
local modtime = 0
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 = {}
77+
end
78+
if mod_statistics.stats[modname].types[type] == nil then
79+
mod_statistics.stats[modname].types[type] = {
80+
min_us = math.huge,
81+
max_us = 0,
82+
avg_us = 0,
83+
min_per = 100,
84+
max_per = 0,
85+
avg_per = 0
86+
}
87+
end
88+
89+
local toupdate = mod_statistics.stats[modname].types[type]
90+
91+
--update us values
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
96+
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)
100+
101+
toupdate.max_per = math.max(toupdate.max_per, cur_per)
102+
103+
--TODO find better algorithm
104+
toupdate.avg_per = toupdate.avg_per * 0.99 + cur_per * 0.01
105+
106+
mod_statistics.data[modname][type] = 0
107+
end
108+
109+
--per mod statistics
110+
--update us values
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
118+
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)
123+
124+
mod_statistics.stats[modname].max_per =
125+
math.max(mod_statistics.stats[modname].max_per, cur_per)
126+
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
130+
end
131+
132+
--update "total"
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
141+
142+
mod_statistics.step_total = 0
143+
end
144+
145+
--------------------------------------------------------------------------------
146+
local function build_callback(log_id, fct)
147+
return function( toregister )
148+
local modname = core.get_current_modname()
149+
150+
fct(function(...)
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
158+
end
159+
)
160+
end
161+
end
162+
163+
--------------------------------------------------------------------------------
164+
function profiling_print_log(cmd, filter)
165+
166+
print("Filter:" .. dump(filter))
167+
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")
171+
core.log("action",
172+
string.format("%16s | %25s | %10s | %10s | %10s | %9s | %9s | %9s",
173+
"modname", "type" , "min µs", "max µs", "avg µs", "min %", "max %", "avg %")
174+
)
175+
core.log("action",
176+
"-----------------+---------------------------+-----------+" ..
177+
"-----------+-----------+-----------+-----------+-----------")
178+
for modname,statistics in pairs(mod_statistics.stats) do
179+
if modname ~= "total" then
180+
181+
if (filter == "") or (modname == filter) then
182+
if modname:len() > 16 then
183+
modname = "..." .. modname:sub(-13)
184+
end
185+
186+
core.log("action",
187+
string.format("%16s | %25s | %9d | %9d | %9d | %9d | %9d | %9d",
188+
modname,
189+
" ",
190+
statistics.min_us,
191+
statistics.max_us,
192+
statistics.avg_us,
193+
statistics.min_per,
194+
statistics.max_per,
195+
statistics.avg_per)
196+
)
197+
if core.setting_getbool("detailed_profiling") then
198+
if statistics.types ~= nil then
199+
for type,typestats in pairs(statistics.types) do
200+
201+
if type:len() > 25 then
202+
type = "..." .. type:sub(-22)
203+
end
204+
205+
core.log("action",
206+
string.format(
207+
"%16s | %25s | %9d | %9d | %9d | %9d | %9d | %9d",
208+
" ",
209+
type,
210+
typestats.min_us,
211+
typestats.max_us,
212+
typestats.avg_us,
213+
typestats.min_per,
214+
typestats.max_per,
215+
typestats.avg_per)
216+
)
217+
end
218+
end
219+
end
220+
end
221+
end
222+
end
223+
core.log("action",
224+
"-----------------+---------------------------+-----------+" ..
225+
"-----------+-----------+-----------+-----------+-----------")
226+
227+
if filter == "" then
228+
core.log("action",
229+
string.format("%16s | %25s | %9d | %9d | %9d | %9d | %9d | %9d",
230+
"total",
231+
" ",
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)
238+
)
239+
end
240+
core.log("action", " ")
241+
242+
return true
243+
end
244+
245+
--------------------------------------------------------------------------------
246+
local function initialize_profiling()
247+
core.log("action", "Initialize tracing")
248+
249+
mod_statistics.entity_callbacks = {}
250+
251+
-- first register our own globalstep handler
252+
core.register_globalstep(mod_statistics.update_statistics)
253+
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
262+
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)
271+
end
272+
end
273+
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)
282+
end
283+
end
284+
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)
293+
end
294+
end
295+
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)
304+
end
305+
end
306+
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)
315+
end
316+
end
317+
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
323+
324+
rp_register_entity(name,prototype)
325+
end
326+
327+
for i,v in ipairs(replacement_table) do
328+
local to_replace = core[v]
329+
core[v] = build_callback(v, to_replace)
330+
end
331+
332+
local rp_register_abm = core.register_abm
333+
core.register_abm = function(spec)
334+
335+
local modname = core.get_current_modname()
336+
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)
347+
end
348+
}
349+
rp_register_abm(replacement_spec)
350+
end
351+
352+
core.log("action", "Mod profiling initialized")
353+
end
354+
355+
initialize_profiling()

‎doc/lua_api.txt‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1535,6 +1535,8 @@ minetest.set_node_level(pos, level)
15351535
^ set level of leveled node, default level = 1, if totallevel > maxlevel returns rest (total-max).
15361536
minetest.add_node_level(pos, level)
15371537
^ increase level of leveled node by level, default level = 1, if totallevel > maxlevel returns rest (total-max). can be negative for decreasing
1538+
minetest.get_time_us()
1539+
^ get time in microseconds
15381540

15391541
Inventory:
15401542
minetest.get_inventory(location) -> InvRef

0 commit comments

Comments
 (0)