Unusual backtrace line numbers with macros

[staticfloat]

I've noticed that Julia's backtrace line numbers don't alway make sense. For instance, in the following short program (named lapack_perf.jl) and ignoring the actual errors in the code:

reps  = 10
n     = 100
srand(1234321)
a     = rand(n,n)
apd   = a'*a

function test_chold{T<:Number}(apd::Matrix{T})
    times = zeros(10)
    cholds = T[]
    times = [@elapsed push(cholds, chold(apd)) for k = reps]

    # return so it doesn't get optimized away
    cholds
end


print( test_chold(apd) )

I get the following backtrace:

$ julia lapack_perf.jl 
no method convert(Type{Float64},CholeskyDense{Float64})
 in method_missing at base.jl:70
 in push at array.jl:708
 in test_chold at /Users/sabae/Desktop/lapack_perf.jl:49
 in load_now at util.jl:231
 in load_now at util.jl:245
 in require at util.jl:174
 in process_options at client.jl:178
 in _start at client.jl:232
at /Users/sabae/Desktop/lapack_perf.jl:17
 in load_now at util.jl:231
 in load_now at util.jl:245
 in require at util.jl:174
 in process_options at client.jl:178
 in _start at client.jl:232
 in load_now at util.jl:256
 in require at util.jl:174
 in process_options at client.jl:178
 in _start at client.jl:232

This all looks fine and good until we see the in test_chold at /Users/sabae/Desktop/lapack_perf.jl:49 line; Clearly this file doesn't have a line 49.

EDIT: This is due to macros, as @dmbates states. Is there a better way to effect line-printing with macros (which are very helpful and therefore likely to be used extensively)?

[dmbates]

Remember that the problematic call occurs within an expansion of the @elapsed macro.

It appears that you are trying to save the results from chold in an array but it would need to be an array of

julia> typeof(chold(apd))
CholeskyDense{Float64}

to be able to do that. Also, the for k = reps is probably not what you want because that will only do the calculation once with a value of k of 10. You probably want for k in 1:reps

Assuming that the calculation does not involve generating random numbers I would do the timing in one loop and the comparison of the results to the desired value externally.

julia> chold(apd)
CholeskyDense{Float64}(100x100 Float64 Array:
 10.7632  -0.0556399   0.424147  -0.673008  :  -0.328331   0.329383   0.561125   0.235107   
  0.0     10.358      -0.184153   1.12445      -0.211135   0.680397  -1.50525   -0.77154    
  0.0      0.0        10.8046    -1.69622       1.2341     1.38032   -0.607595  -0.922997   
  0.0      0.0         0.0        9.74493      -0.123586  -0.60327    0.745185   1.28362    
  0.0      0.0         0.0        0.0           1.58217   -0.158097   1.87286    1.8869     
  0.0      0.0         0.0        0.0       :   0.308013  -0.75288    0.547033   1.77772    
  0.0      0.0         0.0        0.0          -2.32311    0.695899  -1.18943   -1.26152    
  0.0      0.0         0.0        0.0           0.173486   0.833139  -0.982545  -0.971247   
  0.0      0.0         0.0        0.0           1.01998    0.515218  -0.364214   0.905679   
  0.0      0.0         0.0        0.0          -1.31963    0.17844    1.27579   -0.654185   
  :                                                                                         
  0.0      0.0         0.0        0.0       :   1.436      1.47801   -1.08752   -0.000612769
  0.0      0.0         0.0        0.0          -0.427271   1.58678   -0.682428   1.30084    
  0.0      0.0         0.0        0.0           0.862027   0.499158   0.389469  -0.450842   
  0.0      0.0         0.0        0.0          -0.838898   0.498183   0.552315   0.830528   
  0.0      0.0         0.0        0.0           1.56324    0.529648  -2.11759    0.251053   
  0.0      0.0         0.0        0.0       :  -1.07418   -0.258497   1.93681   -1.49743    
  0.0      0.0         0.0        0.0           1.35022   -0.502995  -0.262886  -0.0517407  
  0.0      0.0         0.0        0.0           0.0        1.06416    1.58952   -0.679477   
  0.0      0.0         0.0        0.0           0.0        0.0        2.13802   -0.683735   
  0.0      0.0         0.0        0.0           0.0        0.0        0.0        0.459775   ,true)

julia> [@elapsed chold(apd) for k in 1:10]
10-element Float64 Array:
 0.000403166
 0.000166893
 0.000160933
 0.000161886
 0.000162125
 0.000156879
 0.000162125
 0.00016284 
 0.0101092  
 0.000149012

[staticfloat]

Ah, the macro expansion is what screws it up. I see. Are macros not
expanded until they are reached? I see that the line #17 higher up in the
stack is "correct", but once we hit the macro, things become difficult to
trace. Is there any way to make this more human-readable?

And yes, I realized the code wasn't doing what I wanted it do; it still
takes me a while to page-swap my brain from any other language to Julia. :)
-E

On Thu, Oct 4, 2012 at 12:04 PM, dmbates notifications@github.com wrote:

