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

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

profile = require 'profile'

--?             profile.stop()
--?             print(profile.report())

    profile.start()