timholy / SnoopCompile.jl

Provide insights about latency (TTFX) for Julia packages
https://timholy.github.io/SnoopCompile.jl/dev/
Other
309 stars 48 forks source link

SnoopCompile is broken in Julia DEV version #296

Closed joa-quim closed 2 years ago

joa-quim commented 2 years ago

Probably known but

julia> trees = invalidation_trees(invalidations)
ERROR: UndefRefError: access to undefined reference
Stacktrace:
 [1] getindex
   @ .\essentials.jl:13 [inlined]
 [2] invalidation_trees(list::Vector{Any}; exclude_corecompiler::Bool)
   @ SnoopCompile C:\Users\joaqu\.julia\packages\SnoopCompile\J3dtR\src\invalidations.jl:327
 [3] invalidation_trees(list::Vector{Any})
   @ SnoopCompile C:\Users\joaqu\.julia\packages\SnoopCompile\J3dtR\src\invalidations.jl:288
 [4] top-level scope
   @ REPL[2]:1
jishnub commented 2 years ago

I obtain a somewhat different error today:

julia> VERSION
v"1.9.0-DEV.1330"

julia> using SnoopCompileCore

julia> invalidations = @snoopr using LowRankApprox;

julia> using SnoopCompile

julia> trees = invalidation_trees(invalidations)
Unreachable reached at 0x7f458b71e045

