search

timholy / FlameGraphs.jl

Analysis of profiling data using trees
MIT License
51 stars 12 forks source link

Wrong line number #21

Closed aviatesk closed 4 years ago

aviatesk commented 4 years ago

(original issue posted at https://github.com/JunoLab/Juno.jl/issues/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: image

aviatesk commented 4 years ago

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 commented 4 years ago

Might be fixed in Julia 1.5? See https://github.com/JuliaLang/julia/pull/35138.

aviatesk commented 4 years ago

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 commented 4 years ago

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 (https://github.com/JuliaLang/julia/issues/34811), so there's not a lot more to do here. But thanks for trying latest master!

aviatesk commented 4 years ago

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