From fbbed0899327a1d70676775c2bdeb42b9f06e980 Mon Sep 17 00:00:00 2001 From: orwell96 Date: Wed, 4 Dec 2019 12:28:47 +0100 Subject: First implementation --- init.lua | 179 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++ readme.txt | 47 ++++++++++++++++ 2 files changed, 226 insertions(+) create mode 100644 readme.txt 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 + +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!) + + -- cgit v1.2.3