profiler.lua

--[[
@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