aboutsummaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authororwell96 <orwell@bleipb.de>2019-12-04 12:28:47 +0100
committerorwell96 <orwell@bleipb.de>2019-12-04 12:28:47 +0100
commitfbbed0899327a1d70676775c2bdeb42b9f06e980 (patch)
tree0460f18fa1f0507bac793a3f2a249256af0cd400
parent9cf280dbe474b000afc91bcacacec0bb1ad7a02b (diff)
downloadadvprofiler-fbbed0899327a1d70676775c2bdeb42b9f06e980.zip
advprofiler-fbbed0899327a1d70676775c2bdeb42b9f06e980.tar.gz
advprofiler-fbbed0899327a1d70676775c2bdeb42b9f06e980.tar.bz2
First implementation
-rw-r--r--init.lua179
-rw-r--r--readme.txt47
2 files changed, 226 insertions, 0 deletions
diff --git a/init.lua b/init.lua
index de2632d..d6b2dce 100644
--- a/init.lua
+++ b/init.lua
@@ -1,4 +1,183 @@
-- Advprofiler
-- A mod profiler written in need for a profiler for advtrains
+-- (c)2019 orwell96 <orwell@bleipb.de>
+
+advprofiler = {}
+
+--[[
+
+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 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, nil
+ local li
+ for i=1,count do
+ li = list[i]
+ tot = tot + li
+ max = math.max((max or li), li)
+ end
+ local avg = tot/count
+ 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,
+ }
+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 = rt_tot
+ unit.st_times_max = rt_max
+ unit.st_times_avg = rt_avg
+ unit.st_stepcount = sc
+
+ unit.rn_runcount = 0
+ unit.rn_count = 0
+ end
+end
+
+function profiler:end_window(print_table)
+ table.insert(print_table, "=== "..profiler.name.." ===")
+ 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_count, sc)
+ rep.time_tot, rep.time_avg, rep.time_max = accumulate(unit.st_times_tot, sc)
+
+ local report_f = unit.report or advprofiler.report
+
+ table.insert(print_table, unitn..": "..report_f(rep))
+
+ 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)
+ return new
+end
+
+
+
+function advprofiler.step()
+ for _,prof in ipairs(_profs) do
+ prof:end_step()
+ 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.report(rep)
+ return string.format("Count avg=%d max=%d total=%d | Time avg=%3fms max=%3fms total=%3fms"
+ rep.count_avg, rep.count_max, rep.count_tot,
+ rep.time_avg, rep.time_max, rep.time_tot)
+end
+
+
diff --git a/readme.txt b/readme.txt
new file mode 100644
index 0000000..0e1b59c
--- /dev/null
+++ b/readme.txt
@@ -0,0 +1,47 @@
+ADVPROFILER
+===========
+
+advprofiler is a Minetest mod library to facilitate profiling of Minetest mod functions. It tries to unify and extend the functionality of existing profiling frameworks (namely https://bitbucket.org/sorcerykid/stopwatch and
+https://github.com/xyzz/minetest-mods/blob/master/seasons/profiler.lua)
+
+What it does differently than other profilers is that it is step-oriented. It counts the times and calls measured per Minetest server step, and not continuously.
+
+Profilers and units
+===================
+
+A profiler (profiler instance) represents one large project to be monitored. It is obtained by a constructor, and has a name which is purely informational.
+
+A single profiler consists of several units. Units are identified only by a string key, which needs to be unique. Units can be explicitly registered to specify functions to present and/or accumulate data, if they are not explicitly registered, they're created implicitly using default presentation functions.
+
+Profiling variants
+==================
+
+Each unit measures two things: 'count' and 'time'. Whether you actually use the "time" value is up to you, if you never access it, the implementation will handle this efficiently.
+
+There are two ways to access a unit. Both can be used interchangeably on the same unit, depending on the use case.
+
+Count mode
+----------
+
+This mode consists of a single call, which simply increases the 'count' value:
+# prof:count("unit", [count_inc=1])
+
+It does neither start nor stop the timetaker
+
+Time mode
+---------
+# prof:enter("unit", [count_inc=1])
+Increments the 'count' and saves the current os.clock() as start timestamp
+
+# prof:leave("unit")
+Stops the timetaker and adds the elapsed time to the 'time'.
+
+Recursing units is not supported. Calling enter() on an already entered unit results in a warning, as well as calling leave() on a not-entered unit.
+
+Server Steps
+============
+Once per server step, advprofiler performs an intermediate evaluation step, in which it determines the per-step average values. This happens in a dedicated globalstep callback.
+
+During the step evaluation, none of the units should be in 'entered' state. If an unit is still not left, a warning is emitted and the time sample is discarded (the 'count' is still applied in this case!)
+
+