Remember that the problematic call occurs within an expansion of the
@Elapsed macro.

It appears that you are trying to save the results from chold in an array
but it would need to be an array of

julia> typeof(chold(apd))CholeskyDense{Float64}

to be able to do that. Also, the for k = reps is probably not what you
want because that will only do the calculation once with a value of k of
10. You probably want for k in 1:reps

Assuming that the calculation does not involve generating random numbers I
would do the timing in one loop and the comparison of the results to the
desired value externally.

julia> chold(apd)
CholeskyDense{Float64}(100x100 Float64 Array:
10.7632 -0.0556399 0.424147 -0.673008 : -0.328331 0.329383 0.561125 0.235107
0.0 10.358 -0.184153 1.12445 -0.211135 0.680397 -1.50525 -0.77154
0.0 0.0 10.8046 -1.69622 1.2341 1.38032 -0.607595 -0.922997
0.0 0.0 0.0 9.74493 -0.123586 -0.60327 0.745185 1.28362
0.0 0.0 0.0 0.0 1.58217 -0.158097 1.87286 1.8869
0.0 0.0 0.0 0.0 : 0.308013 -0.75288 0.547033 1.77772
0.0 0.0 0.0 0.0 -2.32311 0.695899 -1.18943 -1.26152
0.0 0.0 0.0 0.0 0.173486 0.833139 -0.982545 -0.971247
0.0 0.0 0.0 0.0 1.01998 0.515218 -0.364214 0.905679
0.0 0.0 0.0 0.0 -1.31963 0.17844 1.27579 -0.654185
:
0.0 0.0 0.0 0.0 : 1.436 1.47801 -1.08752 -0.000612769
0.0 0.0 0.0 0.0 -0.427271 1.58678 -0.682428 1.30084
0.0 0.0 0.0 0.0 0.862027 0.499158 0.389469 -0.450842
0.0 0.0 0.0 0.0 -0.838898 0.498183 0.552315 0.830528
0.0 0.0 0.0 0.0 1.56324 0.529648 -2.11759 0.251053
0.0 0.0 0.0 0.0 : -1.07418 -0.258497 1.93681 -1.49743
0.0 0.0 0.0 0.0 1.35022 -0.502995 -0.262886 -0.0517407
0.0 0.0 0.0 0.0 0.0 1.06416 1.58952 -0.679477
0.0 0.0 0.0 0.0 0.0 0.0 2.13802 -0.683735
0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.459775 ,true)

julia> [@Elapsed chold(apd) for k in 1:10]
10-element Float64 Array:
0.000403166
0.000166893
0.000160933
0.000161886
0.000162125
0.000156879
0.000162125
0.00016284
0.0101092
0.000149012

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/1334#issuecomment-9153139.

[vtjnash]

the reported line number is from the elapsed macro in base/util.jl

@JeffBezanson you've already done such a great job improving line number reporting, can it be fixed here too?

shorter code example:

julia> times = [@elapsed push!([1,],2.4) for k = 2]
InexactError()
 in push! at array.jl:649
 in push at deprecated.jl:8
 in anonymous at no file:49  #<-- the error is here

[mlubin]

Bump. Any chance this can be fixed for 0.3? JuMP's heavy use of macros leads to nearly useless error messages for users.

[staticfloat]

Is there any hope that improvements we make for precompiled code line numbers can improve this situation?

[timholy]

I don't have time to dig into this myself, but for anyone who is interested: a little poking makes me think there are two pieces to this problem, and that perhaps one might not be so hard. Check out the error that @vtjnash's example gives:

julia> times = [@elapsed push!([1,],2.4) for k = 2]
ERROR: InexactError()
 in push! at array.jl:484
 in anonymous at no file:56

The line number 56 comes from util.jl, where @elapsed is defined.

Now check this out:

