Add Profiler Plugin (#155)

3 files changed, 456 insertions, 0 deletions

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.
+
+![command](https://user-images.githubusercontent.com/1702572/202113672-6ba593d9-03be-4462-9e82-e3339cf2722f.png)
+
+> **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.
+
+![settings](https://user-images.githubusercontent.com/1702572/202113713-7e932b4f-3283-42e6-af92-a1aa9ad09bde.png)
+
+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:
+
+![metrics](https://user-images.githubusercontent.com/1702572/202113736-ef8d550c-130e-4372-b66c-694ee5f4c5c0.png)
+
+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