[12257] signal (4): Illegal instruction
in expression starting at REPL[4]:1
getproperty at ./Base.jl:37 [inlined]
children at /home/jishnu/.julia/packages/SnoopCompile/J3dtR/src/invalidations.jl:80 [inlined]
call_composed at ./operators.jl:1019 [inlined]
#_#97 at ./operators.jl:1016 [inlined]
ComposedFunction at ./operators.jl:1016 [inlined]
iterate at /home/jishnu/.julia/packages/AbstractTrees/kBTzE/src/cursors.jl:143 [inlined]
iterate at /home/jishnu/.julia/packages/AbstractTrees/kBTzE/src/cursors.jl:143 [inlined]
isempty at ./essentials.jl:870 [inlined]
next at /home/jishnu/.julia/packages/AbstractTrees/kBTzE/src/iteration.jl:110 [inlined]
iterate at /home/jishnu/.julia/packages/AbstractTrees/kBTzE/src/iteration.jl:160 [inlined]
iterate at /home/jishnu/.julia/packages/AbstractTrees/kBTzE/src/iteration.jl:159 [inlined]
#invalidation_trees#137 at /home/jishnu/.julia/packages/SnoopCompile/J3dtR/src/invalidations.jl:441
invalidation_trees at /home/jishnu/.julia/packages/SnoopCompile/J3dtR/src/invalidations.jl:288
unknown function (ip: 0x7f458b71e8f2)
_jl_invoke at /cache/build/default-amdci4-1/julialang/julia-master/src/gf.c:2447 [inlined]
ijl_apply_generic at /cache/build/default-amdci4-1/julialang/julia-master/src/gf.c:2629
jl_apply at /cache/build/default-amdci4-1/julialang/julia-master/src/julia.h:1856 [inlined]
do_call at /cache/build/default-amdci4-1/julialang/julia-master/src/interpreter.c:126
eval_value at /cache/build/default-amdci4-1/julialang/julia-master/src/interpreter.c:215
eval_stmt_value at /cache/build/default-amdci4-1/julialang/julia-master/src/interpreter.c:166 [inlined]
eval_body at /cache/build/default-amdci4-1/julialang/julia-master/src/interpreter.c:613
jl_interpret_toplevel_thunk at /cache/build/default-amdci4-1/julialang/julia-master/src/interpreter.c:751
jl_toplevel_eval_flex at /cache/build/default-amdci4-1/julialang/julia-master/src/toplevel.c:912
jl_toplevel_eval_flex at /cache/build/default-amdci4-1/julialang/julia-master/src/toplevel.c:856
jl_toplevel_eval_flex at /cache/build/default-amdci4-1/julialang/julia-master/src/toplevel.c:856
ijl_toplevel_eval_in at /cache/build/default-amdci4-1/julialang/julia-master/src/toplevel.c:971
eval at ./boot.jl:370 [inlined]
eval_user_input at /cache/build/default-amdci4-1/julialang/julia-master/usr/share/julia/stdlib/v1.9/REPL/src/REPL.jl:152
repl_backend_loop at /cache/build/default-amdci4-1/julialang/julia-master/usr/share/julia/stdlib/v1.9/REPL/src/REPL.jl:248
#start_repl_backend#46 at /cache/build/default-amdci4-1/julialang/julia-master/usr/share/julia/stdlib/v1.9/REPL/src/REPL.jl:233
start_repl_backend##kw at /cache/build/default-amdci4-1/julialang/julia-master/usr/share/julia/stdlib/v1.9/REPL/src/REPL.jl:230 [inlined]
#run_repl#59 at /cache/build/default-amdci4-1/julialang/julia-master/usr/share/julia/stdlib/v1.9/REPL/src/REPL.jl:372
run_repl at /cache/build/default-amdci4-1/julialang/julia-master/usr/share/julia/stdlib/v1.9/REPL/src/REPL.jl:357
jfptr_run_repl_58722.clone_1 at /home/jishnu/packages/julias/julia-latest/lib/julia/sys.so (unknown line)
_jl_invoke at /cache/build/default-amdci4-1/julialang/julia-master/src/gf.c:2447 [inlined]
ijl_apply_generic at /cache/build/default-amdci4-1/julialang/julia-master/src/gf.c:2629
#1013 at ./client.jl:421
jfptr_YY.1013_46091.clone_1 at /home/jishnu/packages/julias/julia-latest/lib/julia/sys.so (unknown line)
_jl_invoke at /cache/build/default-amdci4-1/julialang/julia-master/src/gf.c:2447 [inlined]
ijl_apply_generic at /cache/build/default-amdci4-1/julialang/julia-master/src/gf.c:2629
jl_apply at /cache/build/default-amdci4-1/julialang/julia-master/src/julia.h:1856 [inlined]
jl_f__call_latest at /cache/build/default-amdci4-1/julialang/julia-master/src/builtins.c:774
#invokelatest#2 at ./essentials.jl:805 [inlined]
invokelatest at ./essentials.jl:802 [inlined]
run_main_repl at ./client.jl:405
exec_options at ./client.jl:322
_start at ./client.jl:522
jfptr__start_47846.clone_1 at /home/jishnu/packages/julias/julia-latest/lib/julia/sys.so (unknown line)
_jl_invoke at /cache/build/default-amdci4-1/julialang/julia-master/src/gf.c:2447 [inlined]
ijl_apply_generic at /cache/build/default-amdci4-1/julialang/julia-master/src/gf.c:2629
jl_apply at /cache/build/default-amdci4-1/julialang/julia-master/src/julia.h:1856 [inlined]
true_main at /cache/build/default-amdci4-1/julialang/julia-master/src/jlapi.c:567
jl_repl_entrypoint at /cache/build/default-amdci4-1/julialang/julia-master/src/jlapi.c:711
main at julia-latest (unknown line)
__libc_start_main at /lib/x86_64-linux-gnu/libc.so.6 (unknown line)
unknown function (ip: 0x401098)
Allocations: 8020685 (Pool: 8016791; Big: 3894); GC: 7
[1]    12257 illegal hardware instruction (core dumped)  julia-latest --project
timholy commented 2 years ago

Thanks @jishnub for the reproducible example. I can verify this. I will try to bisect Julia and see where it got introduced.

@joa-quim the error was not known, and last time CI ran it failed only because JET was still catching up. If you have a reproducible example that would help; I suspect it may be a different error than the one reported by @jishnub.

timholy commented 2 years ago

Update: on the machine I use for bisecting, master works. Specifics:

julia> versioninfo()                                                                                                                                                                                          Julia Version 1.9.0-DEV.1330
Commit 7e51510f70* (2022-09-12 12:33 UTC)
Platform Info:
  OS: Linux (x86_64-linux-gnu)
  CPU: 64 × AMD Ryzen Threadripper 3970X 32-Core Processor
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-14.0.5 (ORCJIT, znver2)
  Threads: 1 on 64 virtual cores
