Skip to content

Commit

Permalink
Move the sampling profiler into base
Browse files Browse the repository at this point in the history
This also cleans up many aspects of the API:
  - Rename SProfile->Profile
  - Don't include sprofile_ in function names, use module scoping
  - Export only @Profile, all others get scoped
  - Combine _tree and _flat into a single Profile.print() method
  - kwargs for Profile.print():
       format:   :tree, :flat
       C:        true, false  (whether to show C instruction pointers)
       combine:  true, false  (whether to merge ips resolving to same info)
       cols:     <Integer>    (the number of columns used in formatting)
  - Pass data as an argument to Profile.print() (now it's possible to
       profile the profiler!)
  - Define a LineInfo immutable to store code lookups (instead of tuples)
  - Use better variable names
  • Loading branch information
timholy committed Jul 25, 2013
1 parent 20c206a commit 39cd8dc
Show file tree
Hide file tree
Showing 6 changed files with 411 additions and 26 deletions.
7 changes: 7 additions & 0 deletions base/client.jl
Original file line number Diff line number Diff line change
Expand Up @@ -312,6 +312,12 @@ function init_head_sched()
yield()
end

function init_profile()
# Use a max size of 1M profile samples, and fire timer evey 1ms
Profile.init(1_000_000, 0.001)
end


function _start()
# set up standard streams
reinit_stdio()
Expand All @@ -324,6 +330,7 @@ function _start()
Sys.init()
GMP.gmp_init()
global const CPU_CORES = Sys.CPU_CORES
init_profile()

@windows_only begin
user_data_dir = abspath(ENV["AppData"],"julia")
Expand Down
2 changes: 2 additions & 0 deletions base/exports.jl
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,7 @@ export
Errno,
Meta,
Graphics,
Profile,

# Types
AbstractMatrix,
Expand Down Expand Up @@ -1244,6 +1245,7 @@ export
@timed,
@elapsed,
@allocated,
@profile,
@which,
@windows_only,
@unix_only,
Expand Down
357 changes: 357 additions & 0 deletions base/profile.jl
Original file line number Diff line number Diff line change
@@ -0,0 +1,357 @@
module Profile

import Base: hash, isequal

export @profile

macro profile(ex)
quote
try
status = start_timer()
if status < 0
error(error_codes[status])
end
$(esc(ex))
finally
stop_timer()
end
end
end

####
#### User-level functions
####
function init(nsamples::Integer, delay::Float64)
status = ccall(:profile_init, Cint, (Csize_t, Uint64), nsamples, iround(10^9*delay))
if status == -1
error("Could not allocate space for ", nsamples, " profiling samples")
end
end

clear() = ccall(:profile_clear_data, Void, ())

function print(io::IO = STDOUT, data = fetch(); format = :tree, C = false, combine = true, cols = tty_cols())
if format == :tree
tree(io, data, C, combine, cols)
elseif format == :flat
flat(io, data, C, combine, cols)
else
error("Output format ", format, " not recognized")
end
end


####
#### Internal interface
####
immutable LineInfo
func::ASCIIString
file::ASCIIString
line::Int
end

const UNKNOWN = LineInfo("?", "?", -1)

isequal(a::LineInfo, b::LineInfo) = a.line == b.line && a.func == b.func && a.file == b.file

hash(li::LineInfo) = bitmix(hash(li.func), bitmix(hash(li.file), hash(li.line)))

# C wrappers
start_timer() = ccall(:profile_start_timer, Cint, ())

stop_timer() = ccall(:profile_stop_timer, Void, ())

get_data_pointer() = convert(Ptr{Uint}, ccall(:profile_get_data, Ptr{Uint8}, ()))

len_data() = convert(Int, ccall(:profile_len_data, Uint, ()))

maxlen_data() = convert(Int, ccall(:profile_maxlen_data, Uint, ()))

function lookup(ip::Uint, doCframes::Bool)

This comment has been minimized.

Copy link
@vtjnash

vtjnash Jul 25, 2013

Member

isn't this function duplicated somewhere else in base? presumably it could be shared between the code for printing a backtrace and here

This comment has been minimized.

Copy link
@timholy

timholy Jul 25, 2013

Author Member

repl.jl has this line in the middle of show_backtrace:

lkup = ccall(:jl_lookup_code_address, Any, (Ptr{Void}, Int32), t[i], 0)

Since show_backtrace doesn't need to manipulate lists of backtraces, it doesn't really need to define a storage mechanism for code lookups. My suspicion is that there is little value in converting show_backtrace use this function. If others disagree, please go right ahead.

