1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
|
-- Advprofiler
-- A mod profiler written in need for a profiler for advtrains
-- (c)2019 orwell96 <orwell@bleipb.de>
advprofiler = {}
local WINDOW_SIZE = 1024
local report_to_csv = true
local report_file = minetest.get_worldpath()..DIR_DELIM.."advprofiler.csv"
--[[
Unit table:
["unit"] = {
-- st=step, run = one enter..leave
st_counts = {...} -- total count values (indexed by step)
st_times_tot = {...} -- total time spent in unit per step
st_times_max = {...} -- max time spent in single run
st_times_avg = {...} -- avg time spent in single run
st_stepcount = 3 -- count of actual steps in st table*
rn_times = {...} -- times of individual runs in current step
rn_runcount = 3 -- count of actual runs in current step*
rn_count = 4 -- 'count' value in current step
[enter_ts = ...] -- Timestamp when unit was last entered
}
* to prevent expensive reallocations in tables, track the current table length
in external variables and only overwrite values.
]]
local _profs = {}
advprofiler._profilers = _profs
local function logs(t)
minetest.log("action", "[advprofiler] "..t)
end
local function warning(prof, unit, text)
minetest.log("warning", "[advprofiler] ("..prof.name..":"..unit..") "..text)
end
local clock = os.clock
local function accumulate(list, count)
local tot, max = 0, 0
local act_cnt = 0
local li
for i=1,count do
li = list[i]
if li then
tot = tot + li
max = math.max(max, li)
act_cnt = act_cnt + 1
end
end
if act_cnt==0 then return nil,nil,nil end
local avg = tot/act_cnt
return tot, avg, max
end
-- prototype for profiler instances (index metatable)
local profiler = {}
function profiler:unit_get(unit)
if self.units[unit] then return self.units[unit] end
-- create unit new
self.units[unit] = {
st_counts = {},
st_times_tot = {},
st_times_max = {},
st_times_avg = {},
st_stepcount = 0,
rn_times = {},
rn_runcount = 0,
rn_count = 0,
}
return self.units[unit]
end
function profiler:count(unitn, count_inc)
local unit = self:unit_get(unitn)
unit.rn_count = unit.rn_count + (count_inc or 1)
end
function profiler:enter(unitn, count_inc)
local unit = self:unit_get(unitn)
if unit.enter_ts then
warning(self,unitn,"Unit is already entered!")
return
end
unit.rn_count = unit.rn_count + (count_inc or 1)
unit.enter_ts = clock()
end
function profiler:leave(unitn)
local t1 = clock()
local unit = self:unit_get(unitn)
if not unit.enter_ts then
warning(self,unitn,"Unit was never entered!")
return
end
local td = t1 - unit.enter_ts
if td<0 then
warning(self,unitn,"Time difference smaller than 0 ?! td="..td)
return
end
unit.rn_runcount = unit.rn_runcount + 1
unit.rn_times[unit.rn_runcount] = td
unit.enter_ts = nil
end
function profiler:end_step()
for unitn, unit in pairs(self.units) do
local sc = unit.st_stepcount + 1
unit.st_counts[sc] = unit.rn_count
local rt_tot, rt_avg, rt_max = accumulate(unit.rn_times, unit.rn_runcount)
unit.st_times_tot[sc] = rt_tot
unit.st_times_max[sc] = rt_max
unit.st_times_avg[sc] = rt_avg
unit.st_stepcount = sc
unit.rn_runcount = 0
unit.rn_count = 0
end
end
local function nformat_csv(n)
if not n then return "--" end
return string.format("%d", n)
end
local function tformat_csv(n)
if not n then return "--" end
return string.format("%d", n*1000)
end
function profiler:end_window(print_table, csv_file)
table.insert(print_table, "=== "..self.name.." ===")
if csv_file then
csv_file:write("### "..self.name.."\n")
end
for unitn, unit in pairs(self.units) do
if unit.enter_ts then
warning(self,unitn,"Unit still entered at end of step! (discarding)")
unit.enter_ts = nil
end
local sc = unit.st_stepcount
local rep = {
profiler = self,
unit = unitn,
}
rep.count_tot, rep.count_avg, rep.count_max = accumulate(unit.st_counts, sc)
rep.time_tot, rep.time_avg, rep.time_max = accumulate(unit.st_times_tot, sc)
_ , rep.per_call_avg, _ = accumulate(unit.st_times_avg, sc)
_ , _ , rep.per_call_max = accumulate(unit.st_times_max, sc)
local report_f = unit.report or advprofiler.report
table.insert(print_table, unitn..":\t"..report_f(rep))
if csv_file then
local colt = advprofiler.get_report_columns(rep)
csv_file:write(table.concat(colt, "\t").."\n")
end
unit.st_stepcount = 0
end
end
--===========--
local prof_mt = {__index = profiler}
-- creates a new profiler instance and returns it
function advprofiler.new_profiler(name)
local new = {
name = name,
units = {},
}
setmetatable(new, prof_mt)
table.insert(_profs, new)
logs("Registered profiler "..name)
return new
end
function advprofiler.step()
for _,prof in ipairs(_profs) do
prof:end_step()
end
end
function advprofiler.end_window_and_report(cyc)
local print_table = {
"--- Profiling report for cycle "..cyc.." ---",
"Unit\tcount_tot\tcount_avg\tcount_max\ttime_tot\ttime_avg\ttime_max\tper_call_avg\tper_call_max"
}
local csv_file
if report_to_csv then
csv_file = io.open(report_file, "w")
end
if csv_file then
csv_file:write("Unit\tcount_tot\tcount_avg\tcount_max\ttime_tot\ttime_avg\ttime_max\tper_call_avg\tper_call_max\n")
end
for _,prof in ipairs(_profs) do
prof:end_window(print_table, csv_file)
end
for _,l in ipairs(print_table) do
logs(l)
end
if csv_file then
csv_file:close()
end
end
--[[
Report table:
(all values are 'per step' ,tot=total over whole window)
rep.count_tot, rep.count_avg, rep.count_max
rep.time_tot, rep.time_avg, rep.time_max
]]
function advprofiler.get_report_columns(rep)
return {
rep.unit,
nformat_csv(rep.count_tot), nformat_csv(rep.count_avg), nformat_csv(rep.count_max),
tformat_csv(rep.time_tot), tformat_csv(rep.time_avg), tformat_csv(rep.time_max),
tformat_csv(rep.per_call_avg), tformat_csv(rep.per_call_max)
}
end
local function t1000(t)
return t and t*1000 or 0
end
function advprofiler.report(rep)
return string.format("Count avg=%d\tmax=%d\ttotal=%d\tTime avg=%dms\tmax=%dms\ttotal=%dms\tPer-Call avg=%dms\tmax=%dms",
rep.count_avg, rep.count_max, rep.count_tot,
t1000(rep.time_avg), t1000(rep.time_max), t1000(rep.time_tot),
t1000(rep.per_call_avg), t1000(rep.per_call_max))
end
--===========--
local stepcnt = 0
local cyccnt = 0
minetest.register_globalstep(function(dtime)
advprofiler.step()
stepcnt = (stepcnt + 1) % WINDOW_SIZE
if stepcnt == 0 then
cyccnt = cyccnt + 1
advprofiler.end_window_and_report(cyccnt)
end
end)
|