Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Profile.jl improvements #33190

Merged
merged 11 commits into from
Sep 17, 2019
22 changes: 12 additions & 10 deletions base/client.jl
Original file line number Diff line number Diff line change
Expand Up @@ -79,8 +79,10 @@ function repl_cmd(cmd, out)
nothing
end

# deprecated function--preserved for DocTests.jl
function ip_matches_func(ip, func::Symbol)
for fr in StackTraces.lookup(ip)
ip isa InterpreterIP || (ip -= 1)
for fr in StackTraces.lookupat(ip)
if fr === StackTraces.UNKNOWN || fr.from_c
return false
end
Expand All @@ -90,28 +92,28 @@ function ip_matches_func(ip, func::Symbol)
end

function scrub_repl_backtrace(bt)
if bt !== nothing
if bt !== nothing && !(bt isa Vector{Any}) # ignore our sentinel value types
bt = stacktrace(bt)
# remove REPL-related frames from interactive printing
eval_ind = findlast(addr->ip_matches_func(addr, :eval), bt)
if eval_ind !== nothing
return bt[1:eval_ind-1]
end
eval_ind = findlast(frame -> !frame.from_c && frame.func == :eval, bt)
eval_ind === nothing || deleteat!(bt, eval_ind:length(bt))
end
return bt
end

function display_error(io::IO, er, bt)
printstyled(io, "ERROR: "; bold=true, color=Base.error_color())
showerror(IOContext(io, :limit => true), er, scrub_repl_backtrace(bt))
bt = scrub_repl_backtrace(bt)
showerror(IOContext(io, :limit => true), er, bt, backtrace = bt!==nothing)
println(io)
end
function display_error(io::IO, stack::Vector)
printstyled(io, "ERROR: "; bold=true, color=Base.error_color())
show_exception_stack(IOContext(io, :limit => true), Any[ (x[1], scrub_repl_backtrace(x[2])) for x in stack ])
bt = Any[ (x[1], scrub_repl_backtrace(x[2])) for x in stack ]
show_exception_stack(IOContext(io, :limit => true), bt)
end
display_error(stack::Vector) = display_error(stderr, stack)
display_error(er, bt) = display_error(stderr, er, bt)
display_error(er) = display_error(er, [])
display_error(er, bt=nothing) = display_error(stderr, er, bt)

function eval_user_input(errio, @nospecialize(ast), show_value::Bool)
errcount = 0
Expand Down
20 changes: 8 additions & 12 deletions base/deprecated.jl
Original file line number Diff line number Diff line change
Expand Up @@ -101,33 +101,29 @@ firstcaller(bt::Vector, funcsym::Symbol) = firstcaller(bt, (funcsym,))
function firstcaller(bt::Vector, funcsyms)
# Identify the calling line
found = false
lkup = StackTraces.UNKNOWN
found_frame = Ptr{Cvoid}(0)
for frame in bt
lkups = StackTraces.lookup(frame)
for outer lkup in lkups
for ip in bt
ip isa Base.InterpreterIP || (ip -= 1) # convert from return stack to call stack (for inlining info)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Great, I think this answers my question at #33277 (comment)

lkups = StackTraces.lookupat(ip)
for lkup in lkups
if lkup == StackTraces.UNKNOWN || lkup.from_c
continue
end
if found
found_frame = frame
@goto found
return ip, lkup
end
found = lkup.func in funcsyms
# look for constructor type name
if !found && lkup.linfo isa Core.MethodInstance
li = lkup.linfo
ft = ccall(:jl_first_argument_datatype, Any, (Any,), li.def.sig)
if isa(ft,DataType) && ft.name === Type.body.name
if isa(ft, DataType) && ft.name === Type.body.name
ft = unwrap_unionall(ft.parameters[1])
found = (isa(ft,DataType) && ft.name.name in funcsyms)
found = (isa(ft, DataType) && ft.name.name in funcsyms)
end
end
end
end
return found_frame, StackTraces.UNKNOWN
@label found
return found_frame, lkup
return C_NULL, StackTraces.UNKNOWN
end

