Re: OP_HALT is really useful

[Sean Conner <sean@...>]

It was thus said that the Great Sven Olsen once stated:
> >
> > It can also be used for dtrace-like instrumentation points.
> 
> Interesting.  After mucking around in the VM for the purposes of applying
> your patch, I've started daydreaming about writing some instrumentation
> hooks of my own.  What I'd like to do is generate a call stack trace +
> runtime info for a given entry point, so that I can more easily track down
> runtime bottlenecks.  I'm beginning to believe that this may be pretty
> easy, my current plan is more or less:
> 
> 1) Hack into OP_CALL and OP_TAILCALL to update some lightweight C
> structures with timing info in the case that we're running with
> instrumentation switched on.

  You might want to look at what Lua already provides before spending time
on this.  A simple way to profile is to simply sample where the program is
at regular intervals and that can be done with a function like:

function profile(f)
  local data = {}

  local function hook()
    local info = debug.getinfo(2,'Sl')
    local key  = string.format("%s:%s",info.source,info.currentline)
    if not data[key] then data[key] = 0 end
    data[key] = data[key] + 1
  end

  debug.sethook(hook,"",7) -- check location after 7 VM cycles
  f()
  debug.sethook()

  local res = {}
  for key,value in pairs(data) do
    table.insert(res,{ where = key , hits = value })
  end

  table.sort(res,function(a,b)
    if a.hits > b.hits then return true end
    if a.hits < b.hits then return false end
    return a.where < b.where
  end)

  return res
end

I ran this with luacheck (because that does significant work and is CPU
bound) and got the following results:

     29057 @/home/spc/.luarocks/share/lua/5.1/luacheck/standards.lua:130
     16605 @/home/spc/.luarocks/share/lua/5.1/luacheck/standards.lua:98
     16604 @/home/spc/.luarocks/share/lua/5.1/luacheck/standards.lua:97
     12451 @/home/spc/.luarocks/share/lua/5.1/luacheck/standards.lua:107
      9648 @/home/spc/.luarocks/share/lua/5.1/luacheck/standards.lua:108
      8303 @/home/spc/.luarocks/share/lua/5.1/luacheck/standards.lua:103

Here, line 130 of standards.lua was most often seen running when we checked. 
To do what you want to do, hooking CP_CALL and CP_TAILCALL to get function
time overhead, I would first do this in Lua to see if it gives you the
information you want.  You'll want the 'c' and 'r' hooks so you get the
entry and exit point for functions.  Something like:

function clock() end	-- return current time (preferrably a monotonic
			-- clock and not a wall clock, which can change time
			-- on you at least twice a year) at required
			-- precision.

function profile_time(f)
  local stack = { clock() }
  local data  = {}

  local function hook(what)
    local info = debug.getinfo(2,"Sn")
    local key  = string.format("%s %s",info.source,info.name)
    
    if not data[key] then
      data[key] = 0
    end

    if what == 'call' then
      table.insert(stack,clock())

    elseif what == 'return' then
      local now  = clock()
      data[key] = data[key] + (now - table.remove(stack))

    elseif what == 'tail return' then
      local now = clock()
      data[key] = data[key] + (now - table.remove(stack))
    end
  end
  
  debug.sethook(hook,"cr")
  f()
  debug.sethook()
  
  local res = {}
  for key,value in pairs(data) do
    table.insert(res,{ where = key , time = value })
  end
  
  table.sort(res,function(a,b)
    if a.time > b.time then return true end
    if a.time < b.time then return false end
    return a.where < b.where
  end)

  return res
end

I ran this over luacheck and got:

   3942314 @/home/spc/.luarocks/share/lua/5.1/luacheck/check.lua 
   3185576 @/home/spc/.luarocks/share/lua/5.1/luacheck/main.lua 
   2877918 =[C] require
   2763300 =[C] xpcall
   2716661 @/home/spc/.luarocks/share/lua/5.1/luacheck/utils.lua try
   2210802 @/home/spc/.luarocks/lib/luarocks/rocks/luacheck/0.21.2-1/bin/luacheck f
   1603145 =[C] pcall
   1376311 @/home/spc/.luarocks/share/lua/5.1/luacheck/parser.lua 
   1312949 @/home/spc/.luarocks/share/lua/5.1/luacheck/parser.lua parse_block
   1310442 @/home/spc/.luarocks/share/lua/5.1/luacheck/parser.lua parse_statement
   1301092 @/home/spc/.luarocks/share/lua/5.1/luacheck/standards.lua add_fields
   1132164 @/home/spc/.luarocks/share/lua/5.1/luacheck/utils.lua map

  Note---this is total accumulated time, including subroutine calls.  From the
first output, showing that standards.lua:130 was most often seen, that line
is in the function add_fields(), which here we can see took 1301092
microseconds (that's the unit here) to run.  

  It should be easy to combine the two to get a stack dump and timing
information to produce those flame graphs
(http://www.brendangregg.com/flamegraphs.html) everybody seems to be
producing nowadays.

  Do it in Lua, profile and then decide if you need to modify the Lua
interpeter.

  -spc (Profile and enjoy ... )