advprofiler/init.lua

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