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

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}})
9 Likes

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)))

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}})

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.

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

1 Like

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)
1 Like

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

The slowdown is particularly visible on Windows.