enabling a profiler makes the problem go away
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!
This commit is contained in:
Kartik K. Agaram
parent
32975fa963
commit
9af3a968de
|
|
@ -0,0 +1,192 @@
|
|||
-- 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
|
||||
|
|
@ -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 = 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
|
||||
5
run.lua
5
run.lua
|
|
@ -18,6 +18,8 @@ Crosslink_background_color={r=0, g=0, b=0, a=0.1}
|
|||
|
||||
run = {}
|
||||
|
||||
profile = require 'profile'
|
||||
|
||||
-- The note-taking app has a few differences with the baseline editor it's
|
||||
-- forked from:
|
||||
-- - most notes are read-only
|
||||
|
|
@ -807,6 +809,8 @@ function run.keychord_pressed(chord, key)
|
|||
if pane then
|
||||
if pane.editable then
|
||||
if chord == 'C-e' then
|
||||
--? profile.stop()
|
||||
--? print(profile.report())
|
||||
command.exit_editing()
|
||||
elseif pane.cursor_x == nil then
|
||||
-- ignore if cursor is not visible on screen
|
||||
|
|
@ -1190,6 +1194,7 @@ function keychord_pressed_in_normal_mode_with_immutable_pane(pane, chord, key)
|
|||
end
|
||||
if chord == 'C-e' then
|
||||
command.edit_note()
|
||||
profile.start()
|
||||
elseif chord == 'C-c' then
|
||||
edit.keychord_pressed(pane, chord, key)
|
||||
else
|
||||
|
|
|
|||
Loading…
Reference in New Issue