Slower times to TTFX for GMT in 1.11 and even more in nightly

joa-quim · February 26, 2025, 4:47pm

Hi,

I’ve been delaying this post but not that time to v1.12 release seems to approach I think I should not delay it no more.

Since the 1.10 I have notice that building and using has become progressively slower but this can not be a such general trend otherwise much people would have complained already (though so do from time to time).

The numbers supporting this slowing trend.

Precompile times

v1.10.8
1 dependency successfully precompiled in 50 seconds. 86 already precompiled.
54.104402 seconds (5.92 M allocations: 428.064 MiB, 0.19% gc time, 2.65% compilation time)
v1.11.3
1 dependency successfully precompiled in 69 seconds. 106 already precompiled.
70.022164 seconds (2.11 M allocations: 138.035 MiB, 0.15% gc time, 0.25% compilation time: 3% of which was recompilation)
Nightly
1 dependency successfully precompiled in 83 seconds. 107 already precompiled.
84.497631 seconds (3.32 M allocations: 188.795 MiB, 0.25% gc time, 0.18% compilation time)

Time to run the tests

v1.10.8
Test Summary: | Pass Total Time
GMT | 589 589 3m59.5s
v1.11.3
Test Summary: | Pass Total Time
GMT | 589 589 5m49.9s
Nightly
Test Summary: | Pass Total Time
GMT | 589 589 9m17.1s

Time to load

v1.10.8
julia> @time using GMT
0.749225 seconds (847.44 k allocations: 56.259 MiB, 4.59% gc time, 1.33% compilation time)
v1.11.3
julia> @time using GMT
0.757707 seconds (894.38 k allocations: 57.734 MiB, 5.12% gc time, 0.45% compilation time)
Nightly
julia> @time using GMT
1.146255 seconds (1.96 M allocations: 103.028 MiB, 6.50% gc time, 6.55% compilation time)

TTFP

v1.10.8
julia> @time @eval plot(rand(5,2))
2.705809 seconds (7.53 M allocations: 510.835 MiB, 5.16% gc time, 99.89% compilation time: 90% of which was recompilation)
v1.11.3
julia> @time @eval plot(rand(5,2))
6.115157 seconds (32.69 M allocations: 1.626 GiB, 8.90% gc time, 99.95% compilation time: 21% of which was recompilation)
Nightly
julia> @time @eval plot(rand(5,2))
7.588851 seconds (24.42 M allocations: 1.270 GiB, 7.07% gc time, 99.95% compilation time: 14% of which was recompilation)

Now, this long TTFP is also strange because the plot(rand(5,2)) is the last command of the PrecompileTools block. So one should expect it to be almost instantaneous (it is on a second run) but it isn’t.

Checking with the nightly @trace_compile macro we see that some methods are being recompiled. Why? What invalidated them? SnoopCompileCore reports only one invalidation coming from the GMT code.
And even the recompilations account only to ~0.75 sec but full time run was ~7.6 sec

In summary, it seems that precompile is not compiling many methods and that other are invalidated I don’t know where/why. And all of this is rather more dramatic in nightly.

julia> @trace_compile plot(rand(5,2))
#=    2.5 ms =# precompile(Tuple{typeof(Base.mapreducedim!), Function, Function, Array{Tuple{Float64, Float64}, 2}, Array{Float64, 2}})
#=  290.1 ms =# precompile(Tuple{typeof(GMT.common_plot_xyz), String, GMT.GMTdataset{Float64, 2}, String, Bool, Bool}) # recompile
#=   16.6 ms =# precompile(Tuple{typeof(Base.convert), Type{Array{Union{Int64, String}, 1}}, Array{Int64, 1}})
#=   46.1 ms =# precompile(Tuple{typeof(GMT.add_opt_cpt), Base.Dict{Symbol, Any}, String, Array{Symbol, 2}, Char, Int64, GMT.GMTdataset{Float64, 2}, Nothing, Bool, Bool, String, Bool}) # recompile
#=   98.0 ms =# precompile(Tuple{typeof(GMT.plt_txt_attrib!), GMT.GMTdataset{Float64, 2}, Base.Dict{Symbol, Any}, Array{String, 1}}) # recompile
#=  186.8 ms =# precompile(Tuple{typeof(GMT.finish_PS_module), Base.Dict{Symbol, Any}, Array{String, 1}, String, Bool, Bool, Bool, GMT.GMTdataset{Float64, 2}, Vararg{Any}}) # recompile
#=  109.2 ms =# precompile(Tuple{typeof(GMT.gmt), String, GMT.GMTdataset{Float64, 2}, Vararg{Any}}) # recompile
#=    7.2 ms =# precompile(Tuple{typeof(Base.map), Type{UInt8}, NTuple{32, Char}})

ianshmean · March 6, 2025, 4:25pm

Thanks for highlighting this.

I think measuring the full TTFP requires display(plot(rand(5,2)))

Also is that the full output of @trace_compile plot(rand(5,2))?

