Invalidations findings (from a GMT case)

joa-quim · January 2, 2023, 2:55pm

Continuing from Julia v1.9.0-beta2 is fast and using Tim’s recipe

using SnoopCompileCore
invs = @snoopr using GMT
tinf = @snoopi_deep plot(rand(5,2));
using SnoopCompile
trees = invalidation_trees(invs);
taletrees = precompile_blockers(trees, tinf)

I found that the major culprit was this line I had in startup.jl to print UInt's in a human readable way (I hate when they printed in hexadecimal).

Base.show(io::IO, x::T) where {T<:Union{UInt, UInt64, UInt32, UInt16, UInt8}} = Base.print(io, x)

Removing it made already a big difference (though I’m again screwed in search of an alternative).

julia> @time using GMT
  1.808663 seconds (3.46 M allocations: 205.896 MiB, 4.76% gc time, 0.22% compilation time)

julia> @time @eval plot(rand(5,2))
  2.616777 seconds (7.55 M allocations: 470.434 MiB, 6.38% gc time, 162.89% compilation time: 45% of which was recompilation)

(it used to take ~4.5 sec)

  | | |_| | | | (_| |  |  Version 1.10.0-DEV.207 (2022-12-28)
 _/ |\__'_|_|_|\__'_|  |  Commit 9448c89652 (5 days old master)
|__/                   |

julia> include("c:/v/test_gmt1.jl")
1-element Vector{SnoopCompile.StaleTree}:
 inserting eltype(::Type{JuliaInterpreter.ExprSplitter}) @ JuliaInterpreter C:\Users\joaqu\.julia\packages\JuliaInterpreter\8vzXf\src\construct.jl:430 invalidated:
   mt_backedges: 1: MethodInstance for SubArray(::IndexCartesian, ::P, ::I, ::Tuple{Vararg{Any, N}}) where {P<:GMTdataset, I<:Tuple, N} at depth 1 with 5 children blocked InferenceTimingNode: 0.004436/0.073617 on GMT.make_color_column(::Dict{Symbol, Any}, ::String, ::String, ::Int64, ::Int64, ::Int64, ::Bool, ::Bool, ::Bool, ::Vector{String}, ::Matrix{Float64}, nothing::Nothing) with 16 direct children
                 2: MethodInstance for SubArray(::IndexLinear, ::P, ::I, ::Tuple{Vararg{Any, N}}) where {P<:(Array), I<:Tuple, N} at depth 1 with 17 children blocked 1.4152226000000003 inclusive time for 2 nodes

There is only one invalidation coming from JuliaInterpreter, which is not a GMT’s dependency (nor indirectly). It turns out it is a Revise dependency and I have Revise in my startup.jl.

Without Revise

julia> @time @eval plot(rand(5,2))
0.687842 seconds (1.08 M allocations: 71.042 MiB, 2.03% gc time, 146.57% compilation time: 33% of which was recompilation)

Finaly the load time

This is a longer list but all references seem to come from dependecies of PrettyTables like LatexStrings and StringManipulation

julia> include(“c:/v/test_gmt1.jl”)
SnoopCompile.StaleTree

julia> trees
7-element Vector{SnoopCompile.MethodInvalidations}:
 inserting firstindex(s::LaTeXStrings.LaTeXString) @ LaTeXStrings C:\Users\joaqu\.julia\packages\LaTeXStrings\pJ7vn\src\LaTeXStrings.jl:108 invalidated:
   backedges: 1: superseding firstindex(s::AbstractString) @ Base strings\basic.jl:180 with MethodInstance for firstindex(::AbstractString) (1 children)

 inserting codeunits(s::LaTeXStrings.LaTeXString) @ LaTeXStrings C:\Users\joaqu\.julia\packages\LaTeXStrings\pJ7vn\src\LaTeXStrings.jl:124 invalidated:
   mt_backedges: 1: signature Tuple{typeof(codeunits), Any} triggered MethodInstance for Base.cwstring(::AbstractString) (3 children)
   backedges: 1: superseding codeunits(s::AbstractString) @ Base strings\basic.jl:785 with MethodInstance for codeunits(::AbstractString) (1 children)

 inserting Base.IteratorSize(::Type{R}) where R<:Union{AbstractColumns, AbstractRow} @ Tables C:\Users\joaqu\.julia\packages\Tables\T7rHm\src\Tables.jl:179 invalidated:
   backedges: 1: superseding Base.IteratorSize(::Type) @ Base generator.jl:94 with MethodInstance for Base.IteratorSize(::Type{<:AbstractString}) (5 children)
   112 mt_cache

 inserting lastindex(s::LaTeXStrings.LaTeXString) @ LaTeXStrings C:\Users\joaqu\.julia\packages\LaTeXStrings\pJ7vn\src\LaTeXStrings.jl:109 invalidated:
   backedges: 1: superseding lastindex(s::AbstractString) @ Base strings\basic.jl:181 with MethodInstance for lastindex(::AbstractString) (5 children)

 inserting eltype(::Type{Tables.NamedTupleIterator{Tables.Schema{names, types}, T}}) where {names, types, T} @ Tables C:\Users\joaqu\.julia\packages\Tables\T7rHm\src\namedtuples.jl:36 invalidated:
   backedges: 1: superseding eltype(::Type) @ Base abstractarray.jl:233 with MethodInstance for eltype(::Type) (6 children)
   34 mt_cache

 inserting sizeof(s::LaTeXStrings.LaTeXString) @ LaTeXStrings C:\Users\joaqu\.julia\packages\LaTeXStrings\pJ7vn\src\LaTeXStrings.jl:125 invalidated:
   backedges: 1: superseding sizeof(s::AbstractString) @ Base strings\basic.jl:179 with MethodInstance for sizeof(::AbstractString) (15 children)

 inserting convert(::Type{String}, d::StringManipulation.Decoration) @ StringManipulation C:\Users\joaqu\.julia\packages\StringManipulation\wxRU4\src\decorations.jl:193 invalidated:
   mt_backedges:  1: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Base.UUID}, ::Any, ::Any) (0 children)
                  2: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Union{Bool, String}}, ::Any, ::Any) (0 children)
                  3: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Union{Nothing, String}}, ::Any, ::Any) (0 children)
                  4: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Nothing}, ::Nothing, ::Any) (0 children)
                  5: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Vector{String}, ::Any, ::Int64) (0 children)
                  6: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for push!(::Vector{String}, ::Any) (0 children)
                  7: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Union{Base.SHA1, String}}, ::Any, ::Any) (0 children)
                  8: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Function}, ::Any, ::Any) (0 children)
                  9: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Union{String, Vector{String}}}, ::Any, ::Any) (0 children)
                 10: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, String}, ::Any, ::Any) (0 children)
                 11: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for (::Base.var"#cvt1#1"{Tuple{String, String, Base.UUID}})(::Int64) (0 children)
                 12: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for (::Base.var"#cvt1#1"{Tuple{String, Union{Nothing, VersionNumber}}})(::Int64) (0 children)
                 13: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Any}, ::Any, ::Any) (0 children)
                 14: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Vector{Pkg.Types.Stage1}}, ::Vector{Pkg.Types.Stage1}, ::Any) (0 children)
                 15: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for (::Base.var"#cvt1#1"{Tuple{Base.UUID, String, String, VersionNumber}})(::Int64) (0 children)
                 16: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for Test.Fail(::Symbol, ::Any, ::Any, ::Any, ::Nothing, ::LineNumberNode, ::Bool) (0 children)
                 17: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for Test.Fail(::Symbol, ::Any, ::Any, ::Any, ::Any, ::LineNumberNode, ::Bool) (0 children)
                 18: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for Test.Fail(::Symbol, ::Any, ::Any, ::Nothing, ::Nothing, ::LineNumberNode, ::Bool) (0 children)
                 19: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Base.UUID}, ::Base.UUID, ::Any) (0 children)
                 20: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for Test.Fail(::Symbol, ::Any, ::Any, ::Bool, ::Nothing, ::LineNumberNode, ::Bool) (0 children)
                 21: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Pkg.Types.Compat}, ::Any, ::Any) (0 children)
                 22: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Vector{String}}, ::Vector{String}, ::Any) (0 children)
                 23: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::IdDict{Any, String}, ::Any, ::Any) (1 children)
                 24: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, String}, ::Any, ::String) (1 children)
                 25: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for convert(::Type{Pair{String, String}}, ::Pair{String}) (1 children)
                 26: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for Logging.var"#handle_message#3"(::Base.Pairs{Symbol, Union{}, Tuple{}, NamedTuple{(), Tuple{}}}, ::typeof(Base.CoreLogging.handle_message), ::Logging.ConsoleLogger, ::Base.CoreLogging.LogLevel, ::Any, ::Any, ::Any, ::Any, ::Any, ::Any) (1 children)
                 27: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for Logging.var"#handle_message#3"(::Base.Pairs{Symbol, V, Tuple{Vararg{Symbol, N}}, NamedTuple{names, T}} where {V, N, names, T<:Tuple{Vararg{Any, N}}}, ::typeof(Base.CoreLogging.handle_message), ::Logging.ConsoleLogger, ::Base.CoreLogging.LogLevel, ::Any, ::Any, ::Any, ::Any, ::Any, ::Any) (1 children)
                 28: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for Test.Error(::Symbol, ::Any, ::Any, ::Vector{Any}, ::LineNumberNode) (1 children)
                 29: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for REPL.LineEdit.PrefixSearchState(::Any, ::Any, ::Any, ::Any) (1 children)
                 30: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for REPL.LineEditREPL(::Any, ::Any, ::Any, ::Any, ::Any, ::Any, ::Any, ::Any, ::Any, ::Any, ::Any) (1 children)
                 31: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for Test.Error(::Symbol, ::Any, ::Bool, ::Nothing, ::LineNumberNode) (1 children)
                 32: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for Test.Error(::Symbol, ::Any, ::Any, ::Nothing, ::LineNumberNode) (2 children)
                 33: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for Test.Error(::Symbol, ::Any, ::Any, ::Any, ::LineNumberNode) (2 children)
                 34: signature Tuple{typeof(convert), Union{Type{Base.UUID}, Type{String}}, Any} triggered MethodInstance for (::Base.var"#cvt1#1"{Tuple{String, String, Base.UUID}})(::Int64) (3 children)
                 35: signature Tuple{typeof(convert), Union{Type{Base.UUID}, Type{VersionNumber}, Type{String}}, Any} triggered MethodInstance for (::Base.var"#cvt1#1"{Tuple{Base.UUID, String, String, VersionNumber}})(::Int64) (3 children)
                 36: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for Base.CoreLogging.var"#handle_message#2"(::Base.Pairs{Symbol, V, Tuple{Vararg{Symbol, N}}, NamedTuple{names, T}} where {V, N, names, T<:Tuple{Vararg{Any, N}}}, ::typeof(Base.CoreLogging.handle_message), ::Base.CoreLogging.SimpleLogger, ::Base.CoreLogging.LogLevel, ::Any, ::Any, ::Any, ::Any, ::Any, ::Any) (4 children)
                 37: signature Tuple{typeof(convert), Union{Type{String}, Type{Union{Nothing, VersionNumber}}}, Any} triggered MethodInstance for (::Base.var"#cvt1#1"{Tuple{String, Union{Nothing, VersionNumber}}})(::Int64) (4 children)
                 38: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for REPL.REPLHistoryProvider(::Any, ::Any, ::Any, ::Any, ::Any, ::Any, ::Any, ::Any, ::Any, ::Any) (17 children)
                 39: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for convert(::Type{Union{Nothing, String}}, ::Any) (48 children)
                 40: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for Pkg.Types.Compat(::Pkg.Versions.VersionSpec, ::Any) (121 children)
                 41: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for Pkg.Registry.verify_compressed_registry_toml(::String) (156 children)

