464 lines
14 KiB
Lua
464 lines
14 KiB
Lua
--[[
|
|
ProFi v1.3, by Luke Perkin 2012. MIT Licence http://www.opensource.org/licenses/mit-license.php.
|
|
|
|
Example:
|
|
ProFi = require 'ProFi'
|
|
ProFi:start()
|
|
some_function()
|
|
another_function()
|
|
coroutine.resume( some_coroutine )
|
|
ProFi:stop()
|
|
ProFi:writeReport( 'MyProfilingReport.txt' )
|
|
|
|
API:
|
|
*Arguments are specified as: type/name/default.
|
|
ProFi:start( string/once/nil )
|
|
ProFi:stop()
|
|
ProFi:checkMemory( number/interval/0, string/note/'' )
|
|
ProFi:writeReport( string/filename/'ProFi.txt' )
|
|
ProFi:reset()
|
|
ProFi:setHookCount( number/hookCount/0 )
|
|
ProFi:setGetTimeMethod( function/getTimeMethod/os.clock )
|
|
ProFi:setInspect( string/methodName, number/levels/1 )
|
|
]]
|
|
|
|
-----------------------
|
|
-- Locals:
|
|
-----------------------
|
|
|
|
local ProFi = {}
|
|
local onDebugHook, sortByDurationDesc, sortByCallCount, getTime
|
|
local DEFAULT_DEBUG_HOOK_COUNT = 0
|
|
local FORMAT_HEADER_LINE = "| %-50s: %-40s: %-20s: %-12s: %-12s: %-12s|\n"
|
|
local FORMAT_OUTPUT_LINE = "| %s: %-12s: %-12s: %-12s|\n"
|
|
local FORMAT_INSPECTION_LINE = "> %s: %-12s\n"
|
|
local FORMAT_TOTALTIME_LINE = "| TOTAL TIME = %f\n"
|
|
local FORMAT_MEMORY_LINE = "| %-20s: %-16s: %-16s| %s\n"
|
|
local FORMAT_HIGH_MEMORY_LINE = "H %-20s: %-16s: %-16sH %s\n"
|
|
local FORMAT_LOW_MEMORY_LINE = "L %-20s: %-16s: %-16sL %s\n"
|
|
local FORMAT_TITLE = "%-50.50s: %-40.40s: %-20s"
|
|
local FORMAT_LINENUM = "%4i"
|
|
local FORMAT_TIME = "%04.3f"
|
|
local FORMAT_RELATIVE = "%03.2f%%"
|
|
local FORMAT_COUNT = "%7i"
|
|
local FORMAT_KBYTES = "%7i Kbytes"
|
|
local FORMAT_MBYTES = "%7.1f Mbytes"
|
|
local FORMAT_MEMORY_HEADER1 = "\n=== HIGH & LOW MEMORY USAGE ===============================\n"
|
|
local FORMAT_MEMORY_HEADER2 = "=== MEMORY USAGE ==========================================\n"
|
|
local FORMAT_BANNER = [[
|
|
###############################################################################################################
|
|
##### ProFi, a lua profiler. This profile was generated on: %s
|
|
##### ProFi is created by Luke Perkin 2012 under the MIT Licence, www.locofilm.co.uk
|
|
##### Version 1.3. Get the most recent version at this gist: https://gist.github.com/2838755
|
|
###############################################################################################################
|
|
|
|
]]
|
|
|
|
-----------------------
|
|
-- Public Methods:
|
|
-----------------------
|
|
|
|
--[[
|
|
Starts profiling any method that is called between this and ProFi:stop().
|
|
Pass the parameter 'once' to so that this methodis only run once.
|
|
Example:
|
|
ProFi:start( 'once' )
|
|
]]
|
|
function ProFi:start( param )
|
|
if param == 'once' then
|
|
if self:shouldReturn() then
|
|
return
|
|
else
|
|
self.should_run_once = true
|
|
end
|
|
end
|
|
self.has_started = true
|
|
self.has_finished = false
|
|
self:resetReports( self.reports )
|
|
self:startHooks()
|
|
self.startTime = getTime()
|
|
end
|
|
|
|
--[[
|
|
Stops profiling.
|
|
]]
|
|
function ProFi:stop()
|
|
if self:shouldReturn() then
|
|
return
|
|
end
|
|
self.stopTime = getTime()
|
|
self:stopHooks()
|
|
self.has_finished = true
|
|
end
|
|
|
|
function ProFi:checkMemory( interval, note )
|
|
local time = getTime()
|
|
local interval = interval or 0
|
|
if self.lastCheckMemoryTime and time < self.lastCheckMemoryTime + interval then
|
|
return
|
|
end
|
|
self.lastCheckMemoryTime = time
|
|
local memoryReport = {
|
|
['time'] = time;
|
|
['memory'] = collectgarbage('count');
|
|
['note'] = note or '';
|
|
}
|
|
table.insert( self.memoryReports, memoryReport )
|
|
self:setHighestMemoryReport( memoryReport )
|
|
self:setLowestMemoryReport( memoryReport )
|
|
end
|
|
|
|
--[[
|
|
Writes the profile report to a file.
|
|
Param: [filename:string:optional] defaults to 'ProFi.txt' if not specified.
|
|
]]
|
|
function ProFi:writeReport( filename )
|
|
if #self.reports > 0 or #self.memoryReports > 0 then
|
|
filename = filename or 'ProFi.txt'
|
|
self:sortReportsWithSortMethod( self.reports, self.sortMethod )
|
|
self:writeReportsToFilename( filename )
|
|
print( string.format("[ProFi]\t Report written to %s", filename) )
|
|
end
|
|
end
|
|
|
|
--[[
|
|
Resets any profile information stored.
|
|
]]
|
|
function ProFi:reset()
|
|
self.reports = {}
|
|
self.reportsByTitle = {}
|
|
self.memoryReports = {}
|
|
self.highestMemoryReport = nil
|
|
self.lowestMemoryReport = nil
|
|
self.has_started = false
|
|
self.has_finished = false
|
|
self.should_run_once = false
|
|
self.lastCheckMemoryTime = nil
|
|
self.hookCount = self.hookCount or DEFAULT_DEBUG_HOOK_COUNT
|
|
self.sortMethod = self.sortMethod or sortByDurationDesc
|
|
self.inspect = nil
|
|
end
|
|
|
|
--[[
|
|
Set how often a hook is called.
|
|
See http://pgl.yoyo.org/luai/i/debug.sethook for information.
|
|
Param: [hookCount:number] if 0 ProFi counts every time a function is called.
|
|
if 2 ProFi counts every other 2 function calls.
|
|
]]
|
|
function ProFi:setHookCount( hookCount )
|
|
self.hookCount = hookCount
|
|
end
|
|
|
|
--[[
|
|
Set how the report is sorted when written to file.
|
|
Param: [sortType:string] either 'duration' or 'count'.
|
|
'duration' sorts by the time a method took to run.
|
|
'count' sorts by the number of times a method was called.
|
|
]]
|
|
function ProFi:setSortMethod( sortType )
|
|
if sortType == 'duration' then
|
|
self.sortMethod = sortByDurationDesc
|
|
elseif sortType == 'count' then
|
|
self.sortMethod = sortByCallCount
|
|
end
|
|
end
|
|
|
|
--[[
|
|
By default the getTime method is os.clock (CPU time),
|
|
If you wish to use other time methods pass it to this function.
|
|
Param: [getTimeMethod:function]
|
|
]]
|
|
function ProFi:setGetTimeMethod( getTimeMethod )
|
|
getTime = getTimeMethod
|
|
end
|
|
|
|
--[[
|
|
Allows you to inspect a specific method.
|
|
Will write to the report a list of methods that
|
|
call this method you're inspecting, you can optionally
|
|
provide a levels parameter to traceback a number of levels.
|
|
Params: [methodName:string] the name of the method you wish to inspect.
|
|
[levels:number:optional] the amount of levels you wish to traceback, defaults to 1.
|
|
]]
|
|
function ProFi:setInspect( methodName, levels )
|
|
if self.inspect then
|
|
self.inspect.methodName = methodName
|
|
self.inspect.levels = levels or 1
|
|
else
|
|
self.inspect = {
|
|
['methodName'] = methodName;
|
|
['levels'] = levels or 1;
|
|
}
|
|
end
|
|
end
|
|
|
|
-----------------------
|
|
-- Implementations methods:
|
|
-----------------------
|
|
|
|
function ProFi:shouldReturn( )
|
|
return self.should_run_once and self.has_finished
|
|
end
|
|
|
|
function ProFi:getFuncReport( funcInfo )
|
|
local title = self:getTitleFromFuncInfo( funcInfo )
|
|
local funcReport = self.reportsByTitle[ title ]
|
|
if not funcReport then
|
|
funcReport = self:createFuncReport( funcInfo )
|
|
self.reportsByTitle[ title ] = funcReport
|
|
table.insert( self.reports, funcReport )
|
|
end
|
|
return funcReport
|
|
end
|
|
|
|
function ProFi:getTitleFromFuncInfo( funcInfo )
|
|
local name = funcInfo.name or 'anonymous'
|
|
-- TODO (freeminer): remove common path, i.e. /home/xyz/freeminer/games/default/, from the source
|
|
local source = funcInfo.source:sub(-50) or 'C_FUNC'
|
|
local linedefined = funcInfo.linedefined or 0
|
|
linedefined = string.format( FORMAT_LINENUM, linedefined )
|
|
return string.format(FORMAT_TITLE, source, name, linedefined)
|
|
end
|
|
|
|
function ProFi:createFuncReport( funcInfo )
|
|
local name = funcInfo.name or 'anonymous'
|
|
local source = funcInfo.source or 'C Func'
|
|
local linedefined = funcInfo.linedefined or 0
|
|
local funcReport = {
|
|
['title'] = self:getTitleFromFuncInfo( funcInfo );
|
|
['count'] = 0;
|
|
['timer'] = 0;
|
|
}
|
|
return funcReport
|
|
end
|
|
|
|
function ProFi:startHooks()
|
|
debug.sethook( onDebugHook, 'cr', self.hookCount )
|
|
end
|
|
|
|
function ProFi:stopHooks()
|
|
debug.sethook()
|
|
end
|
|
|
|
function ProFi:sortReportsWithSortMethod( reports, sortMethod )
|
|
if reports then
|
|
table.sort( reports, sortMethod )
|
|
end
|
|
end
|
|
|
|
function ProFi:writeReportsToFilename( filename )
|
|
local file, err = io.open( filename, 'w' )
|
|
assert( file, err )
|
|
self:writeBannerToFile( file )
|
|
if #self.reports > 0 then
|
|
self:writeProfilingReportsToFile( self.reports, file )
|
|
end
|
|
if #self.memoryReports > 0 then
|
|
self:writeMemoryReportsToFile( self.memoryReports, file )
|
|
end
|
|
file:close()
|
|
end
|
|
|
|
function ProFi:writeProfilingReportsToFile( reports, file )
|
|
local totalTime = self.stopTime - self.startTime
|
|
local totalTimeOutput = string.format(FORMAT_TOTALTIME_LINE, totalTime)
|
|
file:write( totalTimeOutput )
|
|
local header = string.format( FORMAT_HEADER_LINE, "FILE", "FUNCTION", "LINE", "TIME", "RELATIVE", "CALLED" )
|
|
file:write( header )
|
|
for i, funcReport in ipairs( reports ) do
|
|
local timer = string.format(FORMAT_TIME, funcReport.timer)
|
|
local count = string.format(FORMAT_COUNT, funcReport.count)
|
|
local relTime = string.format(FORMAT_RELATIVE, (funcReport.timer / totalTime) * 100 )
|
|
local outputLine = string.format(FORMAT_OUTPUT_LINE, funcReport.title, timer, relTime, count )
|
|
file:write( outputLine )
|
|
if funcReport.inspections then
|
|
self:writeInpsectionsToFile( funcReport.inspections, file )
|
|
end
|
|
end
|
|
end
|
|
|
|
function ProFi:writeMemoryReportsToFile( reports, file )
|
|
file:write( FORMAT_MEMORY_HEADER1 )
|
|
self:writeHighestMemoryReportToFile( file )
|
|
self:writeLowestMemoryReportToFile( file )
|
|
file:write( FORMAT_MEMORY_HEADER2 )
|
|
for i, memoryReport in ipairs( reports ) do
|
|
local outputLine = self:formatMemoryReportWithFormatter( memoryReport, FORMAT_MEMORY_LINE )
|
|
file:write( outputLine )
|
|
end
|
|
end
|
|
|
|
function ProFi:writeHighestMemoryReportToFile( file )
|
|
local memoryReport = self.highestMemoryReport
|
|
local outputLine = self:formatMemoryReportWithFormatter( memoryReport, FORMAT_HIGH_MEMORY_LINE )
|
|
file:write( outputLine )
|
|
end
|
|
|
|
function ProFi:writeLowestMemoryReportToFile( file )
|
|
local memoryReport = self.lowestMemoryReport
|
|
local outputLine = self:formatMemoryReportWithFormatter( memoryReport, FORMAT_LOW_MEMORY_LINE )
|
|
file:write( outputLine )
|
|
end
|
|
|
|
function ProFi:formatMemoryReportWithFormatter( memoryReport, formatter )
|
|
local time = string.format(FORMAT_TIME, memoryReport.time)
|
|
local kbytes = string.format(FORMAT_KBYTES, memoryReport.memory)
|
|
local mbytes = string.format(FORMAT_MBYTES, memoryReport.memory/1024)
|
|
local outputLine = string.format(formatter, time, kbytes, mbytes, memoryReport.note)
|
|
return outputLine
|
|
end
|
|
|
|
function ProFi:writeBannerToFile( file )
|
|
local banner = string.format(FORMAT_BANNER, os.date())
|
|
file:write( banner )
|
|
end
|
|
|
|
function ProFi:writeInpsectionsToFile( inspections, file )
|
|
local inspectionsList = self:sortInspectionsIntoList( inspections )
|
|
file:write('\n==^ INSPECT ^======================================================================================================== COUNT ===\n')
|
|
for i, inspection in ipairs( inspectionsList ) do
|
|
local line = string.format(FORMAT_LINENUM, inspection.line)
|
|
local title = string.format(FORMAT_TITLE, inspection.source, inspection.name, line)
|
|
local count = string.format(FORMAT_COUNT, inspection.count)
|
|
local outputLine = string.format(FORMAT_INSPECTION_LINE, title, count )
|
|
file:write( outputLine )
|
|
end
|
|
file:write('===============================================================================================================================\n\n')
|
|
end
|
|
|
|
function ProFi:sortInspectionsIntoList( inspections )
|
|
local inspectionsList = {}
|
|
for k, inspection in pairs(inspections) do
|
|
inspectionsList[#inspectionsList+1] = inspection
|
|
end
|
|
table.sort( inspectionsList, sortByCallCount )
|
|
return inspectionsList
|
|
end
|
|
|
|
function ProFi:resetReports( reports )
|
|
for i, report in ipairs( reports ) do
|
|
report.timer = 0
|
|
report.count = 0
|
|
report.inspections = nil
|
|
end
|
|
end
|
|
|
|
function ProFi:shouldInspect( funcInfo )
|
|
return self.inspect and self.inspect.methodName == funcInfo.name
|
|
end
|
|
|
|
function ProFi:getInspectionsFromReport( funcReport )
|
|
local inspections = funcReport.inspections
|
|
if not inspections then
|
|
inspections = {}
|
|
funcReport.inspections = inspections
|
|
end
|
|
return inspections
|
|
end
|
|
|
|
function ProFi:getInspectionWithKeyFromInspections( key, inspections )
|
|
local inspection = inspections[key]
|
|
if not inspection then
|
|
inspection = {
|
|
['count'] = 0;
|
|
}
|
|
inspections[key] = inspection
|
|
end
|
|
return inspection
|
|
end
|
|
|
|
function ProFi:doInspection( inspect, funcReport )
|
|
local inspections = self:getInspectionsFromReport( funcReport )
|
|
local levels = 5 + inspect.levels
|
|
local currentLevel = 5
|
|
while currentLevel < levels do
|
|
local funcInfo = debug.getinfo( currentLevel, 'nS' )
|
|
if funcInfo then
|
|
local source = funcInfo.short_src or '[C]'
|
|
local name = funcInfo.name or 'anonymous'
|
|
local line = funcInfo.linedefined
|
|
local key = source..name..line
|
|
local inspection = self:getInspectionWithKeyFromInspections( key, inspections )
|
|
inspection.source = source
|
|
inspection.name = name
|
|
inspection.line = line
|
|
inspection.count = inspection.count + 1
|
|
currentLevel = currentLevel + 1
|
|
else
|
|
break
|
|
end
|
|
end
|
|
end
|
|
|
|
function ProFi:onFunctionCall( funcInfo )
|
|
local funcReport = ProFi:getFuncReport( funcInfo )
|
|
funcReport.callTime = getTime()
|
|
funcReport.count = funcReport.count + 1
|
|
if self:shouldInspect( funcInfo ) then
|
|
self:doInspection( self.inspect, funcReport )
|
|
end
|
|
end
|
|
|
|
function ProFi:onFunctionReturn( funcInfo )
|
|
local funcReport = ProFi:getFuncReport( funcInfo )
|
|
if funcReport.callTime then
|
|
local time = getTime() - funcReport.callTime
|
|
-- handle overflow for unsigned 32-bit time
|
|
-- if for some reason `unsigned int` is 64-bit then overflows don't happen!
|
|
if time < 0 then
|
|
time = 4294967296 / 1000000 + time
|
|
end
|
|
funcReport.timer = funcReport.timer + time
|
|
end
|
|
end
|
|
|
|
function ProFi:setHighestMemoryReport( memoryReport )
|
|
if not self.highestMemoryReport then
|
|
self.highestMemoryReport = memoryReport
|
|
else
|
|
if memoryReport.memory > self.highestMemoryReport.memory then
|
|
self.highestMemoryReport = memoryReport
|
|
end
|
|
end
|
|
end
|
|
|
|
function ProFi:setLowestMemoryReport( memoryReport )
|
|
if not self.lowestMemoryReport then
|
|
self.lowestMemoryReport = memoryReport
|
|
else
|
|
if memoryReport.memory < self.lowestMemoryReport.memory then
|
|
self.lowestMemoryReport = memoryReport
|
|
end
|
|
end
|
|
end
|
|
|
|
-----------------------
|
|
-- Local Functions:
|
|
-----------------------
|
|
|
|
getTime = os.clock
|
|
|
|
onDebugHook = function( hookType )
|
|
local funcInfo = debug.getinfo( 2, 'nS' )
|
|
if hookType == "call" then
|
|
ProFi:onFunctionCall( funcInfo )
|
|
elseif hookType == "return" then
|
|
ProFi:onFunctionReturn( funcInfo )
|
|
end
|
|
end
|
|
|
|
sortByDurationDesc = function( a, b )
|
|
return a.timer > b.timer
|
|
end
|
|
|
|
sortByCallCount = function( a, b )
|
|
return a.count > b.count
|
|
end
|
|
|
|
-----------------------
|
|
-- Return Module:
|
|
-----------------------
|
|
|
|
ProFi:reset()
|
|
return ProFi
|