Typing now seems quite smooth.
This is the second time this has happened, and I'm starting to ascribe magical properties to profile.lua, to the extent that I've never even tried out the second profiler.lua file. Well, let's leave it on and see how things go over a few days!
CRTRY4AD5V6XVA2GWPQNNBJSWHPZT3HRMYYRWH2AZKOFIRAIMXZQC
--[[
@title lua-profiler
@version 1.1
@description Code profiling for Lua based code;
The output is a report file (text) and optionally to a console or other logger.
The initial reason for this project was to reduce misinterpretations of code profiling
caused by the lengthy measurement time of the 'ProFi' profiler v1.3;
and then to remove the self-profiler functions from the output report.
The profiler code has been substantially rewritten to remove dependence to the 'OO'
class definitions, and repetitions in code;
thus this profiler has a smaller code footprint and reduced execution time up to ~900% faster.
The second purpose was to allow slight customisation of the output report,
which I have parametrised the output report and rewritten.
Caveats: I didn't include an 'inspection' function that ProFi had, also the RAM
output is gone. Please configure the profiler output in top of the code, particularly the
location of the profiler source file (if not in the 'main' root source directory).
@authors Charles Mallah
@copyright (c) 2018-2020 Charles Mallah
@license MIT license
@sample Output will be generated like this, all output here is ordered by time (seconds):
`> TOTAL TIME = 0.030000 s
`--------------------------------------------------------------------------------------
`| FILE : FUNCTION : LINE : TIME : % : # |
`--------------------------------------------------------------------------------------
`| map : new : 301 : 0.1330 : 52.2 : 2 |
`| map : unpackTileLayer : 197 : 0.0970 : 38.0 : 36 |
`| engine : loadAtlas : 512 : 0.0780 : 30.6 : 1 |
`| map : init : 292 : 0.0780 : 30.6 : 1 |
`| map : setTile : 38 : 0.0500 : 19.6 : 20963|
`| engine : new : 157 : 0.0220 : 8.6 : 1 |
`| map : unpackObjectLayer : 281 : 0.0190 : 7.5 : 2 |
`--------------------------------------------------------------------------------------
`| ui : sizeCharLimit : 328 : ~ : ~ : 2 |
`| modules/profiler : stop : 192 : ~ : ~ : 1 |
`| ui : sizeWidthToScreenWidthHalf : 301 : ~ : ~ : 4 |
`| map : setRectGridTo : 255 : ~ : ~ : 7 |
`| ui : sizeWidthToScreenWidth : 295 : ~ : ~ : 11 |
`| character : warp : 32 : ~ : ~ : 15 |
`| panels : Anon : 0 : ~ : ~ : 1 |
`--------------------------------------------------------------------------------------
The partition splits the notable code that is running the slowest, all other code is running
too fast to determine anything specific, instead of displaying "0.0000" the script will tidy
this up as "~". Table headers % and # refer to percentage total time, and function call count.
@example Print a profile report of a code block
`local profiler = require("profiler")
`profiler.start()
`-- Code block and/or called functions to profile --
`profiler.stop()
`profiler.report("profiler.log")
@example Profile a code block and allow mirror print to a custom print function
`local profiler = require("profiler")
`function exampleConsolePrint()
` -- Custom function in your code-base to print to file or console --
`end
`profiler.attachPrintFunction(exampleConsolePrint, true)
`profiler.start()
`-- Code block and/or called functions to profile --
`profiler.stop()
`profiler.report("profiler.log") -- exampleConsolePrint will now be called from this
@example Override a configuration parameter programmatically; insert your override values into a
new table using the matched key names:
`local overrides = {
` fW = 100, -- Change the file column to 100 characters (from 20)
` fnW = 120, -- Change the function column to 120 characters (from 28)
` }
`profiler.configuration(overrides)
]]
--[[ Configuration ]]--
local config = {
outputFile = "profiler.lua", -- Name of this profiler (to remove itself from reports)
emptyToThis = "~", -- Rows with no time are set to this value
fW = 20, -- Width of the file column
fnW = 28, -- Width of the function name column
lW = 7, -- Width of the line column
tW = 7, -- Width of the time taken column
rW = 6, -- Width of the relative percentage column
cW = 5, -- Width of the call count column
reportSaved = "> Report saved to: ", -- Text for the file output confirmation
}
--[[ Locals ]]--
local module = {}
local getTime = os.clock
local string, debug, table = string, debug, table
local reportCache = {}
local allReports = {}
local reportCount = 0
local startTime = 0
local stopTime = 0
local printFun = nil
local verbosePrint = false
local outputHeader, formatHeader, outputTitle, formatOutput, formatTotalTime
local formatFunLine, formatFunTime, formatFunRelative, formatFunCount, divider, nilTime
local function deepCopy(input)
if type(input) == "table" then
local output = {}
for i, o in next, input, nil do
output[deepCopy(i)] = deepCopy(o)
end
return output
else
return input
end
end
local function charRepetition(n, character)
local s = ""
character = character or " "
for _ = 1, n do
s = s..character
end
return s
end
local function singleSearchReturn(inputString, search)
for _ in string.gmatch(inputString, search) do -- luacheck: ignore
return true
end
return false
end
local function rebuildColumnPatterns()
local c = config
local str = "s: %-"
outputHeader = "| %-"..c.fW..str..c.fnW..str..c.lW..str..c.tW..str..c.rW..str..c.cW.."s|\n"
formatHeader = string.format(outputHeader, "FILE", "FUNCTION", "LINE", "TIME", "%", "#")
outputTitle = "%-"..c.fW.."."..c.fW..str..c.fnW.."."..c.fnW..str..c.lW.."s"
formatOutput = "| %s: %-"..c.tW..str..c.rW..str..c.cW.."s|\n"
formatTotalTime = "Total time: %f s\n"
formatFunLine = "%"..(c.lW - 2).."i"
formatFunTime = "%04.4f"
formatFunRelative = "%03.1f"
formatFunCount = "%"..(c.cW - 1).."i"
divider = charRepetition(#formatHeader - 1, "-").."\n"
-- nilTime = "0."..charRepetition(c.tW - 3, "0")
nilTime = "0.0000"
end
local function functionReport(information)
local src = information.short_src
if not src then
src = "<C>"
elseif string.sub(src, #src - 3, #src) == ".lua" then
src = string.sub(src, 1, #src - 4)
end
local name = information.name
if not name then
name = "Anon"
elseif string.sub(name, #name - 1, #name) == "_l" then
name = string.sub(name, 1, #name - 2)
end
local title = string.format(outputTitle, src, name,
string.format(formatFunLine, information.linedefined or 0))
local report = reportCache[title]
if not report then
report = {
title = string.format(outputTitle, src, name,
string.format(formatFunLine, information.linedefined or 0)),
count = 0, timer = 0,
}
reportCache[title] = report
reportCount = reportCount + 1
allReports[reportCount] = report
end
return report
end
local onDebugHook = function(hookType)
local information = debug.getinfo(2, "nS")
if hookType == "call" then
local funcReport = functionReport(information)
funcReport.callTime = getTime()
funcReport.count = funcReport.count + 1
elseif hookType == "return" then
local funcReport = functionReport(information)
if funcReport.callTime and funcReport.count > 0 then
funcReport.timer = funcReport.timer + (getTime() - funcReport.callTime)
end
end
end
--[[ Functions ]]--
--[[Attach a print function to the profiler, to receive a single string parameter
@param fn (function) <required>
@param verbose (boolean) <default: false>
]]
function module.attachPrintFunction(fn, verbose)
printFun = fn
verbosePrint = verbose or false
end
--[[Start the profiling
]]
function module.start()
if not outputHeader then
rebuildColumnPatterns()
end
reportCache = {}
allReports = {}
reportCount = 0
startTime = getTime()
stopTime = nil
debug.sethook(onDebugHook, "cr", 0)
end
--[[Stop profiling
]]
function module.stop()
stopTime = getTime()
debug.sethook()
end
--[[Writes the profile report to file (will stop profiling if not stopped already)
@param filename (string) <default: "profiler.log"> [File will be created and overwritten]
]]
function module.report(filename)
if not stopTime then
module.stop()
end
filename = filename or "profiler.log"
table.sort(allReports, function(a, b) return a.timer > b.timer end)
local fileWriter = io.open(filename, "w+")
local divide = false
local totalTime = stopTime - startTime
local totalTimeOutput = "> "..string.format(formatTotalTime, totalTime)
fileWriter:write(totalTimeOutput)
if printFun ~= nil then
printFun(totalTimeOutput)
end
fileWriter:write(divider)
fileWriter:write(formatHeader)
fileWriter:write(divider)
for i = 1, reportCount do
local funcReport = allReports[i]
if funcReport.count > 0 and funcReport.timer <= totalTime then
local printThis = true
if config.outputFile ~= "" then
if singleSearchReturn(funcReport.title, config.outputFile) then
printThis = false
end
end
if printThis then -- Remove lines that are not needed
if singleSearchReturn(funcReport.title, "[[C]]") then
printThis = false
end
end
if printThis then
local count = string.format(formatFunCount, funcReport.count)
local timer = string.format(formatFunTime, funcReport.timer)
local relTime = string.format(formatFunRelative, (funcReport.timer / totalTime) * 100)
if not divide and timer == nilTime then
fileWriter:write(divider)
divide = true
end
if timer == nilTime then
timer = config.emptyToThis
relTime = config.emptyToThis
end
-- Build final line
local output = string.format(formatOutput, funcReport.title, timer, relTime, count)
fileWriter:write(output)
-- This is a verbose print to the attached print function
if printFun ~= nil and verbosePrint then
printFun(output)
end
end
end
end
fileWriter:write(divider)
fileWriter:close()
if printFun ~= nil then
printFun(config.reportSaved.."'"..filename.."'")
end
end
--[[Modify the configuration of this module programmatically;
Provide a table with keys that share the same name as the configuration parameters:
@param overrides (table) <required> [Each key is from a valid name, the value is the override]
@unpack config
]]
function module.configuration(overrides)
local safe = deepCopy(overrides)
for k, v in pairs(safe) do
if config[k] == nil then
print("error: override field '"..k.."' not found (configuration)")
else
config[k] = v
end
end
rebuildColumnPatterns()
end
--[[ End ]]--
return module
-- https://github.com/2dengine/profile.lua
-- "A small, non-intrusive module for finding bottlenecks in your Lua code."
-- MIT license
local clock = os.clock
--- Simple profiler written in Lua.
-- @module profile
-- @alias profile
local profile = {}
-- function labels
local _labeled = {}
-- function definitions
local _defined = {}
-- time of last call
local _tcalled = {}
-- total execution time
local _telapsed = {}
-- number of calls
local _ncalls = {}
-- list of internal profiler functions
local _internal = {}
--- This is an internal function.
-- @tparam string event Event type
-- @tparam number line Line number
-- @tparam[opt] table info Debug info table
function profile.hooker(event, line, info)
info = info or debug.getinfo(2, 'fnS')
local f = info.func
-- ignore the profiler itself
if _internal[f] or info.what ~= "Lua" then
return
end
-- get the function name if available
if info.name then
_labeled[f] = info.name
end
-- find the line definition
if not _defined[f] then
_defined[f] = info.short_src..":"..info.linedefined
_ncalls[f] = 0
_telapsed[f] = 0
end
if _tcalled[f] then
local dt = clock() - _tcalled[f]
_telapsed[f] = _telapsed[f] + dt
_tcalled[f] = nil
end
if event == "tail call" then
local prev = debug.getinfo(3, 'fnS')
profile.hooker("return", line, prev)
profile.hooker("call", line, info)
elseif event == 'call' then
_tcalled[f] = clock()
else
_ncalls[f] = _ncalls[f] + 1
end
end
--- Sets a clock function to be used by the profiler.
-- @tparam function func Clock function that returns a number
function profile.setclock(f)
assert(type(f) == "function", "clock must be a function")
clock = f
end
--- Starts collecting data.
function profile.start()
if rawget(_G, 'jit') then
jit.off()
jit.flush()
end
debug.sethook(profile.hooker, "cr")
end
--- Stops collecting data.
function profile.stop()
debug.sethook()
for f in pairs(_tcalled) do
local dt = clock() - _tcalled[f]
_telapsed[f] = _telapsed[f] + dt
_tcalled[f] = nil
end
-- merge closures
local lookup = {}
for f, d in pairs(_defined) do
local id = (_labeled[f] or '?')..d
local f2 = lookup[id]
if f2 then
_ncalls[f2] = _ncalls[f2] + (_ncalls[f] or 0)
_telapsed[f2] = _telapsed[f2] + (_telapsed[f] or 0)
_defined[f], _labeled[f] = nil, nil
_ncalls[f], _telapsed[f] = nil, nil
else
lookup[id] = f
end
end
collectgarbage('collect')
end
--- Resets all collected data.
function profile.reset()
for f in pairs(_ncalls) do
_ncalls[f] = 0
end
for f in pairs(_telapsed) do
_telapsed[f] = 0
end
for f in pairs(_tcalled) do
_tcalled[f] = nil
end
collectgarbage('collect')
end
--- This is an internal function.
-- @tparam function a First function
-- @tparam function b Second function
function profile.comp(a, b)
local dt = _telapsed[b] - _telapsed[a]
if dt == 0 then
return _ncalls[b] < _ncalls[a]
end
return dt < 0
end
--- Iterates all functions that have been called since the profile was started.
-- @tparam[opt] number limit Maximum number of rows
function profile.query(limit)
local t = {}
for f, n in pairs(_ncalls) do
if n > 0 then
t[#t + 1] = f
end
end
table.sort(t, profile.comp)
if limit then
while #t > limit do
table.remove(t)
end
end
for i, f in ipairs(t) do
local dt = 0
if _tcalled[f] then
dt = clock() - _tcalled[f]
end
t[i] = { i, _labeled[f] or '?', _ncalls[f], _telapsed[f] + dt, _defined[f] }
end
return t
end
local cols = { 3, 29, 11, 24, 32 }
--- Generates a text report.
-- @tparam[opt] number limit Maximum number of rows
function profile.report(n)
local out = {}
local report = profile.query(n)
for i, row in ipairs(report) do
for j = 1, 5 do
local s = row[j]
local l2 = cols[j]
s = tostring(s)
local l1 = s:len()
if l1 < l2 then
s = s..(' '):rep(l2-l1)
elseif l1 > l2 then
s = s:sub(l1 - l2 + 1, l1)
end
row[j] = s
end
out[i] = table.concat(row, ' | ')
end
local row = " +-----+-------------------------------+-------------+--------------------------+----------------------------------+ \n"
local col = " | # | Function | Calls | Time | Code | \n"
local sz = row..col..row
if #out > 0 then
sz = sz..' | '..table.concat(out, ' | \n | ')..' | \n'
end
return '\n'..sz..row
end
-- store all internal profiler functions
for _, v in pairs(profile) do
if type(v) == "function" then
_internal[v] = true
end
end
return profile