Quantcast

Add new Profiler module to allow basic profiling of Ovale code.

Johnny C. Lam [06-01-14 - 05:30]
Add new Profiler module to allow basic profiling of Ovale code.

To get profiling stats for a function, execute Profiler:Start(tag) at the
head of the function and Profiler:Stop(tag) before exiting the function,
where "tag" is a unique label to track.

Everything that happens in-between Start/Stop is attributed to the given
tag.  If a profiled function calls another profiled function, then the
time spent within the called function is not charged to the calling
function.

git-svn-id: svn://svn.curseforge.net/wow/ovale/mainline/trunk@1504 d5049fe3-3747-40f7-a4b5-f36d6801af5f
Filename
Ovale.toc
OvaleOptions.lua
Profiler.lua
compiler.pl
diff --git a/Ovale.toc b/Ovale.toc
index 94324d5..4c824e0 100644
--- a/Ovale.toc
+++ b/Ovale.toc
@@ -18,6 +18,9 @@ locales\files.xml

 Ovale.lua

+# Profiling module.
+Profiler.lua
+
 # Utility modules.
 OvaleLexer.lua
 OvalePool.lua
diff --git a/OvaleOptions.lua b/OvaleOptions.lua
index 665bc85..4ef4d92 100644
--- a/OvaleOptions.lua
+++ b/OvaleOptions.lua
@@ -678,6 +678,30 @@ local self_options =
 						if Ovale.OvaleStance then Ovale.OvaleStance:DebugStances() end
 					end
 				},
+				profilestart = {
+					order = -10,
+					name = "Start gathering profiling stats",
+					type = "execute",
+					func = function() Ovale.Profiler:Enable(nil, true) end,
+				},
+				profilestop = {
+					order = -11,
+					name = "Stop gathering profiling stats",
+					type = "execute",
+					func = function() Ovale.Profiler:Disable(nil, true) end,
+				},
+				profilereset = {
+					order = -12,
+					name = "Reset profiling stats",
+					type = "execute",
+					func = function() Ovale.Profiler:Reset() end,
+				},
+				profile = {
+					order = -13,
+					name = "Print profiling stats",
+					type = "execute",
+					func = function() Ovale.Profiler:Info() end,
+				},
 			},
 		},
 	},
