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 [email protected] 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?

[mlubin]

I guess my plea to fix this in 0.3 didn't go through, trying again for 0.4 :)

[timholy]

@mlubin, while I've dug into this a bit myself in the past, the whole Array nirvana thing (along with miscellaneous other contributions) is already more than maxing out the time I have available for "core julia" stuff. Care to dive in and try to fix this yourself?

[IainNZ]

@timholy any ideas where the general area of the problem is?

[timholy]

The tests above contain the entire sum of my knowledge on this issue.

[SimonDanisch]

I didn't want to open a new issue, but I have the feeling, that line numbers got worse lately.
Most recent example:
I was debugging OpenCL code, and I didn't get any decent line numbers at all, even though that there where (from what I can see) no funky constructs.
The error:

ERROR: InexactError()
 in convert at pointer.jl:7 (repeats 2 times)
while loading C:\Users\Sim\Desktop\Julia\InteropContext.jl, in expression starting on line 21

There is a lot missing here!
It took me quite some time to figure out the correct stack trace which was something like this:

 in convert at pointer.jl:7 #didn't show up the time I got decent stack traces, though
OpenCL\src\types.jl on line 143
OpenCL\src\context.jl on line 176
OpenCL\src\context.jl on line 90
InteropContext.jl, in expression starting on line 17
C:\Users\Sim\Desktop\Julia\InteropContext.jl, in expression starting on line 21

"minimal" example:
https://gist.github.com/c5bc1f0422ba64fd46c5.git

I don't know what's going on here... I had a version, where it gave me the correct line numbers, but I can't reproduce it right now.

Julia Version 0.4.0-dev+2523
Commit e26eb53* (2015-01-06 05:57 UTC)
Platform Info:
  System: Windows (x86_64-w64-mingw32)
  CPU: Intel(R) Core(TM) i5-4200U CPU @ 1.60GHz
  WORD_SIZE: 64
  BLAS: libopenblas (USE64BITINT DYNAMIC_ARCH NO_AFFINITY Haswell)
  LAPACK: libopenblas
  LIBM: libopenlibm
  LLVM: libLLVM-3.3

Best,
Simon

[tkelman]

If you can come up with an example that doesn't use code from a package, it'll be much easier to try bisecting this.

[SimonDanisch]

Yes I know, but this requirement hold me back from posting any bug report
for the last months.
It has been nearly impossible for me to reproduce this with a better
minimal example, and at some point I gave up trying, as it was too time
consuming.

2015-01-14 12:36 GMT+01:00 Tony Kelman [email protected]:

If you can come up with an example that doesn't use code from a package,
it'll be much easier to try bisecting this.

—
Reply to this email directly or view it on GitHub
#1334 (comment).

[SimonDanisch]

So I thought this is better than nothing. I must admit I haven't tried it
this time, as the last time was very frustrating. I tried every combination
of nested function calls, includes, separate modules, nested separated
modules, macros in the surrounding code, etc... I simply don't know how to
go about this, other than spear fishing in the dark ;)

2015-01-14 13:29 GMT+01:00 Simon Danisch [email protected]:

Yes I know, but this requirement hold me back from posting any bug report
for the last months.
It has been nearly impossible for me to reproduce this with a better
minimal example, and at some point I gave up trying, as it was too time
consuming.

2015-01-14 12:36 GMT+01:00 Tony Kelman [email protected]:

If you can come up with an example that doesn't use code from a package,
it'll be much easier to try bisecting this.

—
Reply to this email directly or view it on GitHub
#1334 (comment).

[tkelman]

Okay, okay, I'll fiddle with things and try to see if I can find any commits since the 0.4-dev branch that give better backtraces there. You could try with older nightlies from http://s3.amazonaws.com/julianightlies, but it looks like the oldest ones still there are about a month old.

I do think your specific problem should probably be a separate issue though, since it's likely platform-dependent.

[ihnorton]

@JeffBezanson I guess I'll go find my threadbare Scheme hat.

@ScottPJones the patch probably applies cleanly, but I wouldn't use it yet. As per above, it relies on a faulty assumption. (also makes the REPL noisy, hard-codes an important test, probably leaks, etc.).

[ihnorton]

Another example from julia-users: https://groups.google.com/d/msg/julia-users/GXHm6sqR3YI/oF990MaNAQAJ

[ihnorton]

I could use some help with lowering these poploc nodes. Some attempts and thoughts so far:

• I tried adding a (meta poploc) node at the end of every block that introduces a line-number-filename-node, and fiddled with block handling in to-lff to make it consider the next-to-last node as tail if the true tail is a meta node. This is really janky because (among other things) return is not the last statement in a given block, thus it breaks tail handling in other places.
• insert the meta node at macro invocation: haven't tried this yet, but I think it would have the same problem of introducing non-return tail nodes. Also not quite sure how to handle multiple line-number-filename nodes in the same expanded form (just ... count them?)
• The cop-out solution: attach the file to every single line node. Would this be too expensive?

[ihnorton]

@JeffBezanson, if you have any time to share thoughts on the pop_location meta nodes idea, that would be very helpful. @jakebolewski and @carnaval made a strong argument that this can't be addressed in general (to handle the corner cases of code splicing) without a significant reworking of the parsing and lowering code to trace source origin within each expression. Some interesting tidbits along these lines: Debugging Layers (in Converge); Racket's syntax object / srcloc design.

However, I am hopeful that there is some room for improvement in the current scheme:

• as above, attach the file to every single line node. This costs one additional symbol per line node, and probably a few lookups... That seems fairly insignificant overall, but I'll try to implement it and benchmark.
• another idea: strip all line nodes when splicing macros and inlining code. This would lose any chance of getting definition site, but should fix function-level line numbers. Seems like a good trade to me. An advantage of this idea is that it would have zero overhead (relative to the current situation) and may not require any codegen or debuginfo changes.

[ihnorton]

Related to the second idea: strip all non-filename line nodes when splicing code. Then we could make the original assumption that unattached line nodes are only at top-level scope, and still trace to the definition location.

(downside: consecutive non-toplevel filename line nodes could be ambiguous -- nested vs. spliced -- but that would not be terrible because the toplevel line would always be correct)

[timholy]

@ihnorton, you should do the honors here.

[timholy]

OK to close this?

[ihnorton]

Ok 😄

[KristofferC]

New backtraces are really awesome btw!