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

inlined code line numbers need work #13725

Closed
JeffBezanson opened this issue Oct 22, 2015 · 8 comments
Closed

inlined code line numbers need work #13725

JeffBezanson opened this issue Oct 22, 2015 · 8 comments
Labels
bug Indicates an unexpected problem or unintended behavior error handling Handling of exceptions by Julia or the user regression Regression in behavior compared to a previous version

Comments

@JeffBezanson
Copy link
Member

Example (encountered while working on #13547):

julia> Array{Type{Int64}}([Float32])
ERROR: TypeError: copy!: in typeassert, expected Type{Int64}, got Type{Float32}
 [inlined code] from operators.jl:313
 in copy! at abstractarray.jl:301
 [inlined code] from abstractarray.jl:112
 in call at essentials.jl:116

The line abstractarray.jl:301 is correct, but the other 3 line numbers are completely wrong. I believe the fix is for the inliner to insert some kind of location "pop" operation. For example we have

julia> @code_typed Array{Type{Int64}}([Float32])
1-element Array{Any,1}:
 :($(Expr(:lambda, Any[symbol("#s1"),:arg], Any[Any[Any[symbol("#s1"),Type{Array{Type{Int64},N}},0],Any[:arg,Array{DataType,1},0]],Any[],Any[Int64,Int64,Array{Type{Int64},1}],Any[:T]], :(begin  # essentials.jl, line 58: # array.jl, line 229: # array.jl, line 230: # array.jl, line 158: # array.jl, line 48:
        GenSym(0) = (Base.arraysize)(arg::Array{DataType,1},1)::Int64 # essentials.jl, line 204: # essentials.jl, line 194: # essentials.jl, line 114: # essentials.jl, line 61: # essentials.jl, line 116:
...

We see several line nodes piled up, without knowing their nesting structure.

@JeffBezanson JeffBezanson added error handling Handling of exceptions by Julia or the user bug Indicates an unexpected problem or unintended behavior labels Oct 22, 2015
@yuyichao
Copy link
Contributor

Ref my other example in #13553 (comment)

@ihnorton
Copy link
Member

We would need to handle line nodes spliced in by macros too, unless these enter/pop things are labeled. Ref: #1334 (comment)

@JeffBezanson
Copy link
Member Author

I think we might have to put back the line number filter in inlining. I'm seeing really extreme regressions in line number info; for example looking at #13350 I get the following profile full of random locations:

1    ...ff/src/api/gradient.jl; _calc_gradient; line: 86
 1 ...r/julia/perf_parens.jl; anonymous; line: 124
  1 ...rdDiff/src/Partials.jl; sumA_fast; line: 81
   1 .../src/GradientNumber.jl; mygetindex_fast; line: 12
1826 REPL.jl; anonymous; line: 92
 1826 REPL.jl; eval_user_input; line: 3
  1826 profile.jl; anonymous; line: 16
   1826 essentials.jl; g; line: 116
    1825 .../src/api/gradient.jl; _calc_gradient; line: 86
     1825 ...ulia/perf_parens.jl; anonymous; line: 124
      1807 ...iff/src/Partials.jl; sumA_fast; line: 81
       654 ...c/GradientNumber.jl; mygetindex_fast; line: 12
        2 ./float.jl; +; line: 0
        3 ./float.jl; +; line: 204
        1 ./float.jl; -; line: 0
        1 ./float.jl; -; line: 206
        7 ...iff/src/Partials.jl; call; line: 81
       1   ...iff/src/Partials.jl; +; line: 15
       1   ...iff/src/Partials.jl; +; line: 81
       22  ...iff/src/Partials.jl; mygetindex_fast; line: 81
       2   ...ulia/perf_parens.jl; mygetindex_fast; line: 48
       157 ...ulia/perf_parens.jl; mygetindex_fast; line: 81
        2 ...c/GradientNumber.jl; *; line: 14
        1 ...iff/src/Partials.jl; *; line: 81
        1 ...iff/src/Partials.jl; +; line: 15
        4 ...iff/src/Partials.jl; +; line: 81
        6 float.jl; *; line: 204
        2 float.jl; +; line: 204
       470 ...ulia/perf_parens.jl; mygetindex_fast; line: 87
        5  ...c/GradientNumber.jl; *; line: 14
        2  ...iff/src/Partials.jl; *; line: 81
        21 ...iff/src/Partials.jl; -; line: 81
        23 ...iff/src/Partials.jl; /; line: 81
        15 float.jl; *; line: 204
        2  float.jl; -; line: 201
        50 float.jl; /; line: 210
       4   array.jl; mygetindex_fast; line: 48
        1 ./float.jl; trunc; line: 0
        2 ./float.jl; trunc; line: 242
       1   int.jl; mygetindex_fast; line: 18
       1   operators.jl; mygetindex_fast; line: 48
       463 operators.jl; mygetindex_fast; line: 322
        68 ...iff/src/Partials.jl; *; line: 81
        3  ...iff/src/Partials.jl; +; line: 15
        4  ...iff/src/Partials.jl; +; line: 81
        5  float.jl; *; line: 208
        1  float.jl; +; line: 204
      1    bool.jl; sumA_fast; line: 16
      17   int.jl; sumA_fast; line: 8

Putting back the line number filter, I get the following accurate and useful output:

1821 REPL.jl; anonymous; line: 92
 1821 REPL.jl; eval_user_input; line: 62
  1821 profile.jl; anonymous; line: 16
   1821 ...f/src/api/gradient.jl; g; line: 54
    1821 .../src/api/gradient.jl; _calc_gradient; line: 86
     1821 ...ulia/perf_parens.jl; anonymous; line: 124
      1    ...ulia/perf_parens.jl; mygetindex_fast; line: 84
      13   ...ulia/perf_parens.jl; sumA_fast; line: 104
      1807 ...ulia/perf_parens.jl; sumA_fast; line: 105
       3   ...c/GradientNumber.jl; +; line: 71
       9   ...ulia/perf_parens.jl; mygetindex_fast; line: 48
       2   ...ulia/perf_parens.jl; mygetindex_fast; line: 50
        1 ./float.jl; trunc; line: 0
        1 ./float.jl; trunc; line: 363
       7   ...ulia/perf_parens.jl; mygetindex_fast; line: 51
       8   ...ulia/perf_parens.jl; mygetindex_fast; line: 58
       1   ...ulia/perf_parens.jl; mygetindex_fast; line: 60
       234 ...ulia/perf_parens.jl; mygetindex_fast; line: 66
        4  .../src/ForwardDiff.jl; promote_eltypeof; line: 71
        3  ...c/GradientNumber.jl; *; line: 86
        6  ...c/GradientNumber.jl; *; line: 87
        9  ...c/GradientNumber.jl; /; line: 109
        14 ...c/GradientNumber.jl; /; line: 110
       65  ...ulia/perf_parens.jl; mygetindex_fast; line: 67
        1  ...c/GradientNumber.jl; *; line: 86
        10 ...c/GradientNumber.jl; -; line: 78
       249 ...ulia/perf_parens.jl; mygetindex_fast; line: 68
        1  ./float.jl; +; line: 204
        4  ...c/GradientNumber.jl; *; line: 87
        3  ...c/GradientNumber.jl; /; line: 109
        15 ...c/GradientNumber.jl; /; line: 110
        4  ...c/GradientNumber.jl; call; line: 2
       212 ...ulia/perf_parens.jl; mygetindex_fast; line: 71
        1 ...c/GradientNumber.jl; *; line: 86
        1 ...c/GradientNumber.jl; *; line: 87
        6 ...c/GradientNumber.jl; /; line: 109
        8 ...c/GradientNumber.jl; /; line: 110
       78  ...ulia/perf_parens.jl; mygetindex_fast; line: 72
        12 ...c/GradientNumber.jl; -; line: 78
       232 ...ulia/perf_parens.jl; mygetindex_fast; line: 73
        1 .../src/ForwardDiff.jl; promote_eltypeof; line: 71
        2 ...c/GradientNumber.jl; *; line: 86
        5 ...c/GradientNumber.jl; *; line: 87
        5 ...c/GradientNumber.jl; /; line: 109
        9 ...c/GradientNumber.jl; /; line: 110
        3 ...c/GradientNumber.jl; call; line: 2
       193 ...ulia/perf_parens.jl; mygetindex_fast; line: 78
        27 ...c/GradientNumber.jl; *; line: 90
        8  ...c/GradientNumber.jl; +; line: 71
       143 ...ulia/perf_parens.jl; mygetindex_fast; line: 79
        26 ...c/GradientNumber.jl; *; line: 90
        1  ...c/GradientNumber.jl; +; line: 71
       156 ...ulia/perf_parens.jl; mygetindex_fast; line: 80
        21 ...c/GradientNumber.jl; *; line: 90
        4  ...c/GradientNumber.jl; +; line: 71
       182 ...ulia/perf_parens.jl; mygetindex_fast; line: 81
        6  ...c/GradientNumber.jl; *; line: 86
        14 ...c/GradientNumber.jl; *; line: 87
        6  ...c/GradientNumber.jl; +; line: 71
       1   ...ulia/perf_parens.jl; mygetindex_fast; line: 84

@JeffBezanson JeffBezanson added regression Regression in behavior compared to a previous version backport pending 0.4 and removed backport pending 0.4 labels Oct 22, 2015
@JeffBezanson
Copy link
Member Author

Ok, I think this particular issue is not present in 0.4 thankfully.

@tkelman
Copy link
Contributor

tkelman commented Oct 26, 2015

though it likely would if #13491 were backported?

@JeffBezanson
Copy link
Member Author

Correct, especially commit a33cd07

JeffBezanson added a commit that referenced this issue Oct 26, 2015
#13725

Single expression functions tend to get inlined into the middle of an
expression, so their line numbers should not be inserted into the outer function
(the number applies to only part of an expression, not the whole statement).

This also significantly reduces sysimg size.
bjarthur pushed a commit to bjarthur/julia that referenced this issue Oct 27, 2015
JuliaLang#13725

Single expression functions tend to get inlined into the middle of an
expression, so their line numbers should not be inserted into the outer function
(the number applies to only part of an expression, not the whole statement).

This also significantly reduces sysimg size.
@andreasnoack
Copy link
Member

It might be a different line number issue, but I'll try here first. It used to be the case (0.3) that the backtrace gave the right line number when a test in a loop failed. E.g. with a test file testfile.jl:

using Base.Test

for i = 1:4

    @test 1 == 2

end

the result on 0.3 is

               _
   _       _ _(_)_     |  A fresh approach to technical computing
  (_)     | (_) (_)    |  Documentation: http://docs.julialang.org
   _ _   _| |_  __ _   |  Type "help()" for help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 0.3.12-pre+7 (2015-10-20 12:08 UTC)
 _/ |\__'_|_|_|\__'_|  |  Commit fa31586* (10 days old release-0.3)
|__/                   |  x86_64-apple-darwin15.0.0

julia> include("/Users/andreasnoack/Desktop/testfile.jl")
ERROR: test failed: 1 == 2
 in error at error.jl:21
 in default_handler at test.jl:19
 in do_test at test.jl:39
 in anonymous at no file:5
 in include at ./boot.jl:245
 in include_from_node1 at ./loading.jl:128
while loading /Users/andreasnoack/Desktop/testfile.jl, in expression starting on line 3

where the line in anonymous at no file:5 has the right line number. On latest 0.4, I get

               _
   _       _ _(_)_     |  A fresh approach to technical computing
  (_)     | (_) (_)    |  Documentation: http://docs.julialang.org
   _ _   _| |_  __ _   |  Type "?help" for help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 0.4.1-pre+21 (2015-10-29 07:02 UTC)
 _/ |\__'_|_|_|\__'_|  |  Commit be50c8d* (1 day old release-0.4)
|__/                   |  x86_64-apple-darwin15.0.0

julia> include("/Users/andreasnoack/Desktop/testfile.jl")
ERROR: LoadError: test failed: 1 == 2
 in expression: 1 == 2
 in error at ./error.jl:21
 in default_handler at test.jl:30
 in do_test at test.jl:53
 [inlined code] from /Users/andreasnoack/Desktop/testfile.jl:5
 in anonymous at no file:0
 in include at ./boot.jl:261
 in include_from_node1 at ./loading.jl:304
while loading /Users/andreasnoack/Desktop/testfile.jl, in expression starting on line 3

Update: I still think there is an issue, but the example was bad because the right line number is in the output here. I tried to make a small reproducible example, but it didn't capture the issue. I'll try to make a new example.

@vtjnash
Copy link
Member

vtjnash commented Jul 20, 2016

fixed by #14949

@vtjnash vtjnash closed this as completed Jul 20, 2016
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Indicates an unexpected problem or unintended behavior error handling Handling of exceptions by Julia or the user regression Regression in behavior compared to a previous version
Projects
None yet
Development

No branches or pull requests

6 participants