deprecate(m::Module, s::Symbol, flag=1) = ccall(:jl_deprecate_binding, Cvoid, (Any, Any, Cint), m, s, flag)
Expand Down
29 changes: 21 additions & 8 deletions base/errorshow.jl
Original file line number Diff line number Diff line change
Expand Up @@ -522,7 +522,8 @@ function show_reduced_backtrace(io::IO, t::Vector, with_prefix::Bool)
i = frame_counter
j = p
while i < length(t) && t[i] == t[j]
i+=1 ; j+=1
i += 1
j += 1
end
if j >= frame_counter-1
#= At least one cycle repeated =#
Expand Down Expand Up @@ -590,6 +591,7 @@ function show_backtrace(io::IO, t::Vector)
end

function show_backtrace(io::IO, t::Vector{Any})
# t is a pre-processed backtrace (ref #12856)
if length(t) < BIG_STACKTRACE_SIZE
try invokelatest(update_stackframes_callback[], t) catch end
for entry in t
Expand All @@ -605,31 +607,42 @@ function process_backtrace(t::Vector, limit::Int=typemax(Int); skipC = true)
last_frame = StackTraces.UNKNOWN
count = 0
ret = Any[]
for i = eachindex(t)
lkups = StackTraces.lookup(t[i])
for i in eachindex(t)
lkups = t[i]
if lkups isa StackFrame
lkups = [lkups]
elseif lkups isa Base.InterpreterIP
lkups = StackTraces.lookupat(lkups)
else
lkups = StackTraces.lookupat(lkups - 1)
end
for lkup in lkups
if lkup === StackTraces.UNKNOWN
continue
end

if lkup.from_c && skipC; continue; end
if i == 1 && lkup.func == :error; continue; end
if lkup.from_c && skipC
continue
end
count += 1
if count > limit; break; end
if count > limit
break
end

if lkup.file != last_frame.file || lkup.line != last_frame.line || lkup.func != last_frame.func || lkup.linfo !== lkup.linfo
if n > 0
push!(ret, (last_frame,n))
push!(ret, (last_frame, n))
end
n = 1
last_frame = lkup
else
n += 1
end
end
count > limit && break
end
if n > 0
push!(ret, (last_frame,n))
push!(ret, (last_frame, n))
end
return ret
end
Expand Down
61 changes: 27 additions & 34 deletions base/stacktraces.jl
Original file line number Diff line number Diff line change
Expand Up @@ -7,8 +7,6 @@ module StackTraces


import Base: hash, ==, show
using Base.Printf: @printf
using Base: something

export StackTrace, StackFrame, stacktrace

Expand Down Expand Up @@ -98,31 +96,28 @@ end


"""
lookup(pointer::Union{Ptr{Cvoid}, UInt}) -> Vector{StackFrame}
lookupat(pointer::Union{Ptr{Cvoid}, UInt}) -> Vector{StackFrame}
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is the name change worth it? I could imagine packages calling lookup. Or is this about handling the off-by-one and you're deliberately breaking direct calls here?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Agreed, this change makes me uncomfortable.


Given a pointer to an execution context (usually generated by a call to `backtrace`), looks
up stack frame context information. Returns an array of frame information for all functions
inlined at that point, innermost function first.
"""
function lookup(pointer::Ptr{Cvoid})
infos = ccall(:jl_lookup_code_address, Any, (Ptr{Cvoid}, Cint), pointer - 1, false)
isempty(infos) && return [StackFrame(empty_sym, empty_sym, -1, nothing, true, false, convert(UInt64, pointer))]
function lookupat(pointer::Ptr{Cvoid})
infos = ccall(:jl_lookup_code_address, Any, (Ptr{Cvoid}, Cint), pointer, false)
pointer = convert(UInt64, pointer)
isempty(infos) && return [StackFrame(empty_sym, empty_sym, -1, nothing, true, false, pointer)] # this is equal to UNKNOWN
res = Vector{StackFrame}(undef, length(infos))
for i in 1:length(infos)
info = infos[i]
@assert(length(info) == 7)
res[i] = StackFrame(info[1], info[2], info[3], info[4], info[5], info[6], info[7])
@assert(length(info) == 6)
res[i] = StackFrame(info[1], info[2], info[3], info[4], info[5], info[6], pointer)
end
return res
end

