`try` changes backtraces on FreeBSD

[ararslan]

The errorshow tests failed locally for me on FreeBSD 12.0, and when I investigated, I found that the code that fails works fine if run outside of a testset. As it turns out, the try inserted by @testset is what's causing the difference in stack traces. The following is adapted from the tests:

julia> begin
           f(c) = g(c + 1)
           g(c) = c > 10000 ? (return backtrace()) : f(c + 1)
           bt = f(1)
           io = IOBuffer()
           Base.show_backtrace(io, bt)
           println(String(take!(io)))
       end

Stacktrace:
 [1] g(::Int64) at ./REPL[1]:3
 [2] f(::Int64) at ./REPL[1]:2
 ... (the last 2 lines are repeated 5000 more times)
 [10003] top-level scope at REPL[1]:4
 [10004] eval(::Module, ::Any) at ./boot.jl:319
 [10005] eval_user_input(::Any, ::REPL.REPLBackend) at /usr/home/alex/Projects/julia/usr/share/julia/stdlib/v1.1/REPL/src/REPL.jl:85
 [10006] macro expansion at /usr/home/alex/Projects/julia/usr/share/julia/stdlib/v1.1/REPL/src/REPL.jl:117 [inlined]

julia> try
           f(c) = g(c + 1)
           g(c) = c > 10000 ? (return backtrace()) : f(c + 1)
           bt = f(1)
           io = IOBuffer()
           Base.show_backtrace(io, bt)
           println(String(take!(io)))
       catch err
           err
       end

Stacktrace:
 [1] (::getfield(Main, Symbol("#g#4")){getfield(Main, Symbol("#f#3"))})(::Int64) at ./REPL[2]:3
 [2] (::getfield(Main, Symbol("#f#3")))(::Int64) at ./REPL[2]:2
 ... (the last 2 lines are repeated 145 more times)
 [293] (::getfield(Main, Symbol("#g#4")){getfield(Main, Symbol("#f#3"))})(::Int64) at ./REPL[2]:3

I'm also seeing this on FreeBSD 11.2, which is what our CI is running. This happens with both Julia 1.0 and master. Julia 0.6 produces the correct number of frames (10006 instead of 293) but without the collapsing that we now have.

Note that this issue seems similar to #29695, but Julia is not running with --compile=min here.

[c42f]

#29695 can only corrupt about one frame per 1000 or so because that's the chunk size used in jl_backtrace_from_here. So I don't think this can be the same thing.

I can't repro this on linux, but here's some things which might help a little:

• Look at the raw backtrace instead of the pretty printed one.
• Look at backtrace(true) (ie, including C frames)

[ararslan]

I can't repro this on linux

Likewise, nor on macOS; I've only seen it on FreeBSD. If it occurred elsewhere the tests would be failing on CI, but oddly enough the tests pass even on FreeBSD CI.

Look at the raw backtrace instead of the pretty printed one.

Without try, I get 10016 elements in the stack trace, including jl_fptr_trampoline, do_call, etc. at the end. With try, I get 441 elements, and all are calls to f or g.

Look at backtrace(true) (ie, including C frames)

? I only see one method for backtrace(), which is no arguments.

[ararslan]

Ah, I see, it's stacktrace(::Bool). I was doing map(StackTraces.lookup, x) over the arrays from backtrace. Using stacktrace(x, true), I get C functions without try and no C functions with try.

[c42f]

Sorry, as you found out I meant stacktrace(), not backtrace().

Anyway, is this the difference between the system deciding to run this code in the interpreter vs not? Maybe interpreter stack traces are broken on FreeBSD? There's certainly enough system-specific black magic in interpreter-stacktrace.c that it wouldn't be too surprising.

What happens without the try, but with --compile=min vs --compile=yes?

[c42f]

Well, StackOverflow() is what happens with --compile=min locally... but presumably the 10000 can be decreased to repro with a much shallower stack.

[iblislin]

I guess the root cause is not try statement, it's issue of scope.
let statement can trigger this issue as well.
On my 12.0-PRERELEASE

julia> begin
         f(c) = g(c + 1)
         g(c) = c > 10000 ? (return backtrace()) : f(c + 1)
         bt = f(1)
         io = IOBuffer()
         Base.show_backtrace(io, bt)
         println(String(take!(io)))
       end


Stacktrace:
 [1] g(::Int64) at ./REPL[14]:3
 [2] f(::Int64) at ./REPL[14]:2
 ... (the last 2 lines are repeated 5000 more times)
 [10003] top-level scope at REPL[14]:4
 [10004] eval(::Module, ::Any) at ./boot.jl:319
 [10005] eval_user_input(::Any, ::REPL.REPLBackend) at /usr/home/iblis/git/julia/usr/share/julia/stdlib/v1.1/REPL/src/REPL.jl:85
 [10006] macro expansion at /usr/home/iblis/git/julia/usr/share/julia/stdlib/v1.1/REPL/src/REPL.jl:117 [inlined]

