Create a gist now

Instantly share code, notes, and snippets.

ProFi, a simple lua profiler that works with LuaJIT and prints a pretty report file in columns.
--[[
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'
local source = funcInfo.short_src 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
funcReport.timer = funcReport.timer + (getTime() - funcReport.callTime)
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
@agladysh
agladysh commented Jan 7, 2013

Please consider moving this to a proper GitHub repo.

@robertwahler

+1 for moving this to a repo, super useful, thanks for sharing.

@mindreframer

+1 for a dedicated repo :)))

@mindreframer

https://github.com/mindreframer/ProFi.lua
poke me, when you have a proper git repository

@jucor
jucor commented May 8, 2013

+1 for a repo -- that would make keeping up-to-date, forking, reporting issues, etc, much easier :)

@wqren
wqren commented Jul 8, 2015

+1 for a repo.

@hanoixan
hanoixan commented Jan 5, 2016

I tested this code, and it looks like it has a fundamental flaw: it isn't compatible with recursion. In onFunctionReturn(), the funcReport is based on the funcInfo, which is singleton to each function. While funcReport.count is incremented correctly, funcReport.startTime will be reset on each successive onFunctionCall in the recursion. Each successive onFunctionRetrun will compute its time delta based on the last call to onFunctionCall in the recursion. I recommend tracking the start times in a stack, instead of the funcReport.

@AshishBora
AshishBora commented May 6, 2016 edited

I see that some functions take more time than overall (>100%). How can that be?

Example output :

ProFi, a lua profiler. This profile was generated on: Fri May 6 01:18:22 2016
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

| TOTAL TIME = 97.560000
| FILE : FUNCTION : LINE : TIME : RELATIVE : CALLED |
| ...4001/ashishb/torch-cl/install/share/lua/5.1/nn/: clear : 203 : 68413.910 : 70124.96% : 188 |
| get_example_C.lua : get_example : 11 : 60829.610 : 62350.97% : 23 |
| ...01/ashishb/torch-cl/install/share/lua/5.1/torch: isTensor : 171 : 1901.330 : 1948.88% : 2027 |
| training_funcs.lua : nextBatch : 107 : 72.140 : 73.94% : 11 |
| preproc.lua : preprocess : 45 : 51.170 : 52.45% : 4224 |

@buckle2000

Same problem.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment