"profile.lua" a tool for finding bottlenecks

[ivan]

profile.lua is a real-time, non-intrusive tool for finding bottlenecks in your game.
You don't have to modify any of your existing code to use this tool.
Basically, you require the profiler and tell it when to start/stop collecting data.
It's good to reset the profiler every 100 frames so you can look for bottlenecks in real-time.

Example:

Code: Select all

-- setup
function love.load()
  love.profiler = require('profile')  
  love.profiler.start()
end

-- usage (generates a report every 100 frames)
love.frame = 0
function love.update(dt)
  love.frame = love.frame + 1
  if love.frame%100 == 0 then
    love.report = love.profiler.report(20)
    love.profiler.reset()
  end
end

-- prints the report
function love.draw()
  love.graphics.print(love.report or "Please wait...")
end

Primary API:

Code: Select all

--- Starts collecting data.
function profile.start()

--- Resets all collected data.
function profile.reset()

--- Stops collecting data.
function profile.stop()

--- Generates a report from the collected data.
-- @param s Type of sorting, could be by "call" (number of calls) or "time" (execution time)
-- @return Report string
function profile.report(n)

Repository: https://github.com/2dengine/profile.lua
Dependencies: pure Lua, uses the "debug" module
Memory: uses a lot of memory so make sure your GC is not disabled
CPU: calling functions is slower while profiling so make sure to disable it in production code
Limitations: hooking C functions is not very useful but you don't really need to profile those anyways

[Roland_Yonaba]

I like that. Haven't tried it yet, but I like the features.
May I suggest one thing ?

Let the user implement this:

Code: Select all

function profiler.update(dt)
 -- this one would be implemented by the user, and will be called every dt in love.update.
  love.frame = love.frame + 1
end

Have this, or something similar:

Code: Select all

function profiler.resetIf(cond, action, ...)
  if cond() then
    action(...)
    love.profiler.reset()
  end
end

Well, it might look like a bit of an overkill, but I like how the code breaks into smaller pieces, this way. I think the whole code would look nicer, IMHO.

Code: Select all

    -- setup
    local logReport -- will be defined further in love.load
    function love.load()
      love.profiler = require('profile') 
      love.profiler.hookall("Lua")

      function love.profile.update(dt) love.frame = (love.frame or 0) + 1 end
      function logReport(sortBy, rowCount) love.profiler.report(sortBy, rowCount) end

      love.profiler.start()
    end

    function love.update(dt)
      love.profile.update(dt)
      love.profiler.resetIf(function() return love.frame%100==0 end, logReport, 'time', 20)
    end

Just my two cents. I am pretty sure you get the idea and eventually come up with something better.
Might not be error prone, I wrote it from scratch, though.
Please Ivan, git it. Or I'll do that for you.

[ivan]

Hey Roland,
Thanks so much for taking a look.
Your addition is pretty good.
The reason the I didn't include 'profile.update'
is because there are so many different usage cases.
Like for example testing functions (not in realtime):

Code: Select all

profiler.start()
TEST_FUNC1()
profiler.stop()
result1 = profiler.report()

profiler.reset()

profiler.start()
TEST_FUNC2()
profiler.stop()
result2 = profiler.report()

Your code is fine if you want to do realtime profiling, except for:

Code: Select all

love.profiler.resetIf(function() return love.frame%100==0 end, logReport, 'time', 20)

This line creates a new closure each frame and it will probably spam the profiler report.
I would change it to:

Code: Select all

love.profiler.shouldReset = function()
  return love.frame%100==0
end
love.profiler.resetIf(profiler.shouldReset, 'time', 20)

Please Ivan, git it. Or I'll do that for you.

Sure, be my guest.
The code is on Bitbucket too but you have to dig under: utils/log/profile.lua

[ivan]

Just a small update:
I've cleaned up this lib and moved it to a new repository:
https://bitbucket.org/itraykov/profile.lua/src/

[MrFariator]

Wasn't able to find the info on a cursory glance, but what's the license for your profiler?

[ivan]

MIT License

[MrFariator]

Alright, thanks for the response.

[ivan]

Just released an update to the profiler fixing a significant bug in tracking the elapsed duration of function calls.
It's easy to generate any type of report that you want, for example CSV:

Code: Select all

print('Position,Function name,Number of calls,Time,Average time per call,Source code')
local n = 1
for func, called, elapsed, source in profiler.query("time", 10) do
  local t = {n, func, called, elapsed, elapsed/called, source }
  print(table.concat(t, ","))
  n = n + 1
end
profiler.reset()

[grump]

Interesting. I wanted to write a profiler much like this one a while ago, but I learned quickly that using debug hooks to profile Lua code in LuaJIT does not work reliably with jit enabled. The LuaJIT author said so himself, so I gave up.

Your code uses the debug hook mechanism, does it work reliably now? Did you do anything special to make it work? Have you run into strange hook behavior, for example the "return" event never firing for some calls?

[ivan]

Originally, I had this running with plain Lua but noticed some weird stuff when I transferred it to LuaJIT.
Unfortunately the fix for LuaJIT results in increased memory consumption.
Previously, I used a "stack" which allowed me to figure out when functions were returning, but to play nicely with LuaJIT/FFI I have to call debug.getinfo twice as often.
So yea, it's very inefficient in terms of memory, since "getinfo" creates a temporary table each time, but it's the only option we've got in pure Lua.
In short, it works good for profiling games during playtesting, but should be disabled in production code.