Re: OP_HALT is really useful
[
Date Prev][
Date Next][
Thread Prev][
Thread Next]
[
Date Index]
[
Thread Index]
- Subject: Re: OP_HALT is really useful
- From: Sean Conner <sean@...>
- Date: 2018年5月27日 19:06:29 -0400
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 ... )