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

General Usage
1

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