From 29163eceece5b8f77141b851e81d3dbbf8af1903 Mon Sep 17 00:00:00 2001 From: "Johnny C. Lam" Date: Sun, 1 Jun 2014 05:30:17 +0000 Subject: [PATCH] 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 --- Ovale.toc | 3 + OvaleOptions.lua | 24 +++++++ Profiler.lua | 184 ++++++++++++++++++++++++++++++++++++++++++++++++++++++ compiler.pl | 1 + 4 files changed, 212 insertions(+) create mode 100644 Profiler.lua 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 + +-- +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 = {} +-- + +-- +-- Registered profiling groups. +Profiler.group = {} +-- + +-- +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 +-- + +-- +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 +-- 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; -- 1.7.9.5