diff --git a/Profiler.lua b/Profiler.lua
new file mode 100644
index 0000000..eeebc11
--- /dev/null
+++ b/Profiler.lua
@@ -0,0 +1,184 @@
+--[[--------------------------------------------------------------------
+    Ovale Spell Priority
+    Copyright (C) 2014 Johnny C. Lam
+
+    This program is free software; you can redistribute it and/or modify
+    it under the terms of the GNU General Public License in the LICENSE
+    file accompanying this program.
+--]]--------------------------------------------------------------------
+
+--[[
+	Every time a new function is entered and exited, debugprofilestop() is called and the time between
+	the two timestamps is calculated and attributed to that function.
+--]]
+
+local _, Ovale = ...
+local Profiler = {}
+Ovale.Profiler = Profiler
+
+--<private-static-properties>
+local debugprofilestop = debugprofilestop
+local format = string.format
+local tinsert = table.insert
+local tsort = table.sort
+local API_GetTime = GetTime
+
+local self_timestamp = debugprofilestop()
+local self_stack = {}
+local self_stackSize = 0
+local self_timeSpent = {}
+local self_timesInvoked = {}
+--</private-static-properties>
+
+--<public-static-properties>
+-- Registered profiling groups.
+Profiler.group = {}
+--</public-static-properties>
+
+--<private-static-methods>
+local function DoNothing()
+	-- no-op
+end
+
+local function StartProfiler(tag)
+	local newTimestamp = debugprofilestop()
+
+	-- Attribute the time spent up to this call to the previous function.
+	if self_stackSize > 0 then
+		local delta = newTimestamp - self_timestamp
+		local previous = self_stack[self_stackSize]
+		local timeSpent = self_timeSpent[previous] or 0
+		timeSpent = timeSpent + delta
+		self_timeSpent[previous] = timeSpent
+	end
+
+	-- Add the current function to the call stack.
+	self_timestamp = newTimestamp
+	self_stackSize = self_stackSize + 1
+	self_stack[self_stackSize] = tag
+	do
+		local timesInvoked = self_timesInvoked[tag] or 0
+		timesInvoked = timesInvoked + 1
+		self_timesInvoked[tag] = timesInvoked
+	end
+end
+
+local function StopProfiler(tag)
+	if self_stackSize > 0 then
+		local currentTag = self_stack[self_stackSize]
+		if currentTag == tag then
+			local newTimestamp = debugprofilestop()
+			local delta = newTimestamp - self_timestamp
+			local timeSpent = self_timeSpent[currentTag] or 0
+			timeSpent = timeSpent + delta
+			self_timeSpent[currentTag] = timeSpent
+			self_timestamp = newTimestamp
+			self_stackSize = self_stackSize - 1
+		end
+	end
+end
+--</private-static-methods>
+
+--<public-static-methods>
+function Profiler:RegisterProfilingGroup(group)
+	self.group[group] = self.group[group] or {}
+	self:Disable(group, false)
+end
+
+function Profiler:Enable(group, isVerbose)
+	if group then
+		local methods = self.group[group]
+		if methods then
+			if isVerbose then
+				Ovale:FormatPrint("Profiling for %s is enabled.", group)
+			end
+			methods.Start = StartProfiler
+			methods.Stop = StopProfiler
+		end
+	else
+		for group, methods in pairs(self.group) do
+			if isVerbose then
+				Ovale:FormatPrint("Profiling for %s is enabled.", group)
+			end
+			methods.Start = StartProfiler
+			methods.Stop = StopProfiler
+		end
+	end
+end
+
+function Profiler:Disable(group, isVerbose)
+	if group then
+		local methods = self.group[group]
+		if methods then
+			if isVerbose then
+				Ovale:FormatPrint("Profiling for %s is disabled.", group)
+			end
+			methods.Start = DoNothing
+			methods.Stop = DoNothing
+		end
+	else
+		for group, methods in pairs(self.group) do
+			if isVerbose then
+				Ovale:FormatPrint("Profiling for %s is disabled.", group)
+			end
+			methods.Start = DoNothing
+			methods.Stop = DoNothing
+		end
+	end
+end
+
+function Profiler:Reset()
+	for tag in pairs(self_timeSpent) do
+		self_timeSpent[tag] = 0
+	end
+	for tag in pairs(self_timesInvoked) do
+		self_timesInvoked[tag] = 0
+	end
+end
+
+do
+	local array = {}
+
+	function Profiler:Info()
+		if next(self_timeSpent) then
+			local now = API_GetTime()
+			Ovale:FormatPrint("Profiler info at %f:", now)
+
+			-- Calculate the width needed to print out the times invoked.
+			local width = 1
+			do
+				local tenPower = 10
+				for _, timesInvoked in pairs(self_timesInvoked) do
+					while timesInvoked > tenPower do
+						width = width + 1
+						tenPower = tenPower * 10
+					end
+				end
+			end
+
+			wipe(array)
+			local formatString = format("    %%6fs: %%%dd x %%s", width)
+			for tag, timeSpent in pairs(self_timeSpent) do
+				local timesInvoked = self_timesInvoked[tag]
+				tinsert(array, format(formatString, timeSpent/1000, timesInvoked, tag))
+			end
+			if next(array) then
+				tsort(array)
+				for _, v in ipairs(array) do
+					Ovale:Print(v)
+				end
+			end
+		end
+	end
+end
+
+function Profiler:Debug()
+	Ovale:FormatPrint("Profiler stack size = %d", self_stackSize)
+	local index = self_stackSize
+	while index > 0 and self_stackSize - index < 10 do
+		local tag = self_stack[index]
+		Ovale:FormatPrint("    [%d] %s", index, tag)
+		index = index - 1
+	end
+end
+--</public-static-methods>
diff --git a/compiler.pl b/compiler.pl
index 24727c9..f7c5257 100644
--- a/compiler.pl
+++ b/compiler.pl
@@ -110,6 +110,7 @@ $sp{Ovale}{OvaleQueue} = true;
 $sp{Ovale}{OvaleSimulationCraft} = true;
 $sp{Ovale}{OvaleSkada} = true;
 $sp{Ovale}{OvaleTimeSpan} = true;
+$sp{Ovale}{Profiler} = true;

 $m{OvaleQueue}{NewQueue} = true;
 $sp{OvaleQueue}{Front} = true;