lookup(pointer::UInt) = lookup(convert(Ptr{Cvoid}, pointer))

const top_level_scope_sym = Symbol("top-level scope")

using Base.Meta
is_loc_meta(expr, kind) = isexpr(expr, :meta) && length(expr.args) >= 1 && expr.args[1] === kind
function lookup(ip::Base.InterpreterIP)
function lookupat(ip::Base.InterpreterIP)
if ip.code isa Core.MethodInstance && ip.code.def isa Method
codeinfo = ip.code.uninferred
func = ip.code.def.name
Expand Down Expand Up @@ -154,10 +149,6 @@ function lookup(ip::Base.InterpreterIP)
return scopes
end

# allow lookup on already-looked-up data for easier handling of pre-processed frames
lookup(s::StackFrame) = StackFrame[s]
lookup(s::Tuple{StackFrame,Int}) = StackFrame[s[1]]

"""
backtrace()

Expand Down Expand Up @@ -195,26 +186,28 @@ doesn't return C functions, but this can be enabled.) When called without specif
trace, `stacktrace` first calls `backtrace`.
"""
function stacktrace(trace::Vector{<:Union{Base.InterpreterIP,Ptr{Cvoid}}}, c_funcs::Bool=false)
stack = vcat(StackTrace(), map(lookup, trace)...)::StackTrace

# Remove frames that come from C calls.
if !c_funcs
filter!(frame -> !frame.from_c, stack)
stack = StackTrace()
for ip in trace
ip isa Base.InterpreterIP || (ip -= 1) # convert from return stack to call stack (for inlining info)
for frame in lookupat(ip)
# Skip frames that come from C calls.
if c_funcs || !frame.from_c
push!(stack, frame)
end
end
end
return stack
end

function stacktrace(c_funcs::Bool=false)
stack = stacktrace(backtrace(), c_funcs)
# Remove frame for this function (and any functions called by this function).
remove_frames!(stack, :stacktrace)

# is there a better way? the func symbol has a number suffix which changes.
# it's possible that no test is needed and we could just popfirst! all the time.
# this line was added to PR #16213 because otherwise stacktrace() != stacktrace(false).
# not sure why. possibly b/c of re-ordering of base/sysimg.jl
!isempty(stack) && startswith(string(stack[1].func),"jlcall_stacktrace") && popfirst!(stack)
stack
# also remove all of the non-Julia functions that led up to this point (if that list is non-empty)
c_funcs && deleteat!(stack, 1:(something(findfirst(frame -> !frame.from_c, stack), 1) - 1))
return stack
end

stacktrace(c_funcs::Bool=false) = stacktrace(backtrace(), c_funcs)

"""
remove_frames!(stack::StackTrace, name::Symbol)

Expand All @@ -224,12 +217,12 @@ all frames above the specified function). Primarily used to remove `StackTraces`
from the `StackTrace` prior to returning it.
"""
function remove_frames!(stack::StackTrace, name::Symbol)
splice!(stack, 1:something(findlast(frame -> frame.func == name, stack), 0))
deleteat!(stack, 1:something(findlast(frame -> frame.func == name, stack), 0))
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Wow. Suggests this needs a test, no?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

They have the same side-effect, splice! just also returns a copy of the deleted values

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oh, right. I was confusing this with our renaming of (un)shift!

return stack
end

function remove_frames!(stack::StackTrace, names::Vector{Symbol})
splice!(stack, 1:something(findlast(frame -> frame.func in names, stack), 0))
deleteat!(stack, 1:something(findlast(frame -> frame.func in names, stack), 0))
return stack
end