joa-quim commented 2 years ago

Hi, Still GMT :)

  | | |_| | | | (_| |  |  Version 1.9.0-DEV.1298 (2022-09-06)
 _/ |\__'_|_|_|\__'_|  |  Commit 639a4ff673 (6 days old master)
|__/                   |

julia> using SnoopCompileCore; invalidations = @snoopr(using GMT); using SnoopCompile
[ Info: Precompiling GMT [5752ebe1-31b9-557e-87aa-f909b540aa54]

julia> trees = invalidation_trees(invalidations)
ERROR: UndefRefError: access to undefined reference
Stacktrace:
 [1] getindex
   @ .\essentials.jl:13 [inlined]
 [2] (::SnoopCompile.var"#handle_insert_backedges#139")(list::Vector{Any}, i::Int64, callee::Core.MethodInstance)
   @ SnoopCompile C:\Users\joaqu\.julia\packages\SnoopCompile\J3dtR\src\invalidations.jl:306
 [3] invalidation_trees(list::Vector{Any}; exclude_corecompiler::Bool)
   @ SnoopCompile C:\Users\joaqu\.julia\packages\SnoopCompile\J3dtR\src\invalidations.jl:378
 [4] invalidation_trees(list::Vector{Any})
   @ SnoopCompile C:\Users\joaqu\.julia\packages\SnoopCompile\J3dtR\src\invalidations.jl:288
timholy commented 2 years ago

Thanks. Struggling with...

julia> using Pkg

julia> Pkg.build("GMT")
    Building Conda → `~/.julia/scratchspaces/44cfe95a-1eb2-52ea-b672-e2afdf69b78f/6e47d11ea2776bc5627421d59cdcc1296c058071/build.log`
    Building GMT ──→ `~/.julia/scratchspaces/44cfe95a-1eb2-52ea-b672-e2afdf69b78f/be1f463a791b90e5307634beb9e1a3bd7acb5d55/build.log`

julia> using GMT
[ Info: Precompiling GMT [5752ebe1-31b9-557e-87aa-f909b540aa54]
Base.IOError("could not spawn `gmt --version`: no such file or directory (ENOENT)", -2)
ERROR: LoadError: could not load library "/home/tim/.julia/conda/3/lib/libgmt.so"
/home/tim/src/juliaw/usr/bin/../lib/libstdc++.so.6: version `GLIBCXX_3.4.30' not found (required by /home/tim/.julia/conda/3/lib/./libgdal.so.31)
Stacktrace:
 [1] GMT_Create_Session (repeats 2 times)
   @ ~/.julia/packages/GMT/5iuho/src/libgmt.jl:2 [inlined]
...
joa-quim commented 2 years ago

Me too ... for months 😄

That's the Ghr@#$%&* https://github.com/JuliaLang/julia/pull/45582

I'm afraid the only solution for now is to use a linux package manager to install GMT. If I remember well, last time you tried that also failed because, again if I remember well, that package manager didn't install symbolic links to the libgmt lib.

timholy commented 2 years ago

Thanks. Now it's

julia> using GMT
[ Info: Precompiling GMT [5752ebe1-31b9-557e-87aa-f909b540aa54]
ErrorException("Need at least GMT6.1. The one you have (6.0.0) is not supported.")
ERROR: LoadError: could not load library "/home/tim/.julia/conda/3/lib/libgmt.so"
/home/tim/src/juliaw/usr/bin/../lib/libstdc++.so.6: version `GLIBCXX_3.4.30' not found (required by /home/tim/.julia/conda/3/lib/./libgdal.so.31)
Stacktrace:
 [1] GMT_Create_Session (repeats 2 times)
   @ ~/.julia/packages/GMT/5iuho/src/libgmt.jl:2 [inlined]

Do I need to disable the conda version somehow?

joa-quim commented 2 years ago

Oh, s... you must be on Ubuntu that never updates its packages. No need to deactivate the Conda install. It only pops in when no GMT version is installed system wide. The problem you are having is that Ubuntu installed the 4 years old GMT version (6.0) that is no longer supported.

We have instructions (sorry, didn't find it yet) somewhere on how to install from more updated packages on Ubuntu. (https://github.com/GenericMappingTools/gmt/blob/master/INSTALL.md#ubuntudebian)

But perhaps the easiest is just use build from source. Looking at the CI script, after cloning the GMT repo

https://github.com/GenericMappingTools/gmt/blob/master/BUILDING.md#building-gmt-source-codes git clone --depth 50 https://github.com/GenericMappingTools/gmt

bash ci/install-dependencies-linux.sh
bash ci/build-gmt.sh
# Add GMT PATH to bin
GMT_INSTALL_DIR=${GMT_INSTALL_DIR:-${HOME}/gmt-install-dir}

I'll keep looking for the info on Ubuntus packages

timholy commented 2 years ago

It might be easier for me to coach you through diagnosing this on your machine. It shouldn't be too hard: the error is clearly coming from https://github.com/timholy/SnoopCompile.jl/blob/e34a4c8e06c114d424bfdd8907e2f818eb49b99f/src/invalidations.jl#L327

and the thing to do if !isassigned(list, i+1) might be to display a subset of the list around index i.

joa-quim commented 2 years ago

Sorry, dinner+plus+walk break

I'm afraid I can't help much. Added this before line 327

        ii = i+1
        @show(ii, length(list),list[ii])
        if !isassigned(list, ii)
            @show(i, length(list))
            try
                while(i > 0)
                    println(i, "\t", list[i])
                    i -= 1
                end
            catch
            end
        end

but the conditions under if !isassigned(list, ii) were never caught.

Next I added on Line 306

            try
            push!(callees, list[i+1])
            catch
                @show(i+1,list[i+1])
                @show(callees)
            end

and got

ii = 287
length(list) = 306
list[ii] = MethodInstance for show(::IOBuffer, ::UInt32)
i + 1 = 291
ERROR: UndefRefError: access to undefined reference

For reference with Julia 1.8 I see a quite different printout and where length(list) = 1206

timholy commented 2 years ago

What does invalidations[285:295] look like? That will tell me where this is coming from.

joa-quim commented 2 years ago

Ok, I'd just finished doing this

julia> i=length(invalidations)
306

julia> while i > 0 (!isassigned(invalidations, i) && println(i)); i-=1  end
295
291

So, of all 306 invalidations returned by invalidations = @snoopr(using GMT) elements 291 and 291 were not assigned.

julia> invalidations[285:290]
6-element Vector{Any}:
 MethodInstance for Base.show_delim_array(::IOContext{IOBuffer}, ::Vector{UInt32}, ::Char, ::String, ::Char, ::Bool, ::Int64, ::Int64)
 "insert_backedges"
 MethodInstance for show(::IOBuffer, ::UInt32)
 "insert_backedges_callee"
 MethodInstance for show(::IOContext{IOBuffer}, ::UInt16)
 "insert_backedges_callee"
julia> invalidations[296:end]
11-element Vector{Any}:
 "insert_backedges_callee"
 MethodInstance for Base.print_to_string(::Regex)
 "insert_backedges"
 MethodInstance for (::Pkg.API.var"#instantiate##kw")(::NamedTuple{(:allow_build, :allow_autoprecomp), Tuple{Bool, Bool}}, ::typeof(Pkg.API.instantiate), ::Pkg.Types.Context)
 "insert_backedges"
 MethodInstance for GMT.add_opt(::Dict{Symbol, Any}, ::String, ::String, ::Vector{Symbol}, ::NamedTuple{(:x, :y, :xy, :X, :Y, :asym, :colored, :cline, :csymbol, :wiskers, :cap, :pen), Tuple{String, String, String, String, String, String, String, String, String, String, String, Tuple{String, typeof(GMT.add_opt_pen)}}}, ::Bool, ::Any)
 "insert_backedges"
 MethodInstance for SubArray(::IndexCartesian, ::P, ::I, ::Tuple{Vararg{Any, N}}) where {P<:GMTdataset, I<:Tuple, N}
 "insert_backedges"
 MethodInstance for GMT.add_opt(::Dict{Symbol, Any}, ::String, ::String, ::Matrix{Symbol}, ::NamedTuple{(:angle, :Angle, :font, :justify, :region_justify, :header, :label, :rec_number, :text, :zvalues), Tuple{String, String, Tuple{String, typeof(GMT.font)}, Vararg{String, 7}}}, ::Bool, ::Bool)
 "insert_backedges"
timholy commented 2 years ago

You could just do invalidations[285:end], as our array-printing handles unassigned elements, and that wouldn't omit the context between 291 and 295.

But I think I know what needs fixing. I just have to come up with a reproducible test case.

joa-quim commented 2 years ago

The suit is to ask what do those mean. And c'mon we ask Linux beginners to build GMT from source. It's not difficult at all.

julia> invalidations[285:end]
22-element Vector{Any}:
    MethodInstance for Base.show_delim_array(::IOContext{IOBuffer}, ::Vector{UInt32}, ::Char, ::String, ::Char, ::Bool, ::Int64, ::Int64)
    "insert_backedges"
    MethodInstance for show(::IOBuffer, ::UInt32)
    "insert_backedges_callee"
    MethodInstance for show(::IOContext{IOBuffer}, ::UInt16)
    "insert_backedges_callee"
 #undef
    "insert_backedges_callee"
    MethodInstance for eltype(::Type)
    "insert_backedges_callee"
   ⋮
    "insert_backedges"
    MethodInstance for (::Pkg.API.var"#instantiate##kw")(::NamedTuple{(:allow_build, :allow_autoprecomp), Tuple{Bool, Bool}}, ::typeof(Pkg.API.instantiate), ::Pkg.Types.Context)
    "insert_backedges"
    MethodInstance for GMT.add_opt(::Dict{Symbol, Any}, ::String, ::String, ::Vector{Symbol}, ::NamedTuple{(:x, :y, :xy, :X, :Y, :asym, :colored, :cline, :csymbol, :wiskers, :cap, :pen), Tuple{String, String, String, String, String, String, String, String, String, String, String, Tuple{String, typeof(GMT.add_opt_pen)}}}, ::Bool, ::Any)
    "insert_backedges"
    MethodInstance for SubArray(::IndexCartesian, ::P, ::I, ::Tuple{Vararg{Any, N}}) where {P<:GMTdataset, I<:Tuple, N}
    "insert_backedges"
    MethodInstance for GMT.add_opt(::Dict{Symbol, Any}, ::String, ::String, ::Matrix{Symbol}, ::NamedTuple{(:angle, :Angle, :font, :justify, :region_justify, :header, :label, :rec_number, :text, :zvalues), Tuple{String, String, Tuple{String, typeof(GMT.font)}, Vararg{String, 7}}}, ::Bool, ::Bool)
    "insert_backedges"
timholy commented 2 years ago

But I'm not a Julia beginner 😈

joa-quim commented 2 years ago

I meant GMT (not GMT.jl or Julia) beginners :imp:

timholy commented 2 years ago

My more serious point is that when I'm working to improve Julia and it requires a package that can't be "easily" installed, it's not inappropriate to ask for some debugging assistance.

joa-quim commented 2 years ago

Sure. I'll help on what I can, but when I'll reach the point to ask "WTF does this mean and what can I do fix it" I would prefer that you could reproduce it.

┌ Warning: Could not attribute the following delayed invalidations: └ @ SnoopCompile C:\Users\joaqu.julia\packages\SnoopCompile\J3dtR\src\invalidations.jl:479 Any[MethodInstance for show(::IOContext{IOBuffer}, ::UInt8), MethodInstance for show(::IOContext{IOBuffer}, ::UInt64), MethodInstance for show(::IOContext{IOBuffer}, ::UInt32), MethodInstance for show(::IOContext{IOBuffer}, ::UInt16)] invalidated Core.MethodInstance[MethodInstance for Base.show_delim_array(::IOContext{IOBuffer}, ::Vector{UInt8}, ::Char, ::String, ::Char, ::Bool, ::Int64, ::Int64), MethodInstance for Base.show_delim_array(::IOContext{IOBuffer}, ::Vector{UInt64}, ::String, ::String, ::Char, ::Bool, ::Int64, ::Int64), MethodInstance for Base.show_delim_array(::IOContext{IOBuffer}, ::Vector{UInt8}, ::String, ::String, ::Char, ::Bool, ::Int64, ::Int64), MethodInstance for Base.show_delim_array(::IOContext{IOBuffer}, ::Vector{UInt64}, ::Char, ::String, ::String, ::Bool, ::Int64, ::Int64), MethodInstance for Base.show_delim_array(::IOContext{IOBuffer}, ::Vector{UInt32}, ::String, ::String, ::Char, ::Bool, ::Int64, ::Int64), MethodInstance for Base.show_delim_array(::IOContext{IOBuffer}, ::Vector{UInt32}, ::Char, ::String, ::String, ::Bool, ::Int64, ::Int64), MethodInstance for Base.show_vector(::IOContext{IOBuffer}, ::Vector{UInt16}, ::Char, ::Char), MethodInstance for Base.show_delim_array(::IOContext{IOBuffer}, ::Vector{UInt8}, ::Char, ::String, ::String, ::Bool, ::Int64, ::Int64), MethodInstance for Base.show_delim_array(::IOContext{IOBuffer}, ::Vector{UInt64}, ::Char, ::String, ::Char, ::Bool, ::Int64, ::Int64), MethodInstance for Base.show_delim_array(::IOContext{IOBuffer}, ::Vector{UInt32}, ::Char, ::String, ::Char, ::Bool, ::Int64, ::Int64)] Any[MethodInstance for show(::IOBuffer, ::UInt32), MethodInstance for show(::IOContext{IOBuffer}, ::UInt16), MethodInstance for eltype(::Type)] invalidated Core.MethodInstance[MethodInstance for Base.print_to_string(::Regex), MethodInstance for (::Pkg.API.var"#instantiate##kw")(::NamedTuple{(:allow_build, :allow_autoprecomp), Tuple{Bool, Bool}}, ::typeof(Pkg.API.instantiate), ::Pkg.Types.Context), MethodInstance for GMT.add_opt(::Dict{Symbol, Any}, ::String, ::String, ::Vector{Symbol}, ::NamedTuple{(:x, :y, :xy, :X, :Y, :asym, :colored, :cline, :csymbol, :wiskers, :cap, :pen), Tuple{String, String, String, String, String, String, String, String, String, String, String, Tuple{String, typeof(GMT.add_opt_pen)}}}, ::Bool, ::Any), MethodInstance for SubArray(::IndexCartesian, ::P, ::I, ::Tuple{Vararg{Any, N}}) where {P<:GMTdataset, I<:Tuple, N}, MethodInstance for GMT.add_opt(::Dict{Symbol, Any}, ::String, ::String, ::Matrix{Symbol}, ::NamedTuple{(:angle, :Angle, :font, :justify, :region_justify, :header, :label, :rec_number, :text, :zvalues), Tuple{String, String, Tuple{String, typeof(GMT.font)}, Vararg{String, 7}}}, ::Bool, ::Bool)]

timholy commented 2 years ago

That's confusing because it comes from a part of dump.c that I only just recently understood well enough to interpret those data myself; basically, that output is me punting on the part I didn't know how to handle. But I get it now, and julia itself will need some changes to make it robustly interpretable. But then SnoopCompile will be able to analyze the structure. Improvements coming.

timholy commented 2 years ago

https://github.com/JuliaLang/julia/pull/46756

timholy commented 2 years ago

The immediate issue was closed by https://github.com/JuliaLang/julia/pull/46756. The "unreachable reached" remains to be resolved, but on a CPU where this didn't happen I got far enough to detect an interesting invalidation in LowRankApprox (https://github.com/timholy/SnoopCompile.jl/issues/296#issuecomment-1243932710) which should be fixed by https://github.com/JuliaLang/julia/pull/46907.