@time reports basically all of 7.5s as compilation. Maybe an @eval is needed?

i.e. @trace_compile @eval display(plot(rand(5,2)))

joa-quim · March 6, 2025, 4:52pm

Thanks for looking into this

Also is that the full output of @trace_compile plot(rand(5,2))?

It was, but doing like you say the output is way longer.

julia> @trace_compile @eval display(plot(rand(5,2)))
#=    6.2 ms =# precompile(Tuple{typeof(Base.rand), Int64, Int64})
#=    3.3 ms =# precompile(Tuple{typeof(Core.kwcall), NamedTuple{(:limit, :keepempty), Tuple{Int64, Bool}}, typeof(Base.eachsplit), String, Char})
#=    3.7 ms =# precompile(Tuple{Base.var"##eachsplit#433", Int64, Bool, typeof(Base.eachsplit), String, Char})
#=    5.2 ms =# precompile(Tuple{typeof(Core.kwcall), NamedTuple{(:limit, :keepempty), Tuple{Int64, Bool}}, typeof(Base.eachsplit), String, Function})
#=    5.0 ms =# precompile(Tuple{Base.var"##eachsplit#431", Int64, Bool, typeof(Base.eachsplit), String, Function})
#=    3.9 ms =# precompile(Tuple{Type{Base.SplitIterator{S, F} where F where S<:AbstractString}, String, Base.Fix{2, typeof(Base.isequal), Char}, Int64, Bool})
#=    6.3 ms =# precompile(Tuple{typeof(Base.getproperty), Base.SplitIterator{String, Base.Fix{2, typeof(Base.isequal), Char}}, Symbol})
#=    2.7 ms =# precompile(Tuple{typeof(Base.Iterators.product), Base.UnitRange{Int64}, Vararg{Any}})
#=    3.0 ms =# precompile(Tuple{typeof(Base.to_shape), Tuple{Base.OneTo{Int64}, Base.OneTo{Int64}}})
#=    3.3 ms =# precompile(Tuple{typeof(Core.checked_dims), Int64, Int64, Vararg{Int64}})
#=    2.2 ms =# precompile(Tuple{typeof(Base.something), Nothing, Int64, Vararg{Int64}})
#=    2.3 ms =# precompile(Tuple{typeof(Base.something), Int64})
#=    3.5 ms =# precompile(Tuple{Type{NamedTuple{(:del,), T} where T<:Tuple}, Tuple{Bool}})
#=    3.7 ms =# precompile(Tuple{Type{NamedTuple{(:opt,), T} where T<:Tuple}, Tuple{String}})
#=    3.5 ms =# precompile(Tuple{Type{NamedTuple{(:opt_B, :stalone), T} where T<:Tuple}, Tuple{String, Bool}})
#=    2.9 ms =# precompile(Tuple{Type{NamedTuple{(:secondary,), T} where T<:Tuple}, Tuple{Bool}})
#=    3.2 ms =# precompile(Tuple{Type{NamedTuple{(:x,), T} where T<:Tuple}, Tuple{Bool}})
#=    2.5 ms =# precompile(Tuple{Type{NamedTuple{(:x, :secondary), T} where T<:Tuple}, Tuple{Bool, Bool}})
#=    3.0 ms =# precompile(Tuple{Type{NamedTuple{(:y,), T} where T<:Tuple}, Tuple{Bool}})
#=    2.6 ms =# precompile(Tuple{Type{NamedTuple{(:y, :secondary), T} where T<:Tuple}, Tuple{Bool, Bool}})
#=    2.6 ms =# precompile(Tuple{Type{NamedTuple{(:z,), T} where T<:Tuple}, Tuple{Bool}})
#=    8.5 ms =# precompile(Tuple{Type{NamedTuple{(:map, :outside, :inside, :norm, :paper, :anchor, :width, :justify, :spacing, :offset), T} where T<:Tuple}, Tuple{Tuple{String, typeof(GMT.arg2str), Int64}, Tuple{String, typeof(GMT.arg2str), Int64}, Tuple{String, typeof(GMT.arg2str), Int64}, Tuple{String, typeof(GMT.arg2str), Int64}, Tuple{String, typeof(GMT.arg2str), Int64}, Tuple{String, typeof(GMT.arg2str), Int64}, Tuple{String, typeof(GMT.arg2str)}, String, String, Tuple{String, typeof(GMT.arg2str)}}})
#=    3.4 ms =# precompile(Tuple{Type{NamedTuple{(:clearance, :fill, :inner, :pen, :rounded, :shade), T} where T<:Tuple}, Tuple{String, Tuple{String, typeof(GMT.add_opt_fill)}, String, Tuple{String, typeof(GMT.add_opt_pen)}, String, String}})
#=    2.8 ms =# precompile(Tuple{Type{NamedTuple{(:first,), T} where T<:Tuple}, Tuple{Bool}})
#=   97.7 ms =# precompile(Tuple{Base.Compiler.var"#inferiterate#abstract_iteration##0"{Type{Base.Pairs{Symbol, Any, Tuple{Symbol, Symbol, Symbol}, NamedTuple{(:F, :D, :par), Tuple{String, String, Tuple{Symbol, String}}}}}, Base.Compiler.Future{Base.Compiler.CallMeta}, Base.Compiler.Future{Base.Compiler.AbstractIterationResult}}, Base.Compiler.NativeInterpreter, Base.Compiler.InferenceState})
#=    4.2 ms =# precompile(Tuple{typeof(Base.convert), Type{UInt32}, Int32})
#=   94.0 ms =# precompile(Tuple{Base.Compiler.var"#inferiterate#abstract_iteration##0"{Type{String}, Base.Compiler.Future{Base.Compiler.CallMeta}, Base.Compiler.Future{Base.Compiler.AbstractIterationResult}}, Base.Compiler.NativeInterpreter, Base.Compiler.InferenceState})
#=    2.4 ms =# precompile(Tuple{typeof(Base.Broadcast.broadcastable), Int64})
#=    3.7 ms =# precompile(Tuple{typeof(Base.split_sign), Int64})
#=    4.2 ms =# precompile(Tuple{typeof(Base.indexed_iterate), Tuple{UInt64, Bool}, Int64})
#=    3.1 ms =# precompile(Tuple{typeof(Base.indexed_iterate), Tuple{UInt64, Bool}, Int64, Int64})
#=    2.1 ms =# precompile(Tuple{typeof(Base.abs), UInt64})
#=    2.3 ms =# precompile(Tuple{typeof(Base.unsigned), UInt64})
#=    2.2 ms =# precompile(Tuple{typeof(Base.top_set_bit), UInt64})
#=    3.0 ms =# precompile(Tuple{typeof(Base.Broadcast._getindex), Tuple{Int64}, Int64})
#=    4.2 ms =# precompile(Tuple{Type{NamedTuple{(:proj4,), T} where T<:Tuple}, Tuple{Bool}})
#=    3.4 ms =# precompile(Tuple{Type{UInt32}, Int32})
#=    3.0 ms =# precompile(Tuple{Type{NamedTuple{(:isfile,), T} where T<:Tuple}, Tuple{Bool}})
#=    3.3 ms =# precompile(Tuple{typeof(Base.to_indices), Array{String, 1}, Tuple{Base.UnitRange{Int64}}})
#=    2.9 ms =# precompile(Tuple{typeof(Base.map), Base.var"#view##0#view##1"{Array{String, 1}}, Tuple{Base.UnitRange{Int64}}})
#=    2.2 ms =# precompile(Tuple{typeof(Base._maybe_reshape_parent), Array{String, 1}, Tuple{Bool}})
#=    2.1 ms =# precompile(Tuple{typeof(Base.reshape), Array{String, 1}, Base.Val{1}})
#=    3.5 ms =# precompile(Tuple{typeof(Base.unsafe_view), Array{String, 1}, Base.UnitRange{Int64}})
#=    3.4 ms =# precompile(Tuple{Type{Base.SubArray{T, N, P, I, L} where L where I where P where N where T}, Array{String, 1}, Tuple{Base.UnitRange{Int64}}})
#=    2.5 ms =# precompile(Tuple{typeof(Base.ensure_indexable), Tuple{Base.UnitRange{Int64}}})
#=    3.2 ms =# precompile(Tuple{Type{Base.SubArray{T, N, P, I, L} where L where I where P where N where T}, Base.IndexLinear, Array{String, 1}, Tuple{Base.UnitRange{Int64}}, Tuple{Bool}})
#=    2.4 ms =# precompile(Tuple{typeof(Base.compute_offset1), Array{String, 1}, Int64, Tuple{Base.UnitRange{Int64}}})
#=    4.4 ms =# precompile(Tuple{Type{Base.SubArray{String, 1, Array{String, 1}, Tuple{Base.UnitRange{Int64}}, true}}, Array{String, 1}, Tuple{Base.UnitRange{Int64}}, Int64, Int64})
#=    3.0 ms =# precompile(Tuple{typeof(Base.axes), Base.SubArray{String, 1, Array{String, 1}, Tuple{Base.UnitRange{Int64}}, true}})
#=    4.2 ms =# precompile(Tuple{typeof(Base.checkbounds), Base.SubArray{String, 1, Array{String, 1}, Tuple{Base.UnitRange{Int64}}, true}, Int64})
#=    5.1 ms =# precompile(Tuple{typeof(Base.getproperty), Base.SubArray{String, 1, Array{String, 1}, Tuple{Base.UnitRange{Int64}}, true}, Symbol})
#=    2.7 ms =# precompile(Tuple{typeof(Base._reindexlinear), Base.SubArray{String, 1, Array{String, 1}, Tuple{Base.UnitRange{Int64}}, true}, Int64})
#=    3.4 ms =# precompile(Tuple{Type{NamedTuple{(:x, :y, :meridian, :parallel, :r, :theta), T} where T<:Tuple}, NTuple{6, String}})
#=    7.7 ms =# precompile(Tuple{Type{NamedTuple{(:continuous, :net, :network, :refpoint, :ignore_hdr, :single_group, :segments, :segments_reset, :anchor), T} where T<:Tuple}, Tuple{Tuple{String, Nothing, Int64}, Tuple{String, Nothing, Int64}, Tuple{String, Nothing, Int64}, Tuple{String, Nothing, Int64}, String, String, String, String, Tuple{String, typeof(GMT.arg2str)}}})
#=   90.4 ms =# precompile(Tuple{Base.Compiler.var"#inferiterate#abstract_iteration##0"{Type{Base.Pairs{Symbol, String, Tuple{Symbol}, NamedTuple{(:C,), Tuple{String}}}}, Base.Compiler.Future{Base.Compiler.CallMeta}, Base.Compiler.Future{Base.Compiler.AbstractIterationResult}}, Base.Compiler.NativeInterpreter, Base.Compiler.InferenceState})
#=   20.2 ms =# precompile(Tuple{Base.Compiler.var"#inferiterate#abstract_iteration##0"{Type{Base.Pairs{Symbol, V, Tuple{Vararg{Symbol, N}}, NamedTuple{names, T}} where T<:Tuple{Vararg{Any, N}} where names where N where V}, Base.Compiler.Future{Base.Compiler.CallMeta}, Base.Compiler.Future{Base.Compiler.AbstractIterationResult}}, Base.Compiler.NativeInterpreter, Base.Compiler.InferenceState})
#=   85.3 ms =# precompile(Tuple{Base.Compiler.var"#inferiterate_2arg#abstract_iteration##1"{Base.Compiler.InferenceLattice{Base.Compiler.ConditionalsLattice{Base.Compiler.PartialsLattice{Base.Compiler.ConstsLattice}}}, Array{Any, 1}, Array{Base.Compiler.CallMeta, 1}, Type{Base.Pairs{Symbol, V, Tuple{Vararg{Symbol, N}}, NamedTuple{names, T}} where T<:Tuple{Vararg{Any, N}} where names where N where V}, Base.Compiler.Future{Base.Compiler.AbstractIterationResult}}, Base.Compiler.NativeInterpreter, Base.Compiler.InferenceState})
#=    3.1 ms =# precompile(Tuple{Type{NamedTuple{(:Vd,), T} where T<:Tuple}, Tuple{Int64}})
#=    8.4 ms =# precompile(Tuple{Type{NamedTuple{(:map, :outside, :inside, :norm, :paper, :anchor, :width, :size, :justify, :offset), T} where T<:Tuple}, Tuple{Tuple{String, typeof(GMT.arg2str), Int64}, Tuple{String, Nothing, Int64}, Tuple{String, Nothing, Int64}, Tuple{String, typeof(GMT.arg2str), Int64}, Tuple{String, typeof(GMT.arg2str), Int64}, Tuple{String, typeof(GMT.arg2str), Int64}, String, String, String, Tuple{String, typeof(GMT.arg2str)}}})
#=    3.7 ms =# precompile(Tuple{Type{NamedTuple{(:margin, :round, :concave, :convex), T} where T<:Tuple}, NTuple{4, String}})
#=    5.1 ms =# precompile(Tuple{Type{NamedTuple{(:away, :corners, :shift, :line), T} where T<:Tuple}, Tuple{Tuple{String, Nothing, Int64}, Tuple{String, Nothing, Int64}, String, Tuple{String, typeof(GMT.add_opt_pen)}}})
#=    3.9 ms =# precompile(Tuple{Type{NamedTuple{(:angle, :Angle, :font, :justify, :region_justify, :header, :label, :rec_number, :text, :zvalues), T} where T<:Tuple}, Tuple{String, String, Tuple{String, typeof(GMT.font)}, Vararg{String, 7}}})
#=    2.7 ms =# precompile(Tuple{Type{NamedTuple{(:expand,), T} where T<:Tuple}, Tuple{Bool}})
#=   89.5 ms =# precompile(Tuple{Base.Compiler.var"#inferiterate#abstract_iteration##0"{Type{Base.Pairs{Symbol, String, Tuple{Symbol}, NamedTuple{(:J,), Tuple{String}}}}, Base.Compiler.Future{Base.Compiler.CallMeta}, Base.Compiler.Future{Base.Compiler.AbstractIterationResult}}, Base.Compiler.NativeInterpreter, Base.Compiler.InferenceState})
#=    8.7 ms =# precompile(Tuple{Type{NamedTuple{(:fixed_pt, :back, :back_geocentric, :forward, :forward_geocentric, :orientation, :orientation_geocentric, :unit, :var_pt), T} where T<:Tuple}, Tuple{Tuple{String, typeof(GMT.arg2str)}, Tuple{String, Nothing, Int64}, Tuple{String, Nothing, Int64}, Tuple{String, Nothing, Int64}, Tuple{String, Nothing, Int64}, Tuple{String, Nothing, Int64}, Tuple{String, Nothing, Int64}, String, String}})
#=    4.6 ms =# precompile(Tuple{Type{NamedTuple{(:fixed_pt, :accumulated, :incremental, :unit, :var_pt), T} where T<:Tuple}, Tuple{Tuple{String, typeof(GMT.arg2str), Int64}, Vararg{String, 4}}})
#=    3.5 ms =# precompile(Tuple{Type{NamedTuple{(:unit, :cartesian, :project, :fractional_pt), T} where T<:Tuple}, NTuple{4, String}})
#=   19.8 ms =# precompile(Tuple{Base.Compiler.var"#inferiterate#abstract_iteration##0"{Type{Base.Pairs{Symbol, T, Tuple{Symbol, Symbol}, NamedTuple{(:R, :J), T}} where T<:Tuple{Union{Array{Any, 1}, Array{Float64, 1}}, String} where T}, Base.Compiler.Future{Base.Compiler.CallMeta}, Base.Compiler.Future{Base.Compiler.AbstractIterationResult}}, Base.Compiler.NativeInterpreter, Base.Compiler.InferenceState})
#=   72.2 ms =# precompile(Tuple{Base.Compiler.var"#inferiterate_2arg#abstract_iteration##1"{Base.Compiler.InferenceLattice{Base.Compiler.ConditionalsLattice{Base.Compiler.PartialsLattice{Base.Compiler.ConstsLattice}}}, Array{Any, 1}, Array{Base.Compiler.CallMeta, 1}, Type{Base.Pairs{Symbol, T, Tuple{Symbol, Symbol}, NamedTuple{(:R, :J), T}} where T<:Tuple{Union{Array{Any, 1}, Array{Float64, 1}}, String} where T}, Base.Compiler.Future{Base.Compiler.AbstractIterationResult}}, Base.Compiler.NativeInterpreter, Base.Compiler.InferenceState})
#=    4.8 ms =# precompile(Tuple{typeof(Base._array_for), Type{Tuple{String, GMT.var"#arg2str", Int64}}, Base.HasShape{1}, Tuple{Base.OneTo{Int64}}}) # recompile
#=   17.0 ms =# precompile(Tuple{typeof(Base.collect_to_with_first!), Array{Tuple{String, GMT.var"#arg2str", Int64}, 1}, Tuple{String, GMT.var"#arg2str", Int64}, Base.Generator{Base.UnitRange{Int64}, Base.var"#_ntuple##0#_ntuple##1"{Base.Compiler.var"#tuple_tfunc##0#tuple_tfunc##1"{Array{Any, 1}}}}, Int64})
#=   31.8 ms =# precompile(Tuple{typeof(Base.setindex_widen_up_to), Array{Tuple{String, GMT.var"#arg2str", Int64}, 1}, Tuple{String, GMT.var"#arg2str"}, Int64})
#=    9.5 ms =# precompile(Tuple{typeof(Base.collect_to!), Array{Tuple{String, GMT.var"#arg2str", Vararg{Int64}}, 1}, Base.Generator{Base.UnitRange{Int64}, Base.var"#_ntuple##0#_ntuple##1"{Base.Compiler.var"#tuple_tfunc##0#tuple_tfunc##1"{Array{Any, 1}}}}, Int64, Int64})
#=   19.3 ms =# precompile(Tuple{typeof(Base.setindex_widen_up_to), Array{Tuple{String, GMT.var"#arg2str", Vararg{Int64}}, 1}, String, Int64})
#=   12.1 ms =# precompile(Tuple{Type{NamedTuple{(:map, :outside, :inside, :norm, :paper, :anchor, :length, :size, :justify, :triangles, :horizontal, :move_annot, :neon, :nan, :offset), T} where T<:Tuple}, Tuple{Tuple{String, typeof(GMT.arg2str), Int64}, Tuple{String, typeof(GMT.arg2str), Int64}, Tuple{String, typeof(GMT.arg2str), Int64}, Tuple{String, typeof(GMT.arg2str), Int64}, Tuple{String, typeof(GMT.arg2str), Int64}, Tuple{String, typeof(GMT.arg2str), Int64}, Tuple{String, typeof(GMT.arg2str)}, Tuple{String, typeof(GMT.arg2str)}, String, String, String, String, String, String, Tuple{String, typeof(GMT.arg2str)}}})
#=    3.2 ms =# precompile(Tuple{Type{NamedTuple{(:range, :gap), T} where T<:Tuple}, Tuple{String, String}})
#=    3.5 ms =# precompile(Tuple{Type{NamedTuple{(:nested, :Vd), T} where T<:Tuple}, Tuple{Bool, Int64}})
#=    3.7 ms =# precompile(Tuple{Type{NamedTuple{(:W, :A, :Vd), T} where T<:Tuple}, Tuple{Float64, String, Int64}})
#=   93.3 ms =# precompile(Tuple{Base.Compiler.var"#inferiterate#abstract_iteration##0"{Type{Base.Pairs{Symbol, Any, Tuple{Symbol, Symbol, Symbol}, NamedTuple{(:W, :A, :Vd), Tuple{Float64, String, Int64}}}}, Base.Compiler.Future{Base.Compiler.CallMeta}, Base.Compiler.Future{Base.Compiler.AbstractIterationResult}}, Base.Compiler.NativeInterpreter, Base.Compiler.InferenceState})
#=    3.6 ms =# precompile(Tuple{Type{NamedTuple{(:f, :s), T} where T<:Tuple}, Tuple{String, String}})
#=   91.8 ms =# precompile(Tuple{Base.Compiler.var"#inferiterate#abstract_iteration##0"{Type{Base.Pairs{Symbol, String, Tuple{Symbol, Symbol}, NamedTuple{(:f, :s), Tuple{String, String}}}}, Base.Compiler.Future{Base.Compiler.CallMeta}, Base.Compiler.Future{Base.Compiler.AbstractIterationResult}}, Base.Compiler.NativeInterpreter, Base.Compiler.InferenceState})
#=   15.7 ms =# precompile(Tuple{Core.GeneratedFunctionStub, UInt64, Method, Any, Vararg{Any}}) # recompile
#=    3.5 ms =# precompile(Tuple{Type{NamedTuple{(:clip, :first), T} where T<:Tuple}, Tuple{String, Bool}})
#=    2.6 ms =# precompile(Tuple{Type{NamedTuple{(:anchor,), T} where T<:Tuple}, Tuple{String}})
#=    3.4 ms =# precompile(Tuple{Type{NamedTuple{(:pos, :B, :Vd), T} where T<:Tuple}, Tuple{NamedTuple{(:anchor,), Tuple{String}}, String, Int64}})
#=   91.7 ms =# precompile(Tuple{Base.Compiler.var"#inferiterate#abstract_iteration##0"{Type{Base.Pairs{Symbol, Any, Tuple{Symbol, Symbol, Symbol}, NamedTuple{(:pos, :B, :Vd), Tuple{NamedTuple{(:anchor,), Tuple{String}}, String, Int64}}}}, Base.Compiler.Future{Base.Compiler.CallMeta}, Base.Compiler.Future{Base.Compiler.AbstractIterationResult}}, Base.Compiler.NativeInterpreter, Base.Compiler.InferenceState})
#=   92.1 ms =# precompile(Tuple{Base.Compiler.var"#inferiterate#abstract_iteration##0"{Type{Base.Pairs{Symbol, Int64, Tuple{Symbol}, NamedTuple{(:Vd,), Tuple{Int64}}}}, Base.Compiler.Future{Base.Compiler.CallMeta}, Base.Compiler.Future{Base.Compiler.AbstractIterationResult}}, Base.Compiler.NativeInterpreter, Base.Compiler.InferenceState})
#=    4.0 ms =# precompile(Tuple{Type{NamedTuple{(:O,), T} where T<:Tuple}, Tuple{Bool}})
#=    3.3 ms =# precompile(Tuple{Type{NamedTuple{(:default, :map, :O), T} where T<:Tuple}, Tuple{String, Bool, Bool}})
#=   87.8 ms =# precompile(Tuple{Base.Compiler.var"#inferiterate#abstract_iteration##0"{Type{Base.Pairs{Symbol, String, Tuple{Symbol, Symbol}, NamedTuple{(:T, :f), Tuple{String, String}}}}, Base.Compiler.Future{Base.Compiler.CallMeta}, Base.Compiler.Future{Base.Compiler.AbstractIterationResult}}, Base.Compiler.NativeInterpreter, Base.Compiler.InferenceState})
#=   19.0 ms =# precompile(Tuple{typeof(Base.Compiler.EscapeAnalysis.escape_builtin!), typeof(Core.finalizer), Base.Compiler.EscapeAnalysis.AnalysisState{Base.Compiler.GetNativeEscapeCache{Base.Compiler.WorldView{Base.Compiler.InternalCodeCache}}, Base.Compiler.PartialsLattice{Base.Compiler.ConstsLattice}}, Int64, Array{Any, 1}})
#=    2.9 ms =# precompile(Tuple{Type{NamedTuple{(:gdataset,), T} where T<:Tuple}, Tuple{Bool}})
#=   96.5 ms =# precompile(Tuple{Base.Compiler.var"#inferiterate#abstract_iteration##0"{Type{Base.Pairs{Symbol, String, Tuple{Symbol}, NamedTuple{(:R,), Tuple{String}}}}, Base.Compiler.Future{Base.Compiler.CallMeta}, Base.Compiler.Future{Base.Compiler.AbstractIterationResult}}, Base.Compiler.NativeInterpreter, Base.Compiler.InferenceState})
#=    3.2 ms =# precompile(Tuple{Type{NamedTuple{(:crop2cutline, :invert), T} where T<:Tuple}, Tuple{String, String}})
#=    3.5 ms =# precompile(Tuple{typeof(Base.:(==)), Function, Function})
#=    2.9 ms =# precompile(Tuple{Type{NamedTuple{(:flags, :I), T} where T<:Tuple}, Tuple{UInt8, Bool}})
#=    3.6 ms =# precompile(Tuple{Type{Ptr{Base.Cstring}}, Ptr{Nothing}})
#=    4.6 ms =# precompile(Tuple{Type{NamedTuple{(:dest, :gdataset, :save), T} where T<:Tuple}, Tuple{String, Bool, String}})
#=    3.4 ms =# precompile(Tuple{typeof(Base.:(+)), Vararg{Int64, 4}})
#=   90.9 ms =# precompile(Tuple{Base.Compiler.var"#inferiterate#abstract_iteration##0"{Type{Base.Pairs{Symbol, Bool, Tuple{Symbol}, NamedTuple{(:gdataset,), Tuple{Bool}}}}, Base.Compiler.Future{Base.Compiler.CallMeta}, Base.Compiler.Future{Base.Compiler.AbstractIterationResult}}, Base.Compiler.NativeInterpreter, Base.Compiler.InferenceState})
#=   89.6 ms =# precompile(Tuple{Base.Compiler.var"#inferiterate#abstract_iteration##0"{Type{Base.Pairs{Symbol, NTuple{4, Float64}, Tuple{Symbol}, NamedTuple{(:R,), Tuple{NTuple{4, Float64}}}}}, Base.Compiler.Future{Base.Compiler.CallMeta}, Base.Compiler.Future{Base.Compiler.AbstractIterationResult}}, Base.Compiler.NativeInterpreter, Base.Compiler.InferenceState})
#=    3.4 ms =# precompile(Tuple{Type{NamedTuple{(:centroid,), T} where T<:Tuple}, Tuple{Bool}})
#=   97.4 ms =# precompile(Tuple{Base.Compiler.var"#inferiterate#abstract_iteration##0"{Type{Base.Pairs{Symbol, Bool, Tuple{Symbol}, NamedTuple{(:centroid,), Tuple{Bool}}}}, Base.Compiler.Future{Base.Compiler.CallMeta}, Base.Compiler.Future{Base.Compiler.AbstractIterationResult}}, Base.Compiler.NativeInterpreter, Base.Compiler.InferenceState})
#=    3.5 ms =# precompile(Tuple{Type{NamedTuple{(:buffer, :holes, :intersection, :dateline, :union), T} where T<:Tuple}, NTuple{5, String}})
#=    3.7 ms =# precompile(Tuple{Type{NamedTuple{(:amax, :dmax, :cmax, :Cmax, :fact, :ortho), T} where T<:Tuple}, NTuple{6, String}})
#=    3.3 ms =# precompile(Tuple{Type{NamedTuple{(:all, :start, :has_feature, :add_IDs, :individual), T} where T<:Tuple}, NTuple{5, String}})
#=    3.1 ms =# precompile(Tuple{Type{NamedTuple{(:x,), T} where T<:Tuple}, Tuple{String}})
#=    4.1 ms =# precompile(Tuple{Type{NamedTuple{(:angle, :font), T} where T<:Tuple}, Tuple{String, Tuple{String, typeof(GMT.font)}}})
#=   96.6 ms =# precompile(Tuple{Base.Compiler.var"#inferiterate#abstract_iteration##0"{Type{Base.Pairs{Symbol, Any, Tuple{Symbol, Symbol, Symbol}, NamedTuple{(:J, :C, :F), Tuple{String, Bool, Bool}}}}, Base.Compiler.Future{Base.Compiler.CallMeta}, Base.Compiler.Future{Base.Compiler.AbstractIterationResult}}, Base.Compiler.NativeInterpreter, Base.Compiler.InferenceState})
#=    3.7 ms =# precompile(Tuple{Type{NamedTuple{(:Q, :o), T} where T<:Tuple}, Tuple{Bool, String}})
#=  101.7 ms =# precompile(Tuple{Base.Compiler.var"#inferiterate#abstract_iteration##0"{Type{Base.Pairs{Symbol, Any, Tuple{Symbol, Symbol}, NamedTuple{(:Q, :o), Tuple{Bool, String}}}}, Base.Compiler.Future{Base.Compiler.CallMeta}, Base.Compiler.Future{Base.Compiler.AbstractIterationResult}}, Base.Compiler.NativeInterpreter, Base.Compiler.InferenceState})
#= 3094.9 ms =# precompile(Tuple{typeof(GMT.plot), Array{Float64, 2}})
#=    2.6 ms =# precompile(Tuple{typeof(Base.mapreducedim!), Function, Function, Array{Tuple{Float64, Float64}, 2}, Array{Float64, 2}})
#=   17.5 ms =# precompile(Tuple{typeof(Base.convert), Type{Array{Union{Int64, String}, 1}}, Array{Int64, 1}})
#=   49.8 ms =# precompile(Tuple{typeof(GMT.add_opt_cpt), Base.Dict{Symbol, Any}, String, Array{Symbol, 2}, Char, Int64, GMT.GMTdataset{Float64, 2}, Nothing, Bool, Bool, String, Bool}) # recompile
#=  104.5 ms =# precompile(Tuple{typeof(GMT.plt_txt_attrib!), GMT.GMTdataset{Float64, 2}, Base.Dict{Symbol, Any}, Array{String, 1}}) # recompile
#=  190.2 ms =# precompile(Tuple{typeof(GMT.finish_PS_module), Base.Dict{Symbol, Any}, Array{String, 1}, String, Bool, Bool, Bool, GMT.GMTdataset{Float64, 2}, Vararg{Any}}) # recompile
#=  132.1 ms =# precompile(Tuple{typeof(GMT.gmt), String, GMT.GMTdataset{Float64, 2}, Vararg{Any}}) # recompile
#=    7.4 ms =# precompile(Tuple{typeof(Base.map), Type{UInt8}, NTuple{32, Char}})
#=    5.7 ms =# precompile(Tuple{Type{Base.IOContext{IO_t} where IO_t<:IO}, Base.IOContext{Base.TTY}, Pair{Symbol, Bool}, Pair{Symbol, Module}})
#=    2.4 ms =# precompile(Tuple{typeof(Base.print), Base.IOContext{Base.TTY}, String})
#=    2.7 ms =# precompile(Tuple{typeof(Base.write), Base.IOContext{Base.TTY}, String})
#=    6.1 ms =# precompile(Tuple{typeof(Core.kwcall), NamedTuple{(:init,), Tuple{Base.IOContext{Base.TTY}}}, typeof(Base.foldl), Type, Base.Dict{Symbol, Any}})
#=   27.5 ms =# precompile(Tuple{typeof(Base.mapfoldl_impl), typeof(Base.identity), Type{Base.IOContext{IO_t} where IO_t<:IO}, Base.IOContext{Base.TTY}, Base.Dict{Symbol, Any}})
#=    2.1 ms =# precompile(Tuple{typeof(REPL.show_repl), IO, Base.Multimedia.MIME{:var"text/plain"}, Any}) # recompile
#=    5.6 ms =# precompile(Tuple{typeof(Base.show), Base.IOContext{REPL.LimitIO{Base.TTY}}, Base.Multimedia.MIME{:var"text/plain"}, Nothing})
nothing#=    2.4 ms =# precompile(Tuple{typeof(Base.println), Base.IOContext{Base.TTY}})

