Wrong line number #21

aviatesk · 2020-02-17T02:48:29Z

(original issue posted at JunoLab/Juno.jl#481)

MRE:

using LinearAlgebra

function bar(x)
    if x < 0.5
        return round(Int64, exp(x))
    else
        exp(x)
    end
end

function foo(n)
    for i = 1:n
        for j = 1:10000
            bar(rand())
        end
    end
end

Profile.@profile foo(10000)
node = FlameGraphs.flamegraph(Profile.fetch())
FlameGraphs.canfind("$(@__FILE__):0", node) #=> true

Within this example, line numbers inside bar seem to be incorrectly recorded.

Visual image of this problem:

The text was updated successfully, but these errors were encountered:

aviatesk · 2020-02-17T02:58:44Z

nvm, FlameGraph doesn't do anything wrong:
Profile module seems to count at file:0 for this case:

io = IOBuffer()
Profile.print(io, Profile.fetch())
print(String(take!(io)))
Overhead ╎ [+additional indent] Count File:Line; Function
=========================================================
   ╎3463 @Base\task.jl:358; (::Atom.var"#19#21"{Array{Any,1...
   ╎ 3463 @Atom\src\comm.jl:166; handlemsg(::Dict{String,Any}, :...
   ╎  3463 @Atom\src\eval.jl:62; (::Atom.var"#178#179")(::Dict{S...
   ╎   3463 @Atom\src\eval.jl:67; eval(::String, ::Int64, ::Stri...
   ╎    3463 ...tEPc\src\dynamic.jl:24; macro expansion
   ╎     3463 @Atom\src\eval.jl:71; macro expansion
   ╎    ╎ 3463 @Atom\src\repl.jl:112; hideprompt(::Atom.var"#180#1...
   ╎    ╎  3463 @Atom\src\eval.jl:72; #180
   ╎    ╎   3463 @Base\logging.jl:505; with_logger
   ╎    ╎    3463 @Base\logging.jl:398; with_logstate(::Atom.var"#...
   ╎    ╎     3463 @Atom\src\eval.jl:73; #181
   ╎    ╎    ╎ 3463 @Atom\src\eval.jl:9; withpath(::Function, ::Str...
   ╎    ╎    ╎  3463 ...ls\src\utils.jl:30; withpath(::Atom.var"#182#...
   ╎    ╎    ╎   3463 @Atom\src\eval.jl:74; (::Atom.var"#182#186"{St...
   ╎    ╎    ╎    3463 ...ols\src\eval.jl:30; include_string(::Module,...
   ╎    ╎    ╎     3463 @Base\loading.jl:1095; include_string
   ╎    ╎    ╎    ╎ 3463 @Base\loading.jl:1087; include_string(::Func...
   ╎    ╎    ╎    ╎  3463 ...1910bd56dd522:14; foo(::Int64)
   ╎    ╎    ╎    ╎   25   @Base\range.jl:598; iterate
 25╎    ╎    ╎    ╎    25   ...promotion.jl:398; ==
 34╎    ╎    ╎    ╎   2708 ...1910bd56dd522:0; bar # here appears up a bit weird
 30╎    ╎    ╎    ╎    30   ...ecial\exp.jl:0; exp(::Float64)
 85╎    ╎    ╎    ╎    135  ...ecial\exp.jl:75; exp(::Float64)
   ╎    ╎    ╎    ╎     37   @Base\float.jl:869; reinterpret
 37╎    ╎    ╎    ╎    ╎ 37   ...sentials.jl:414; reinterpret
 13╎    ╎    ╎    ╎     13   @Base\int.jl:277; &
   ╎    ╎    ╎    ╎    29   ...ecial\exp.jl:79; exp(::Float64)
   ╎    ╎    ╎    ╎     29   ...operators.jl:294; >
 29╎    ╎    ╎    ╎    ╎ 29   @Base\int.jl:409; <
 59╎    ╎    ╎    ╎    59   ...ecial\exp.jl:91; exp(::Float64)
   ╎    ╎    ╎    ╎    2    ...ecial\exp.jl:95; exp(::Float64)
   ╎    ╎    ╎    ╎     2    ...operators.jl:294; >
  2╎    ╎    ╎    ╎    ╎ 2    @Base\int.jl:409; <
   ╎    ╎    ╎    ╎    15   ...ecial\exp.jl:97; exp(::Float64)
 15╎    ╎    ╎    ╎     15   @Base\int.jl:409; <
 98╎    ╎    ╎    ╎    98   ...ecial\exp.jl:98; exp(::Float64)
   ╎    ╎    ╎    ╎    29   ...ecial\exp.jl:114; exp(::Float64)
 29╎    ╎    ╎    ╎     29   @Base\float.jl:403; -
   ╎    ╎    ╎    ╎    101  ...ecial\exp.jl:115; exp(::Float64)
101╎    ╎    ╎    ╎     101  @Base\float.jl:405; *
   ╎    ╎    ╎    ╎    359  ...ecial\exp.jl:116; exp(::Float64)
 89╎    ╎    ╎    ╎     89   @Base\float.jl:405; *
 75╎    ╎    ╎    ╎     75   @Base\float.jl:403; -
   ╎    ╎    ╎    ╎     195  ...ecial\exp.jl:52; exp_kernel
   ╎    ╎    ╎    ╎    ╎ 195  @Base\math.jl:123; evalpoly
   ╎    ╎    ╎    ╎    ╎  195  @Base\math.jl:123; macro expansion
195╎    ╎    ╎    ╎    ╎   195  @Base\float.jl:410; muladd
   ╎    ╎    ╎    ╎    753  ...ecial\exp.jl:117; exp(::Float64)
197╎    ╎    ╎    ╎     197  @Base\float.jl:405; *
551╎    ╎    ╎    ╎     551  @Base\float.jl:403; -
  5╎    ╎    ╎    ╎     5    @Base\float.jl:407; /
   ╎    ╎    ╎    ╎    100  ...ecial\exp.jl:119; exp(::Float64)
   ╎    ╎    ╎    ╎     100  ...operators.jl:294; >
100╎    ╎    ╎    ╎    ╎ 100  @Base\int.jl:49; <
   ╎    ╎    ╎    ╎    8    ...ecial\exp.jl:121; exp(::Float64)
  8╎    ╎    ╎    ╎     8    ...promotion.jl:398; ==
   ╎    ╎    ╎    ╎    26   ...ecial\exp.jl:122; exp(::Float64)
   ╎    ╎    ╎    ╎     26   @Base\int.jl:432; <<
 26╎    ╎    ╎    ╎    ╎ 26   @Base\int.jl:425; <<
 65╎    ╎    ╎    ╎    85   ...ecial\exp.jl:123; exp(::Float64)
 20╎    ╎    ╎    ╎     20   @Base\float.jl:405; *
  1╎    ╎    ╎    ╎    118  ...ecial\exp.jl:129; exp(::Float64)
117╎    ╎    ╎    ╎     117  @Base\int.jl:409; <
   ╎    ╎    ╎    ╎    55   ...ecial\exp.jl:134; exp(::Float64)
 55╎    ╎    ╎    ╎     55   @Base\float.jl:405; *
   ╎    ╎    ╎    ╎    267  ...ecial\exp.jl:135; exp(::Float64)
 42╎    ╎    ╎    ╎     42   @Base\float.jl:405; *
 49╎    ╎    ╎    ╎     49   @Base\float.jl:403; -
   ╎    ╎    ╎    ╎     176  ...ecial\exp.jl:52; exp_kernel
   ╎    ╎    ╎    ╎    ╎ 176  @Base\math.jl:123; evalpoly
   ╎    ╎    ╎    ╎    ╎  176  @Base\math.jl:123; macro expansion
176╎    ╎    ╎    ╎    ╎   176  @Base\float.jl:410; muladd
 60╎    ╎    ╎    ╎    405  ...ecial\exp.jl:136; exp(::Float64)
 98╎    ╎    ╎    ╎     98   @Base\float.jl:405; *
240╎    ╎    ╎    ╎     240  @Base\float.jl:403; -
  7╎    ╎    ╎    ╎     7    @Base\float.jl:407; /
  6╎    ╎    ╎    ╎   6    ...1910bd56dd522:4; bar
   ╎    ╎    ╎    ╎   222  ...1910bd56dd522:5; bar
   ╎    ╎    ╎    ╎    222  @Base\float.jl:367; round
 12╎    ╎    ╎    ╎     12   @Base\float.jl:376; round
 53╎    ╎    ╎    ╎     210  @Base\float.jl:700; trunc
157╎    ╎    ╎    ╎    ╎ 157  @Base\float.jl:460; <=
   ╎    ╎    ╎    ╎   502  ...src\Random.jl:256; rand
  9╎    ╎    ╎    ╎    255  ...\src\RNGs.jl:297; default_rng
110╎    ╎    ╎    ╎     119  ...\src\RNGs.jl:299; default_rng(::Int64)
  9╎    ╎    ╎    ╎    ╎ 9    @Base\int.jl:49; <
   ╎    ╎    ╎    ╎     47   ...\src\RNGs.jl:300; default_rng(::Int64)
 47╎    ╎    ╎    ╎    ╎ 47   @Base\array.jl:229; isassigned
 80╎    ╎    ╎    ╎     80   ...\src\RNGs.jl:306; default_rng(::Int64)
   ╎    ╎    ╎    ╎    247  ...rc\Random.jl:256; rand
   ╎    ╎    ╎    ╎     247  ...eneration.jl:35; rand
 37╎    ╎    ╎    ╎    ╎ 37   @Base\float.jl:403; -
   ╎    ╎    ╎    ╎    ╎ 210  ...c\Random.jl:253; rand
   ╎    ╎    ╎    ╎    ╎  160  ...src\RNGs.jl:386; rand
   ╎    ╎    ╎    ╎    ╎   160  ...src\RNGs.jl:190; reserve_1
   ╎    ╎    ╎    ╎    ╎    157  ...rc\RNGs.jl:186; gen_rand
 11╎    ╎    ╎    ╎    ╎     14   ...c\DSFMT.jl:84; dsfmt_fill_array_...
   ╎    ╎    ╎    ╎    ╎    ╎ 1    @Base\int.jl:414; ==
  1╎    ╎    ╎    ╎    ╎    ╎  1    ...motion.jl:398; ==
   ╎    ╎    ╎    ╎    ╎    ╎ 2    @Base\int.jl:174; rem
  2╎    ╎    ╎    ╎    ╎    ╎  2    @Base\int.jl:233; rem
141╎    ╎    ╎    ╎    ╎     143  ...c\DSFMT.jl:86; dsfmt_fill_array_...
   ╎    ╎    ╎    ╎    ╎    ╎ 1    ...pointer.jl:66; unsafe_convert
  1╎    ╎    ╎    ╎    ╎    ╎  1    ...ointer.jl:65; unsafe_convert
   ╎    ╎    ╎    ╎    ╎    3    ...rc\RNGs.jl:180; mt_empty
  1╎    ╎    ╎    ╎    ╎     1    @Base\Base.jl:33; getproperty
  2╎    ╎    ╎    ╎    ╎     2    ...omotion.jl:398; ==
   ╎    ╎    ╎    ╎    ╎  50   ...src\RNGs.jl:387; rand
   ╎    ╎    ╎    ╎    ╎   50   ...src\RNGs.jl:362; rand_inbounds
   ╎    ╎    ╎    ╎    ╎    50   ...rc\RNGs.jl:183; mt_pop!
 45╎    ╎    ╎    ╎    ╎     45   @Base\Base.jl:33; getproperty
  2╎    ╎    ╎    ╎    ╎     2    ...e\array.jl:786; getindex
  3╎    ╎    ╎    ╎    ╎     3    @Base\int.jl:53; +
Total snapshots: 3464

timholy · 2020-04-16T14:08:07Z

Might be fixed in Julia 1.5? See JuliaLang/julia#35138.

aviatesk · 2020-04-17T08:16:55Z

Seems not. I build Julia on the current master but still see the result below, where the problematic line still remains.

julia> include("julia/JunoLab/profile.jl")
julia> foo(100); using Profile; Profile.@profile foo(10000);
julia> io = IOBuffer(); Profile.print(io, Profile.fetch()); print(String(take!(io)))
Overhead ╎ [+additional indent] Count File:Line; Function
=========================================================
   ╎1209 @Base/client.jl:491; _start()
   ╎ 1209 @Base/client.jl:306; exec_options(::Base.JLOptions)
   ╎  1209 @Base/client.jl:368; run_main_repl(::Bool, ::Bool, ...
   ╎   1209 @Base/essentials.jl:709; invokelatest
   ╎    1209 @Base/essentials.jl:710; #invokelatest#1
   ╎     1209 @Base/client.jl:384; (::Base.var"#803#805"{Bool,B...
   ╎    ╎ 1209 @REPL/src/REPL.jl:286; run_repl(::AbstractREPL, ::Any)
   ╎    ╎  1209 @REPL/src/REPL.jl:290; run_repl(::AbstractREPL, ::...
   ╎    ╎   1209 @REPL/src/REPL.jl:178; start_repl_backend(::REPL.R...
   ╎    ╎    1209 @REPL/src/REPL.jl:193; repl_backend_loop(::REPL.R...
   ╎    ╎     1209 @REPL/src/REPL.jl:132; eval_user_input(::Any, ::...
  3╎    ╎    ╎ 1209 @Base/boot.jl:331; eval(::Module, ::Any)
   ╎    ╎    ╎  1206 ...oLab/profile.jl:14; foo(::Int64)
   ╎    ╎    ╎   18   @Base/range.jl:621; iterate
 18╎    ╎    ╎    18   ...e/promotion.jl:398; ==
   ╎    ╎    ╎   889  ...oLab/profile.jl:0; bar # here is the problematic line
 34╎    ╎    ╎    34   ...special/exp.jl:0; exp(::Float64)
   ╎    ╎    ╎    19   ...special/exp.jl:75; exp(::Float64)
   ╎    ╎    ╎     12   @Base/float.jl:869; reinterpret
...

timholy · 2020-04-17T09:18:24Z

Confirmed. This seems like a failure of the unwinder. We've seen these for a long time but this is a particularly simple example. Looks like it's already been reported in Julia (JuliaLang/julia#34811), so there's not a lot more to do here. But thanks for trying latest master!

aviatesk · 2020-04-17T09:29:58Z

No worries, I was just about to build Julia anyway ;)

aviatesk mentioned this issue Feb 17, 2020

Wrong line number in the profiler JunoLab/Juno.jl#481

Closed

aviatesk closed this as completed Feb 17, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Wrong line number #21

Wrong line number #21

aviatesk commented Feb 17, 2020 •

edited

Loading

aviatesk commented Feb 17, 2020

timholy commented Apr 16, 2020

aviatesk commented Apr 17, 2020

timholy commented Apr 17, 2020

aviatesk commented Apr 17, 2020

Wrong line number #21

Wrong line number #21

Comments

aviatesk commented Feb 17, 2020 • edited Loading

aviatesk commented Feb 17, 2020

timholy commented Apr 16, 2020

aviatesk commented Apr 17, 2020

timholy commented Apr 17, 2020

aviatesk commented Apr 17, 2020

aviatesk commented Feb 17, 2020 •

edited

Loading