julia> let
         f(c) = g(c + 1)
         g(c) = c > 10000 ? (return backtrace()) : f(c + 1)
         bt = f(1)
         io = IOBuffer()
         Base.show_backtrace(io, bt)
         println(String(take!(io)))
       end

Stacktrace:
 [1] (::getfield(Main, Symbol("#g#10")){getfield(Main, Symbol("#f#9"))})(::Int64) at ./REPL[15]:3
 [2] (::getfield(Main, Symbol("#f#9")))(::Int64) at ./REPL[15]:2
 ... (the last 2 lines are repeated 145 more times)
 [293] (::getfield(Main, Symbol("#g#10")){getfield(Main, Symbol("#f#9"))})(::Int64) at ./REPL[15]:3

[ararslan]

Interesting note about let.

I've also noticed that I get the same backtrace with begin, let, and try if I define f and g as anonymous functions, i.e.

f = c->g(c + 1)
g = c->c > 10000 ? (return backtrace()) : f(c + 1)

both on 11.2 and 12.0.

[ararslan]

Running in the interpreter I get the same backtrace for both cases: begin and try/let. Said backtrace is markedly different than when running normally though. EDIT: Except with C functions omitted (stacktrace(x, false)), then they're identical.

[c42f]

I can repro this with the FreeBSD image FreeBSD-12.0-RC3-amd64.qcow2 running on KVM.

I thought it was a bug in interpreter backtraces, but looks like it might be a bug in walking the native stack instead. Here's a repro in global scope showing the edge of the failure condition:

f = c-> g(c + 1)
g = c-> c > 10000 ? (return backtrace()) : f(c + 1)
bt = f(1)


@show length(f(9833))
display(stacktrace(f(9833), true))

println()
@show length(f(9831))
display(stacktrace(f(9831), true))

which prints

length(f(9833)) = 363
370-element Array{Base.StackTraces.StackFrame,1}:
 (::getfield(Main, Symbol("##33#34")))(::Int64) at test.jl:13            
 (::getfield(Main, Symbol("##33#34")))(::Int64)                          
 (::getfield(Main, Symbol("##31#32")))(::Int64) at test.jl:12            
 (::getfield(Main, Symbol("##31#32")))(::Int64)                          
 (::getfield(Main, Symbol("##33#34")))(::Int64) at test.jl:13            
 (::getfield(Main, Symbol("##33#34")))(::Int64)                          
 (::getfield(Main, Symbol("##31#32")))(::Int64) at test.jl:12            
 (::getfield(Main, Symbol("##31#32")))(::Int64)                          
 (::getfield(Main, Symbol("##33#34")))(::Int64) at test.jl:13            
 ⋮                                                                       
 jl_toplevel_eval_in at toplevel.c:793                                   
 eval(::Module, ::Any) at boot.jl:319                                    
 eval_user_input(::Any, ::REPL.REPLBackend) at REPL.jl:85                
 macro expansion at REPL.jl:117 [inlined]                                
 (::getfield(REPL, Symbol("##26#27")){REPL.REPLBackend})() at task.jl:259
 jl_apply at julia.h:1571 [inlined]                                      
 start_task at task.c:572                                                
 ip:0xffffffffffffffff                                                   

length(f(9831)) = 341
341-element Array{Base.StackTraces.StackFrame,1}:
 (::getfield(Main, Symbol("##33#34")))(::Int64) at test.jl:13
 (::getfield(Main, Symbol("##33#34")))(::Int64)              
 (::getfield(Main, Symbol("##31#32")))(::Int64) at test.jl:12
 (::getfield(Main, Symbol("##31#32")))(::Int64)              
 (::getfield(Main, Symbol("##33#34")))(::Int64) at test.jl:13
 (::getfield(Main, Symbol("##33#34")))(::Int64)              
 (::getfield(Main, Symbol("##31#32")))(::Int64) at test.jl:12
 (::getfield(Main, Symbol("##31#32")))(::Int64)              
 (::getfield(Main, Symbol("##33#34")))(::Int64) at test.jl:13
 ⋮                                                           
 (::getfield(Main, Symbol("##33#34")))(::Int64)              
 (::getfield(Main, Symbol("##31#32")))(::Int64) at test.jl:12
 (::getfield(Main, Symbol("##31#32")))(::Int64)              
 (::getfield(Main, Symbol("##33#34")))(::Int64) at test.jl:13
 (::getfield(Main, Symbol("##33#34")))(::Int64)              
 (::getfield(Main, Symbol("##31#32")))(::Int64) at test.jl:12
 (::getfield(Main, Symbol("##31#32")))(::Int64)              
 (::getfield(Main, Symbol("##33#34")))(::Int64) at test.jl:13

Note the stack trace has been truncated in f(9831), with the bottom of the stack disappearing completely.

[c42f]

A more minimalistic reproduction, stripping away the mutually recursive functions and any Base stack formatting machinery:

@noinline function raw_bt()
    bt, bt2 = ccall(:jl_backtrace_from_here, Any, (Int32,), false)
    collect(bt)
end

g = c-> c <= 0 ? (return raw_bt()) : g(c - 1)

@show length(g(167))
@show length(g(168))

Which produces

length(g(167)) = 367
length(g(168)) = 339  # Should be longer, but is missing all the final frames!

[c42f]

By inserting a bunch of printf logging, I've traced this down to a call to unw_step returning 0 too early at

julia/src/stackwalk.c

Line 415 in 7a5042a

return unw_step(cursor) > 0;

So that would suggest a FreeBSD specific bug in libunwind, I suppose?

[c42f]

Or, looking into libunwind, a bug in the way that the DWARF info is emitted by the julia JIT? Turning on libunwind UNW_DEBUG by hacking the libunwind source (there's probably a better way) and running with the environment variable UNW_DEBUG_LEVEL=2 reports

julia> @show length(g(167))
[...]
  >_ULx86_64_step: returning 1
 >_ULx86_64_step: (cursor=0x7fffffff7bd8, ip=0x000000000020251e, cfa=0x00007fffffffe9c0)
 >_ULx86_64_dwarf_search_unwind_table: e->fde_offset = 138, segbase = 2013f8, debug_frame_base = 0, fde_addr = 201530
  >_ULx86_64_step: returning 1
 >_ULx86_64_step: (cursor=0x7fffffff7bd8, ip=0x00000000002023fc, cfa=0x00007fffffffeab0)
 >_ULx86_64_dwarf_search_unwind_table: e->fde_offset = 118, segbase = 2013f8, debug_frame_base = 0, fde_addr = 201510
  >_ULx86_64_step: returning 1
 >_ULx86_64_step: (cursor=0x7fffffff7bd8, ip=0x000000000020211b, cfa=0x00007fffffffeae0)
 >_ULx86_64_dwarf_search_unwind_table: e->fde_offset = 68, segbase = 2013f8, debug_frame_base = 0, fde_addr = 201460
  >_ULx86_64_step: returning 1
 >_ULx86_64_step: (cursor=0x7fffffff7bd8, ip=0x000000080022a000, cfa=0x00007fffffffeb30)
  >_ULx86_64_step: NULL %rbp loc, returning 0
length(g(167)) = 357

vs

julia> @show length(g(168))
[...]
 >_ULx86_64_step: (cursor=0x7fffffff7b58, ip=0x000000081ca017e7, cfa=0x00007fffffff94a0)
 >_ULx86_64_step: [RBP=0x7fffffffd3e0] = 0x7fffffffd3f0 (cfa = 0x7fffffff94a0) -> 0x7fffffffd460
 >_ULx86_64_step: Frame Chain [RIP=0xffffd3f8] = 0x1ca0178f
  >_ULx86_64_step: returning 1
 >_ULx86_64_step: (cursor=0x7fffffff7b58, ip=0x000000081ca0178f, cfa=0x00007fffffff94b0)
 >_ULx86_64_step: [RBP=0x7fffffffd3f0] = 0x7fffffffd460 (cfa = 0x7fffffff94b0) -> 0x7fffffffd470
 >_ULx86_64_step: Frame Chain [RIP=0xffffd468] = 0x1ca017e7
  >_ULx86_64_step: returning 1
 >_ULx86_64_step: (cursor=0x7fffffff7b58, ip=0x000000081ca017e7, cfa=0x00007fffffff94c0)
 >_ULx86_64_step: [RBP=0x7fffffffd460] = 0x7fffffffd470 (cfa = 0x7fffffff94c0) -> 0x7fffffffd4e0
 >_ULx86_64_step: Frame Chain [RIP=0xffffd478] = 0x1ca0178f
  >_ULx86_64_step: returning 1
 >_ULx86_64_step: (cursor=0x7fffffff7b58, ip=0x000000081ca0178f, cfa=0x00007fffffff94d0)
 >_ULx86_64_step: [RBP=0x7fffffffd470] = 0x7fffffffd4e0 (cfa = 0x7fffffff94d0) -> 0x7fffffffd4f0
  >_ULx86_64_step: NULL %rbp loc, returning 0
length(g(168)) = 339

The confusing thing is that it's giving up while unwinding a recursive self-call (which actually turns into a couple of mutually recursive calls as we can see in the alternating addresses here), so I would have thought the structure of the native stack would be consistent all the way down.

[c42f]

Ah, looks like DWARF lookup failed, so libunwind is falling back to a heuristic:

              /* Heuristic to determine incorrect guess.  For RBP to be a
                 valid frame it needs to be above current CFA, but don't
                 let it go more than a little.  Note that we can't deduce
                 anything about new RBP (rbp1) since it may not be a frame
                 pointer in the frame above.  Just check we get the value. */

which of course can get confused. So I guess this is down to lack of — or somehow broken — dwarf info emitted by the JIT on FreeBSD.