ianshmean · March 6, 2025, 6:33pm

Looking into this, PrecompileTools.@precompile_workload is broken on 1.12+ currently.

This is on the milestone for 1.12 so should be fixed before 1.12 is released.

github.com/JuliaLang/julia

snoop_inference is broken on latest after stackless inference change

opened 05:33PM - 11 Oct 24 UTC

NHDaly

compiler:precompilation caching observability

We should be able to restore basically the old behavior with the new stack. >… I wasn't certain how to maintain the old code, since it was working with incomplete and inaccurate information available. Now all required information is available in `function typeinf(interp::AbstractInterpreter, frame::InferenceState)`, so this could be reimplemented there in some form. _Originally posted by @vtjnash in https://github.com/JuliaLang/julia/pull/55575#discussion_r1795702974_

ianshmean · March 6, 2025, 6:35pm

But I don’t think that explains the regression from 1.10 → 1.11

joa-quim · March 25, 2025, 6:54pm

And it keeps getting worst with nightly. Now it takes > 10 s instead of the previous ~7.6 s for the TTFP (remember, same takes ~2.7 sec in Julia 1.10)

  | | |_| | | | (_| |  |  Version 1.13.0-DEV.283 (2025-03-23)
 _/ |\__'_|_|_|\__'_|  |  Commit c75cf3ff62 (2 days old master)
|__/                   |

julia> @time using GMT
  1.440747 seconds (2.15 M allocations: 112.428 MiB, 15.21% gc time, 6.32% compilation time)

julia> @time @eval plot(rand(5,2))
 10.664554 seconds (33.57 M allocations: 1.732 GiB, 7.28% gc time, 99.97% compilation time: 13% of which was recompilation)

juliohm · March 25, 2025, 7:08pm

Another evidence of the regression from v1.10 (LTS) to v1.11:

The slowdown is particularly visible on Windows.

Topic		Replies	Views
DEV version slower again General Usage	2	242	November 14, 2022
Large performance regression in nightly build Performance	6	744	February 25, 2022
Taking TTFX seriously: Can we make common packages faster to load and use Performance ttfp	125	11291	June 20, 2022
Help building MWE for 1.8 latency regression Performance	11	931	November 2, 2022
Is compile time significantly slower in 0.6? Internals & Design	17	3088	April 6, 2017

Slower times to TTFX for GMT in 1.11 and even more in nightly

Related topics