Revert change to report function

init.lua

@@ -1,4 +1,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)
+
 

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!)
+
+