kristoffer.carlsson · January 2, 2023, 3:07pm

These should be fixed by Fix inference for STDLIBS_BY_VERSION by timholy · Pull Request #3275 · JuliaLang/Pkg.jl · GitHub. By an accident that was not included in 1.9.0-beta2 but should be in beta3 (or master if you want to try that one out).

jishnub · January 2, 2023, 3:18pm

Why does this PR improve inference, though? It seems the type is defined as a constant, that’s about it

stillyslalom · January 2, 2023, 3:28pm

Line 9 has Dict{UUID}, which only specifies the type of the key. The new const Dict{...} in the PR specifies both key and value types.

joa-quim · January 2, 2023, 3:33pm

I’m already using master (5 days old but that commit was merged 3 weeks ago)

  | | |_| | | | (_| |  |  Version 1.10.0-DEV.207 (2022-12-28)
 _/ |\__'_|_|_|\__'_|  |  Commit 9448c89652 (5 days old master)

kristoffer.carlsson · January 2, 2023, 4:16pm

I mixed it up with some other things I was looking at. improve inference in Pkg by KristofferC · Pull Request #3293 · JuliaLang/Pkg.jl · GitHub should hopefully deal with those.

ufechner7 · January 2, 2023, 5:28pm

Not sure why I get much faster results:

julia> using Plots

julia> @time @eval plot(rand(5,2))
  0.078085 seconds (42.42 k allocations: 2.209 MiB, 90.84% compilation time)

Different backend? Different OS?
I am using Ubuntu on a Intel® Core™ i7-10510U CPU.

joa-quim · January 2, 2023, 5:45pm

Different plots. The one I posted here is from GMT.jl

using GMT

julia> @time @eval plot(rand(5,2))
  0.702287 seconds (1.06 M allocations: 69.453 MiB, 4.55% gc time, 148.71% compilation time: 32% of which was recompilation)

julia> @time @eval plot(rand(5,2))
  0.003255 seconds (494 allocations: 31.133 KiB)

I take it to mean that there still some dependent functions that didn’t get pre-compiled on first run.

joa-quim · January 2, 2023, 6:15pm

ufechner7:

Not sure why I get much faster results:
julia> using Plots

julia> @time @eval plot(rand(5,2))
  0.078085 seconds (42.42 k allocations: 2.209 MiB, 90.84% compilation time)
Different backend? Different OS?
I am using Ubuntu on a Intel® Core™ i7-10510U CPU.

Hmmm, much slower here. From a fresh session:

  | | |_| | | | (_| |  |  Version 1.10.0-DEV.207 (2022-12-28)
 _/ |\__'_|_|_|\__'_|  |  Commit 9448c89652 (5 days old master)
|__/                   |

julia> @time using Plots
  3.561736 seconds (6.14 M allocations: 413.016 MiB, 5.77% gc time, 1.77% compilation time: 48% of which was recompilation)

julia> @time @eval plot(rand(5,2))
  6.858056 seconds (18.11 M allocations: 1.153 GiB, 7.42% gc time, 172.21% compilation time)

.

julia> versioninfo()
Julia Version 1.10.0-DEV.207
Commit 9448c89652 (2022-12-28 00:22 UTC)
Platform Info:
  OS: Windows (x86_64-w64-mingw32)
  CPU: 12 × Intel(R) Core(TM) i7-8750H CPU @ 2.20GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-14.0.6 (ORCJIT, skylake)
  Threads: 6 on 12 virtual cores
Environment:
  JULIA_NUM_THREADS = 6

kristoffer.carlsson · January 2, 2023, 9:58pm

Are you sure you don’t have stuff in your startup file? The 18M allocations is pretty different to me:

julia> @time (p = plot(rand(2,2)); display(p))
  0.516695 seconds (75.79 k allocations: 4.427 MiB, 35.58% compilation time: 8% of which was recompilation)

ufechner7 · January 2, 2023, 10:07pm

Yes, including the display time in the test makes sense and I get very similar results:

ufechner@tuxedi:~$ julia
               _
   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.9.0-beta2 (2022-12-29)
 _/ |\__'_|_|_|\__'_|  |  Official https://julialang.org/ release
|__/                   |

julia> using Plots

julia> @time @eval (p = plot(rand(2,2)); display(p))
  0.527025 seconds (90.88 k allocations: 5.346 MiB, 37.99% compilation time: 7% of which was recompilation)

julia> versioninfo()
Julia Version 1.9.0-beta2
Commit 7daffeecb8c (2022-12-29 07:45 UTC)
Platform Info:
  OS: Linux (x86_64-linux-gnu)
  CPU: 8 × Intel(R) Core(TM) i7-10510U CPU @ 1.80GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-14.0.6 (ORCJIT, skylake)
  Threads: 1 on 8 virtual cores

joa-quim · January 2, 2023, 10:34pm

If you make that way, it’s even worse. (I had Dates and Printf in startup.jl but now it’s clean)

  | | |_| | | | (_| |  |  Version 1.10.0-DEV.207 (2022-12-28)
 _/ |\__'_|_|_|\__'_|  |  Commit 9448c89652 (5 days old master)
|__/                   |

julia> @time using Plots
  3.800417 seconds (6.14 M allocations: 413.174 MiB, 5.28% gc time, 1.81% compilation time: 48% of which was recompilation)

julia> @time (p = plot(rand(2,2)); display(p))
 11.729658 seconds (18.03 M allocations: 1.122 GiB, 4.00% gc time, 118.98% compilation time: <1% of which was recompilation)

joa-quim · January 2, 2023, 11:05pm

Is it only me that have these timings?

giordano · January 2, 2023, 11:37pm

Yes, on my M1 I have

 % ./julia --startup-file=no --project=/tmp -q
 julia> @time @eval using Plots; x = 0:0.1:10; y = sin.(x); @time @eval display(Plots.plot(x, y));
   1.879666 seconds (5.61 M allocations: 351.548 MiB, 7.30% gc time, 0.34% compilation time)
   0.523323 seconds (232.44 k allocations: 14.951 MiB, 43.05% compilation time: 4% of which was recompilation)

Do you know that you can use the flag --startup-file=no without touching your init file?

joa-quim · January 2, 2023, 11:43pm

And would mind imagining where my particular Julia version is coming from?

C:\programs\julia-1.10\bin\julia --startup-file=no
               _
   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.10.0-DEV.207 (2022-12-28)
 _/ |\__'_|_|_|\__'_|  |  Commit 9448c89652 (5 days old master)
|__/                   |

julia> using Plots

julia> @time (p = plot(rand(2,2)); display(p))
 11.809763 seconds (18.03 M allocations: 1.122 GiB, 4.08% gc time, 119.10% compilation time: <1% of which was recompilation)

But this post is not about Plots plot(). It’s about GMT plot() and its invalidation’s finds that touch several other packages.

giordano · January 2, 2023, 11:56pm

I don’t know, but the timings you reported have suspiciously very high memory allocations, no one here has shown anything close 18 M allocations

tim.holy · January 2, 2023, 11:57pm

There is only one invalidation coming from JuliaInterpreter, which is not a GMT’s dependency (nor indirectly). It turns out it is a Revise dependency and I have Revise in my startup.jl.

That suggests you don’t have to worry about any more invalidations for that particular workload. 0.7s is not bad, but do check that you are using SnoopPrecompile and that all elements of display(GMT.plot(rand(5,2))) are inside the @precompile_all_calls.

joa-quim · January 3, 2023, 12:02am

Yes, 0.7 sec is more than fine but that is without Revise and I don’t want to give up of it

I’m not using SnoopPrecompile here but it doesn’t change if use it or not in this regard.

kristoffer.carlsson · January 3, 2023, 10:31am

What happens if you download the official 1.9.0-beta2 and time Plots.plot on it?

If you have very strange results for Plots.plot it isn’t unthinkable that your numbers are strange form GMT.plot as well so it would be good to understand what is going on with that.

nilshg · January 3, 2023, 12:21pm

I can’t properly test on Linux right now as I’ve only got access to WSL2 so display fails, but on my Windows machine I see:

julia> @time @eval using Plots; x = 0:0.1:10; y = sin.(x); @time @eval display(Plots.plot(x, y));
  2.749473 seconds (5.74 M allocations: 357.409 MiB, 5.30% gc time, 0.50% compilation time)
  6.249960 seconds (9.27 M allocations: 576.751 MiB, 2.34% gc time, 88.69% compilation time: <1% of which was recompilation)

julia> versioninfo()
Julia Version 1.9.0-beta2
Commit 7daffeecb8 (2022-12-29 07:45 UTC)
Platform Info:
  OS: Windows (x86_64-w64-mingw32)
  CPU: 8 × 11th Gen Intel(R) Core(TM) i7-1165G7 @ 2.80GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-14.0.6 (ORCJIT, tigerlake)
  Threads: 8 on 8 virtual cores

Which is about half the allocations reported above, but order-of-magnitude correct - so maybe it’s a Windows specific issue?