Skip to content

Commit

Permalink
jit.p: Enhance 'v' mode of profiler
Browse files Browse the repository at this point in the history
This change prints more information when profiling at trace
granularity. The idea is to make it easier to audit the runtime
behavior of your apps: how many traces do they compile into, how are
those traces connected together, and which execution path does each
trace represent.

More detail with examples:

Previously the 'v' mode would print a terse summary. For example when
profiling the rate_limiter app selftest:

    $ sudo ./snabb snsh -jdump=+rs,x -jp=v -t apps.rate_limiter.rate_limiter
    47%  TRACE 16
    22%  TRACE 15
    11%  TRACE 14
    10%  TRACE 12
     4%  TRACE 18
     4%  TRACE 24

More information is shown with this change:

    $ sudo ./snabb snsh -jdump=+rs,x -jp=v -t apps.rate_limiter.rate_limiter
    47%  TRACE  16 (14/4)   ->14       rate_limiter.lua:82
    22%  TRACE  15          ->loop     basic_apps.lua:82
    11%  TRACE  14          ->loop     rate_limiter.lua:73
    10%  TRACE  12          ->loop     basic_apps.lua:26
     4%  TRACE  18 (12/13)  ->14       basic_apps.lua:25
     4%  TRACE  24 (19/10)  ->12       app.lua:293

This tells us:

- Is this a side-trace? If so then (PARENT/EXIT) is shown.
- What does the end of the trace link to? (loop, other trace, ..?)
- What source line does the trace begin on? (Requires -jdump to be in use)

Note that it is also possible to combine this profile mode with line
based profiling to have more visibility into what is happening inside
traces:

    45%  TRACE  13 (10/9)   ->10       rate_limiter.lua:82
      -- 33%  counter.lua:add
      -- 32%  packet.lua:free
      -- 20%  freelist.lua:freelist_add
      -- 10%  rate_limiter.lua:method
      --  3%  link.lua:full
    21%  TRACE   8          ->loop     basic_apps.lua:26
      -- 44%  packet.lua:clone
      -- 18%  counter.lua:add
      -- 11%  packet.lua:allocate
      --  9%  freelist.lua:allocate
      --  9%  basic_apps.lua:method
      --  7%  link.lua:full
      --  4%  link.lua:transmit
    19%  TRACE  10          ->loop     rate_limiter.lua:73
      -- 58%  rate_limiter.lua:method
      -- 21%  link.lua:receive
      -- 17%  counter.lua:add
     7%  TRACE  11          ->loop     basic_apps.lua:82
      -- 74%  counter.lua:add
      -- 21%  link.lua:receive
      --  5%  packet.lua:free_internal
  • Loading branch information
lukego committed Sep 14, 2015
1 parent 065979c commit a212176
Show file tree
Hide file tree
Showing 2 changed files with 42 additions and 4 deletions.
7 changes: 6 additions & 1 deletion lib/luajit/src/jit/dump.lua
Original file line number Diff line number Diff line change
Expand Up @@ -75,6 +75,9 @@ local bcline, disass
-- Active flag, output file handle and dump mode.
local active, out, dumpmode

-- Information about traces that is remembered for future reference.
local info = {}

------------------------------------------------------------------------------

local symtabmt = { __index = false }
Expand Down Expand Up @@ -550,6 +553,7 @@ local function dump_trace(what, tr, func, pc, otr, oex)
if dumpmode.m then dump_mcode(tr) end
end
if what == "start" then
info[tr] = { func = func, pc = pc, otr = otr, oex = oex }
if dumpmode.H then out:write('<pre class="ljdump">\n') end
out:write("---- TRACE ", tr, " ", what)
if otr then out:write(" ", otr, "/", oex) end
Expand Down Expand Up @@ -701,6 +705,7 @@ end
return {
on = dumpon,
off = dumpoff,
start = dumpon -- For -j command line option.
start = dumpon, -- For -j command line option.
info = info
}

39 changes: 36 additions & 3 deletions lib/luajit/src/jit/p.lua
Original file line number Diff line number Diff line change
Expand Up @@ -44,6 +44,8 @@ local jit = require("jit")
assert(jit.version_num == 20100, "LuaJIT core/library version mismatch")
local profile = require("jit.profile")
local vmdef = require("jit.vmdef")
local jutil = require("jit.util")
local dump = require("jit.dump")
local math = math
local pairs, ipairs, tonumber, floor = pairs, ipairs, tonumber, math.floor
local sort, format = table.sort, string.format
Expand Down Expand Up @@ -74,7 +76,38 @@ local function prof_cb(th, samples, vmmode)
-- Collect keys for sample.
if prof_states then
if prof_states == "v" then
key_state = map_vmmode[vmmode] or "TRACE "..vmmode
if map_vmmode[vmmode] then
key_state = map_vmmode[vmmode]
else
-- Sampling a trace: make an understandable one-line description.
local tr = tonumber(vmmode)
local info = jutil.traceinfo(tr)
local extra = dump.info[tr]
-- Show the parent of this trace (if this is a side trace)
local parent = ""
if extra and extra.otr and extra.oex then
parent = "("..extra.otr.."/"..extra.oex..")"
end
-- Show what the end of the trace links to (e.g. loop or other trace)
local lnk = ""
local link, ltype = info.link, info.linktype
if link == tr or link == 0 then lnk = "->"..ltype
elseif ltype == "root" then lnk = "->"..link
else lnk = "->"..link.." "..ltype end
-- Show the current zone (if zone profiling is enabled)
local z = ""
if zone and zone:get() then
z = (" %-16s"):format(zone:get())
end
-- Show the source location where the trace starts
local loc = ""
if extra and extra.func then
local fi = jutil.funcinfo(extra.func, extra.pc)
if fi.loc then loc = fi.loc end
end
local s = ("TRACE %3d %-8s %-10s%s %s"):format(vmmode, parent, lnk, z, loc)
key_state = map_vmmode[vmmode] or s
end
else
key_state = zone:get() or "(none)"
end
Expand Down Expand Up @@ -250,8 +283,8 @@ local function prof_start(mode)
mode = mode:gsub("%-?%d+", function(s) prof_depth = tonumber(s); return "" end)
local m = {}
for c in mode:gmatch(".") do m[c] = c end
prof_states = m.z or m.v
if prof_states == "z" then zone = require("jit.zone") end
prof_states = m.v or m.z
if m.z == "z" then zone = require("jit.zone") end
local scope = m.l or m.f or m.F or (prof_states and "" or "f")
local flags = (m.p or "")
prof_raw = m.r
Expand Down

0 comments on commit a212176

Please sign in to comment.