diff options
Diffstat (limited to 'plugins/profiler/profiler.lua')
| -rw-r--r-- | plugins/profiler/profiler.lua | 311 |
1 files changed, 311 insertions, 0 deletions
diff --git a/plugins/profiler/profiler.lua b/plugins/profiler/profiler.lua new file mode 100644 index 0000000..ca18f24 --- /dev/null +++ b/plugins/profiler/profiler.lua @@ -0,0 +1,311 @@ +--[[ +@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 = 60, -- Width of the file column + fnW = 30, -- 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 |