Profiler In Lua

wiki

(It was written in about 12 minutes, so bear with me here. --Pedro)

Usage: call Profiler:activate() to start measuring, Profiler:deactivate() to stop, and then Profiler:print_results() to see the results. Tweak the print function to your heart's desire to sort the way you want, etc.

Note that through overloading os.time() with a non-ANSI, millisecond-precision function one can enhance the thing. But for my application seconds was good enough to spot the lines that were making time go quadratical instead of linear.

Also note that for now it can only measure line execution counts and times. One could extend it to call execution if necessary. Some preparations have been made, but not nearly enough.

--| Profiler module.

--b "Pedro Miller Rabinovitch" <miller@inf.puc-rio.br>

--$Id: prof.lua,v 1.4 2003/10/17 00:17:21 miller Exp $

--TODO  add function call profiling. Some of the skeleton is already in

---     place, but call profiling behaves different, so a couple of new

---     functionalities must be added.

--TODO  add methods for proper result retrieval

--TODO  use optional clock() function for millisecond precision, if it's

---     available



local E, I = {}, {}

--& Profiler module.

Profiler = E



--. Keeps track of the hit counts of each item

E.counts = {

  line = {}

}

--. These should be inside the _line_ table above.

E.last_line = nil

E.last_time = os.time()

E.started, E.ended = nil, nil



--% Activates the profiling system.

--@ [kind] (string) Optional hook kind. For now, only 'line' works,

--- so just avoid it. >: )

function E:activate( kind )

  kind = kind or 'line'



  local function hook_counter( hk_name, param,... )

    local t = self.counts[hk_name][param]

    if t == nil then

      t = { count=0, time = 0 }

      self.counts[hk_name][param] = t

    end

    self.counts[hk_name][param].count =

     self.counts[hk_name][param].count + 1



    if self.last_line then

      local delta = os.time() - self.last_time

      if delta > 0 then

        self.counts[hk_name][self.last_line].time =

         self.counts[hk_name][self.last_line].time + delta

        self.last_time = os.time()

      end

    end



    self.last_line = param

  end



  self.started = os.time()

  debug.sethook( hook_counter, kind )

end



--% Deactivates the profiling system.

--@ [kind] (string) Optional hook kind. For now, only 'line' works,

--- so just avoid it.

function E:deactivate( kind )

  kind = kind or 'line'

  self.ended = os.time()

  debug.sethook( nil, kind )

end



--% Prints the results.

--@ [kind] (string) Optional hook... Aah, you got it by now.

--TODO add print output formatting and sorting

function E:print_results( kind )

  kind = kind or 'line'

  print( kind, 'count', 'approx. time (s)' )

  print( '----', '-----', '----------------' )

  for i,v in pairs( self.counts[kind] ) do

    print( i, v.count, v.time )

  end

  print( self.ended - self.started,

    ' second(s) total (approximately).' )

end