Expand All @@ -248,7 +241,7 @@ is_top_level_frame(f::StackFrame) = f.linfo isa Core.CodeInfo || (f.linfo === no
function show_spec_linfo(io::IO, frame::StackFrame)
if frame.linfo === nothing
if frame.func === empty_sym
@printf(io, "ip:%#x", frame.pointer)
print(io, "ip:0x", string(frame.pointer, base=16))
elseif frame.func === top_level_scope_sym
print(io, "top-level scope")
else
Expand Down
4 changes: 2 additions & 2 deletions doc/src/base/stacktraces.md
Original file line number Diff line number Diff line change
Expand Up @@ -7,9 +7,9 @@ Base.StackTraces.stacktrace
```

The following methods and types in `Base.StackTraces` are not exported and need to be called e.g.
as `StackTraces.lookup(ptr)`.
as `StackTraces.lookupat(ptr)`.

```@docs
Base.StackTraces.lookup
Base.StackTraces.lookupat
Base.StackTraces.remove_frames!
```
5 changes: 2 additions & 3 deletions doc/src/manual/stacktraces.md
Original file line number Diff line number Diff line change
Expand Up @@ -300,16 +300,15 @@ julia> stacktrace(trace, true)
```

Individual pointers returned by [`backtrace`](@ref) can be translated into [`StackTraces.StackFrame`](@ref)
s by passing them into [`StackTraces.lookup`](@ref):
s by passing them into [`StackTraces.lookupat`](@ref):

```julia-repl
julia> pointer = backtrace()[1];

julia> frame = StackTraces.lookup(pointer)
julia> frame = StackTraces.lookupat(pointer - 1)
1-element Array{Base.StackTraces.StackFrame,1}:
jl_apply_generic at gf.c:2167

julia> println("The top frame is from $(frame[1].func)!")
The top frame is from jl_apply_generic!
```

4 changes: 2 additions & 2 deletions src/julia_internal.h
Original file line number Diff line number Diff line change
Expand Up @@ -626,9 +626,9 @@ typedef int bt_cursor_t;
// Special marker in backtrace data for encoding interpreter frames
#define JL_BT_INTERP_FRAME (((uintptr_t)0)-1)
size_t rec_backtrace(uintptr_t *data, size_t maxsize) JL_NOTSAFEPOINT;
size_t rec_backtrace_ctx(uintptr_t *data, size_t maxsize, bt_context_t *ctx) JL_NOTSAFEPOINT;
size_t rec_backtrace_ctx(uintptr_t *data, size_t maxsize, bt_context_t *ctx, int add_interp_frames) JL_NOTSAFEPOINT;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Excellent change. I was thinking about this exact problem (Profile getting confused by- / having overhead from- interpreter frames) while making #33277.

#ifdef LIBOSXUNWIND
size_t rec_backtrace_ctx_dwarf(uintptr_t *data, size_t maxsize, bt_context_t *ctx);
size_t rec_backtrace_ctx_dwarf(uintptr_t *data, size_t maxsize, bt_context_t *ctx, int add_interp_frames) JL_NOTSAFEPOINT;
#endif
JL_DLLEXPORT void jl_get_backtrace(jl_array_t **bt, jl_array_t **bt2);
void jl_critical_error(int sig, bt_context_t *context, uintptr_t *bt_data, size_t *bt_size);
Expand Down
2 changes: 1 addition & 1 deletion src/signal-handling.c
Original file line number Diff line number Diff line change
Expand Up @@ -231,7 +231,7 @@ void jl_critical_error(int sig, bt_context_t *context, uintptr_t *bt_data, size_
jl_safe_printf("\nsignal (%d): %s\n", sig, strsignal(sig));
jl_safe_printf("in expression starting at %s:%d\n", jl_filename, jl_lineno);
if (context)
*bt_size = n = rec_backtrace_ctx(bt_data, JL_MAX_BT_SIZE, context);
*bt_size = n = rec_backtrace_ctx(bt_data, JL_MAX_BT_SIZE, context, 0);
for (i = 0; i < n; i++)
jl_gdblookup(bt_data[i] - 1);
gc_debug_print_status();
Expand Down
Loading