info = ccall(:jl_lookup_code_address, Any, (Ptr{Void}, Bool), ip, doCframes)
if length(info) == 3
return LineInfo(string(info[1]), string(info[2]), int(info[3]))
else
return UNKNOWN
end
end

error_codes = (Int=>ASCIIString)[

This comment has been minimized.

Copy link
@vtjnash

vtjnash Jul 25, 2013

Member

I didn't notice that the error codes had particular meanings -- I probably did not map this correctly in the windows code.

This comment has been minimized.

Copy link
@timholy

timholy Jul 26, 2013

Author Member

To me it looks like your choice works out pretty well. If you prefer, we could wrap the usage of this in @unix_only.

This comment has been minimized.

Copy link
@vtjnash

vtjnash Jul 26, 2013

Member

it's not important to me, i just randomly picked unique numbers so I wasn't sure how that would play out

-1=>"Cannot specify signal action for profiling",
-2=>"Cannot create the timer for profiling",
-3=>"Cannot start the timer for profiling"]

function fetch()
len = len_data()
maxlen = maxlen_data()
if (len == maxlen)
warn("the profile data buffer is full; profiling probably terminated\nbefore your program finished. To profile for longer runs, call Profile.init()\nwith a larger buffer and/or larger delay.")
end
pointer_to_array(get_data_pointer(), (len,))
end


# Number of backtrace "steps" that are triggered by taking the backtrace, e.g., inside profile_bt
# May be platform-specific?
const btskip = 2

## Print as a flat list
# Counts the number of times each line appears, at any nesting level
function parse_flat(data::Vector{Uint}, doCframes::Bool)
linecount = (Uint=>Int)[]
toskip = btskip
for ip in data
if toskip > 0
toskip -= 1
continue
end
if ip == 0
toskip = btskip
continue
end
linecount[ip] = get(linecount, ip, 0)+1
end
buf = Array(Uint, 0)
n = Array(Int, 0)
for (k,v) in linecount
push!(buf, k)
push!(n, v)
end
# Convert instruction pointers to names & line numbers
lilist = Array(LineInfo, length(buf))
for i = 1:length(buf)
lilist[i] = lookup(buf[i], doCframes)
end
# Keep only the interpretable ones
# The ones with no line number might appear multiple times in a single
# backtrace, giving the wrong impression about the total number of backtraces.
# Delete them too.
keep = !Bool[x == UNKNOWN || x.line == 0 for x in lilist]
n = n[keep]
lilist = lilist[keep]
lilist, n
end

function flat(io::IO, data::Vector{Uint}, doCframes::Bool, combine::Bool, cols::Integer)
lilist, n = parse_flat(data, doCframes)
if isempty(n)
warning_empty()
return
end
p = liperm(lilist)
lilist = lilist[p]
n = n[p]
if combine
j = 1
for i = 2:length(lilist)
if lilist[i] == lilist[j]
n[j] += n[i]
n[i] = 0
else
j = i
end
end
keep = n .> 0
n = n[keep]
lilist = lilist[keep]
end
wcounts = max(6, ndigits(max(n)))
maxline = 0
maxfile = 0
maxfunc = 0
for li in lilist
maxline = max(maxline, li.line)
maxfile = max(maxfile, length(li.file))
maxfunc = max(maxfunc, length(li.func))
end
wline = max(5, ndigits(maxline))
ntext = cols - wcounts - wline - 3
if maxfile+maxfunc <= ntext
wfile = maxfile
wfunc = maxfunc
else
wfile = ifloor(2*ntext/5)
wfunc = ifloor(3*ntext/5)
end
println(io, lpad("Count", wcounts, " "), " ", rpad("File", wfile, " "), " ", rpad("Function", wfunc, " "), " ", lpad("Line", wline, " "))
for i = 1:length(n)
li = lilist[i]
println(io, lpad(string(n[i]), wcounts, " "), " ", rpad(truncto(li.file, wfile), wfile, " "), " ", rpad(truncto(li.func, wfunc), wfunc, " "), " ", lpad(string(li.line), wline, " "))
end
end

## A tree representation
# Identify and counts repetitions of all unique backtraces
function tree_aggregate(data::Array{Uint})
iz = find(data .== 0) # find the breaks between backtraces
treecount = (Vector{Uint}=>Int)[]
istart = 1+btskip
for iend in iz
tmp = data[iend-1:-1:istart]
treecount[tmp] = get(treecount, tmp, 0)+1
istart = iend+1+btskip
end
bt = Array(Vector{Uint}, 0)
counts = Array(Int, 0)
for (k,v) in treecount
push!(bt, k)
push!(counts, v)
end
bt, counts
end

