diff options
| -rw-r--r-- | README.md | 1 | ||||
| -rw-r--r-- | plugins/profiler/README.md | 46 | ||||
| -rw-r--r-- | plugins/profiler/init.lua | 99 | ||||
| -rw-r--r-- | plugins/profiler/profiler.lua | 311 |
4 files changed, 457 insertions, 0 deletions
@@ -150,6 +150,7 @@ To install a plugin: | [`openselected`](plugins/openselected.lua?raw=1) | Opens the selected filename or url | | [`pdfview`](plugins/pdfview.lua?raw=1) | PDF preview for TeX files | | [`primary_selection`](plugins/primary_selection.lua?raw=1) | Adds middle mouse click copy/paste (primary selection). To use this plugin, `xclip` must be installed. | +| [`profiler`](plugins/profiler) | Adds the ability to profile lite-xl with the [lua-profiler](https://github.com/charlesmallah/lua-profiler) | | [`rainbowparen`](plugins/rainbowparen.lua?raw=1) | Show nesting of parentheses with rainbow colours | | [`regexreplacepreview`](plugins/regexreplacepreview.lua?raw=1) | Allows for you to write a regex and its replacement in one go, and live preview the results. | | [`restoretabs`](plugins/restoretabs.lua?raw=1) | Keep a list of recently closed tabs, and restore the tab in order on cntrl+shift+t. | diff --git a/plugins/profiler/README.md b/plugins/profiler/README.md new file mode 100644 index 0000000..4f113b8 --- /dev/null +++ b/plugins/profiler/README.md @@ -0,0 +1,46 @@ +# Profiler Plugin + +Profiling is mainly the runtime analysis of a program performance by counting +the call count and duration for the various routines executed thru the lifecycle +of the application. For more information view the [wikipedia] article. + +This plugin adds the ability to profile function calls while running Lite XL +to investigate performance related issues and more easily pinpoint what could +be causing the slowdowns. It integrates the [lua-profiler] which provides +the functionality we need. + +## Usage + +Open Lite XL and access the command palette by pressing `ctrl+shift+p` and +search for profiler. The command `Profiler: Toggle` command will be shown to +lets you start or stop the profiler. You should start the profiler before +triggering the events that are causing any performance issues. + + + +> **Note:** Starting the profiler will make the editor more slower since it is +> now accumulating metrics about every function call. Do not worry, this is +> expected and shouldn't affect the end result, just be patience because +> everything will be slower. + +There may also be some situations when you would like to enable the profiler +early on the startup process so we provided a config option for that. + + + +You can also change the default `profiler.log` path. Notice that since the +profiler is not part of the core but a plugin it will only start measuring +metrics once the plugin is loaded. The `priority` tag of the profiler plugin +was set to `0` to make it one of the first plugins to start. + +Once you have profiled enough you can execute the `Profiler: Toggle` command +to stop the profiler and it will automatically open a document view with the +recollected metrics as shown below: + + + +You can send Lite XL developers the output of `profiler.log` so it can be +more easily diagnosed what could be causing any issue. + +[wikipedia]: https://en.wikipedia.org/wiki/Profiling_(computer_programming) +[lua-profiler]: https://github.com/charlesmallah/lua-profiler diff --git a/plugins/profiler/init.lua b/plugins/profiler/init.lua new file mode 100644 index 0000000..8b4782b --- /dev/null +++ b/plugins/profiler/init.lua @@ -0,0 +1,99 @@ +-- mod-version:3 --priority:0 + +local core = require "core" +local common = require "core.common" +local config = require "core.config" +local command = require "core.command" +local profiler = require "plugins.profiler.profiler" + +--Keep track of profiler status. +local RUNNING = false +--The profiler runs before the settings plugin, we need to manually load them. +local SETTINGS_PATH = USERDIR .. PATHSEP .. "user_settings.lua" +-- Default location to store the profiler results. +local DEFAULT_LOG_PATH = USERDIR .. PATHSEP .. "profiler.log" + +config.plugins.profiler = common.merge({ + enable_on_startup = false, + log_file = DEFAULT_LOG_PATH, + config_spec = { + name = "Profiler", + { + label = "Enable on Startup", + description = "Enable profiler early on plugin startup process.", + path = "enable_on_startup", + type = "toggle", + default = false + }, + { + label = "Log Path", + description = "Path to the file that will contain the profiler logged data.", + path = "log_file", + type = "file", + default = DEFAULT_LOG_PATH, + filters = {"%.log$"} + } + } +}, config.plugins.profiler) + +---@class plugins.profiler +local Profiler = {} + +function Profiler.start() + if RUNNING then return end + profiler.start() + RUNNING = true +end + +function Profiler.stop() + if RUNNING then + profiler.stop() + profiler.report(config.plugins.profiler.log_file) + RUNNING = false + end +end + +-------------------------------------------------------------------------------- +-- Run profiler at startup if enabled. +-------------------------------------------------------------------------------- +if system.get_file_info(SETTINGS_PATH) then + local ok, t = pcall(dofile, SETTINGS_PATH) + if ok and t.config and t.config.plugins and t.config.plugins.profiler then + local options = t.config.plugins.profiler + local profiler_ref = config.plugins.profiler + profiler_ref.enable_on_startup = options.enable_on_startup or false + profiler_ref.log_file = options.log_file or DEFAULT_LOG_PATH + end +end + +if config.plugins.profiler.enable_on_startup then + Profiler.start() +end + +-------------------------------------------------------------------------------- +-- Override core.run to stop profiler before exit if running. +-------------------------------------------------------------------------------- +local core_run = core.run +function core.run(...) + core_run(...) + Profiler.stop() +end + +-------------------------------------------------------------------------------- +-- Add a profiler toggle command. +-------------------------------------------------------------------------------- +command.add(nil, { + ["profiler:toggle"] = function() + if RUNNING then + Profiler.stop() + core.log("Profiler: stopped") + core.root_view:open_doc(core.open_doc(config.plugins.profiler.log_file)) + else + Profiler.start() + core.log("Profiler: started") + end + end +}) + + +return Profiler 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 |