julia> macroexpand(:(times = [@elapsed push!([1,],2.4) for k = 2]))
:(times = $(Expr(:comprehension, quote  # util.jl, line 55:
            local t0#24 = $(Base).time_ns() # line 56:
            local val#25 = push!([1],2.4) # line 57:
            $(Base)./($(Base).-($(Base).time_ns(),t0#24),1.0e9)
        end, :(k = 2))))

You can see that the generated expression actually has the information about util.jl in it, even though it never gets printed in the displayed backtrace. It seems possible that this aspect of the incorrect backtraces has to do more with how they are analyzed and printed, and not at a deeper level of the insertion of appropriate LineNumberNodes.

How the nofile gets in there, and whether one has the correct line number info for that too, is something I'm less sure about.

If I had time to tackle this, I'd start by looking at repl.jl/show_backtrace, and probably modify it to generate lots of debugging output as it's parsing the backtrace.

[timholy]

I dug into this a bit. To me it seems that Julia is doing everything it should in terms of documenting where code comes from in the generated expressions. Consider:

julia> macroexpand(:(function myfunc()
                  times = [@elapsed push!([1,],2.4) for k = 2]
                  times
              end))
:(function myfunc() # none, line 2:
        times = $(Expr(:comprehension, :(begin  # util.jl, line 51:
        local #56#t0 = Base.time_ns() # line 52:
        local #57#val = push!([1],2.4) # line 53:
        Base./(Base.-(Base.time_ns(),#56#t0),1.0e9)
    end), :(k = 2))) # line 3:
        times
    end)

It took me a little to remember/understand this, but the # none, line 2: refers to the fact that the next line corresponds to line 2 of none. Likewise, the # line 3: behaves similarly. So all the information is there.

Here's a longer block:

julia> macroexpand(:(function myfunc(t)
           times = [@elapsed begin
               y = t+2
               push!([1],2.4)
           end for k=2]
           times
       end))
:(function myfunc(t) # none, line 2:
        times = $(Expr(:comprehension, :(begin  # util.jl, line 51:
        local #58#t0 = Base.time_ns() # line 52:
        local #59#val = begin  # none, line 3:
                    y = t + 2 # line 4:
                    push!([1],2.4)
                end # line 53:
        Base./(Base.-(Base.time_ns(),#58#t0),1.0e9)
    end), :(k = 2))) # line 6:
        times
    end)

Again, it's clearly documenting where code comes from.

So now let's see if this information gets recovered from the backtraces. Using the teh/backtrace branch (#6633) and inserting a couple of println(io, ...) statements into replutil.jl/show_backtrace, I get this:

julia> times = [@elapsed push!([1,],2.4) for k = 2]
ERROR: InexactError()Ptr{Void} @0x00007f5b45c09945
fname: rec_backtrace, file: /home/tim/src/julia/usr/bin/../lib/libjulia.so, line: 37, fromC: true
Ptr{Void} @0x00007f5b45c09dfd
fname: jl_throw, file: /home/tim/src/julia/usr/bin/../lib/libjulia.so, line: 29, fromC: true
Ptr{Void} @0x00007f5b45c09f29
fname: ???, file: /home/tim/src/julia/usr/bin/../lib/libjulia.so, line: 0, fromC: true
Ptr{Void} @0x00007f5b46ba09f5
fname: push!, file: array.jl, line: 442, fromC: false
Ptr{Void} @0x00007f5b46ba0829
fname: anonymous, file: no file, line: 52, fromC: false

 in push! at array.jl:442Ptr{Void} @0x00007f5b45c11c7c
fname: ???, file: /home/tim/src/julia/usr/bin/../lib/libjulia.so, line: 0, fromC: true
Ptr{Void} @0x00007f5b45bc871c
fname: jl_f_top_eval, file: /home/tim/src/julia/usr/bin/../lib/libjulia.so, line: 508, fromC: true
Ptr{Void} @0x00007f5b46ba0391
fname: eval_user_input, file: REPL.jl, line: 51, fromC: false

 in anonymous at no file:52

You can see that there's just not very much useful information in this backtrace. This probably can't be fixed until we switch to MCJIT.

[vtjnash]

I think the information gets actively stripped later on, since we assume the lines in an emitted function all came from the same function/file while emitting the line info, and again later while matching instructions to their source line

[timholy]

Ah! You are right. Looking at code_lowered on myfunc(t) already reveals what could be a key problem. Here's an excerpt:

    #s46 = top(next)(#s48,#s47)
    k = top(tupleref)(#s46,1)
    #s47 = top(tupleref)(#s46,2) # util.jl, line 51:
    #56#t0 = top(getfield)(Base,:time_ns)() # line 52: # none, line 3:
    y = t + 2 # line 4:
    #57#val = push!(vcat(1),2.4) # line 53:
    #s50 = top(getfield)(Base,:/)(top(getfield)(Base,:-)(top(getfield)(Base,:time_ns)(),#56#t0),1.0e9)
    $(Expr(:type_goto, 0, :#s50))

You can see that after the switch to none, it forgets that we've gone back to util.jl. (Later in the output, it also forgets that it's gone back to none.) It seems that one would could fix this by maintaining a stack of file/function names and pop it whenever reaching the end of a block that started with new file/function info.

Am I right in remembering/guessing lowering is performed in the Scheme code? If it's there, I fear it's a bit beyond me to try to fix it (at least, not without a serious investment).

code_typed does not appear to introduce any new problems.

Is there any chance this is related to our truncated backtraces (#3469)? In that issue, I noted there seems to be some association with inlining, and the common feature with the issue here is that code is coming from "elsewhere." That said, I wasn't able to find any evidence for this view in code_typed---it looks "really inlined" from what I can tell, so I'm a bit skeptical that the two issues are actually related.

[vtjnash]

If you look at jl_getFunctionInfo, it should be more clear where the information is getting lost.

I don't think this is related to truncated backtraces

[timholy]

Thanks, that was very informative. I still have only a vague understanding of what's going on, but IIUC we're not relying on the fact that a FuncInfo has only a single name/filename. We're getting funcname/filename info from the context stored in lines, and it looks like each LineStart object has its own context. So, doesn't that mean we could be providing full funcname/filename/linenum info for each line of code?