tree_format_linewidth(x::LineInfo) = ndigits(x.line)+6

function tree_format(lilist::Vector{LineInfo}, counts::Vector{Int}, level::Int, cols::Integer)
nindent = min(ifloor(cols/2), level)
ndigcounts = ndigits(max(counts))
ndigline = max([tree_format_linewidth(x) for x in lilist])
ntext = cols-nindent-ndigcounts-ndigline-5
widthfile = ifloor(0.4ntext)
widthfunc = ifloor(0.6ntext)
strs = Array(ASCIIString, length(lilist))
showextra = false
if level > nindent
nextra = level-nindent
nindent -= ndigits(nextra)+2
showextra = true
end
for i = 1:length(lilist)
li = lilist[i]
if li != UNKNOWN
base = " "^nindent
if showextra
base = string(base, "+", nextra, " ")
end
base = string(base,
rpad(string(counts[i]), ndigcounts, " "),
" ",
truncto(string(li.file), widthfile),
"; ",
truncto(string(li.func), widthfunc),
"; ")
strs[i] = string(base, "line: ", li.line)
else
strs[i] = ""
end
end
strs
end

# Print a "branch" starting at a particular level. This gets called recursively.
function tree(io::IO, bt::Vector{Vector{Uint}}, counts::Vector{Int}, level::Int, doCframes::Bool, combine::Bool, cols::Integer)
# Organize backtraces into groups that are identical up to this level
if combine
# Combine based on the line information
d = (LineInfo=>Vector{Int})[]
for i = 1:length(bt)
ip = bt[i][level+1]
key = lookup(ip, doCframes)
indx = Base.ht_keyindex(d, key)
if indx == -1
d[key] = [i]
else
push!(d.vals[indx], i)
end
end
# Generate counts
dlen = length(d)
lilist = Array(LineInfo, dlen)
group = Array(Vector{Int}, dlen)
n = Array(Int, dlen)
i = 1
for (key, v) in d
lilist[i] = key
group[i] = v
n[i] = sum(counts[v])
i += 1
end
else
# Combine based on the instruction pointer
d = (Uint=>Vector{Int})[]
for i = 1:length(bt)
key = bt[i][level+1]
indx = Base.ht_keyindex(d, key)
if indx == -1
d[key] = [i]
else
push!(d.vals[indx], i)
end
end
# Generate counts, and do the code lookup
dlen = length(d)
lilist = Array(LineInfo, dlen)
group = Array(Vector{Int}, dlen)
n = Array(Int, dlen)
i = 1
for (key, v) in d
lilist[i] = lookup(key, doCframes)
group[i] = v
n[i] = sum(counts[v])
i += 1
end
end
# Order the line information
p = liperm(lilist)
lilist = lilist[p]
group = group[p]
n = n[p]
# Generate the string for each line
strs = tree_format(lilist, n, level, cols)
# Recurse to the next level
len = Int[length(x) for x in bt]
for i = 1:length(lilist)
if !isempty(strs[i])
println(io, strs[i])
end
idx = group[i]
keep = len[idx] .> level+1
if any(keep)
idx = idx[keep]
tree(io, bt[idx], counts[idx], level+1, doCframes, combine, cols)
end
end
end

function tree(io::IO, data::Vector{Uint}, doCframes::Bool, combine::Bool, cols::Integer)
bt, counts = tree_aggregate(data)
if isempty(counts)
warning_empty()
return
end
level = 0
len = Int[length(x) for x in bt]
keep = len .> 0
tree(io, bt[keep], counts[keep], level, doCframes, combine, cols)
end

# Utilities
function truncto(str::ASCIIString, w::Int)
ret = str;
if length(str) > w
ret = string("...", str[end-w+4:end])
end
ret
end

# Order alphabetically (file, function) and then by line number
function liperm(lilist::Vector{LineInfo})
comb = Array(ASCIIString, length(lilist))
for i = 1:length(lilist)
li = lilist[i]
if li != UNKNOWN
comb[i] = @sprintf("%s:%s:%06d", li.file, li.func, li.line)
else
comb[i] = "zzz"
end
end
sortperm(comb)
end

warning_empty() = warn("""
There were no samples collected. Run your program longer (perhaps by
running it multiple times), or adjust the delay between samples with
Profile.init().""")


end # module
Loading

0 comments on commit 39cd8dc

Please sign in to comment.