Add compilation & recompilation time to time_imports macro

[IanButterworth]

Adds report to @time_imports if any import step included compilation time, and if any of that was recompilation.
Observes the nesting, so times stack like the existing import times do.

Worth noting that the overall times reported are similar to @time so the overhead seems insignificant

[giordano]

If you're wondering why OpenSpecFun_jll.jl has 100% of recompilation time, it's because of Graphics.jl. In a fresh session:

julia> @time_imports using OpenSpecFun_jll
     29.1 ms    ┌ Preferences
     39.6 ms  ┌ JLLWrappers 23.32% compilation time
     47.0 ms  OpenSpecFun_jll 31.20% compilation time

In another fresh session:

julia> @time_imports using Graphics
      0.8 ms  ┌ NaNMath
     31.9 ms  ┌ FixedPointNumbers
      0.4 ms  ┌ Reexport
     95.8 ms  ┌ ColorTypes 3.41% compilation time
     62.4 ms  ┌ Colors
    210.6 ms  Graphics 8.62% compilation time

julia> @time_imports using OpenSpecFun_jll
     12.5 ms    ┌ Preferences
     77.4 ms  ┌ JLLWrappers 82.83% compilation time (56% recompilation)
    194.9 ms  OpenSpecFun_jll 92.46% compilation time (83% recompilation)

CC: @timholy.

[IanButterworth]

Part of the idea for adding the recompilation report is to highlight when the SnoopCompile tooling would be worth getting out. So in that spirit

julia> using SnoopCompileCore

julia> invalidations = @snoopr using Graphics

julia> using SnoopCompile

julia> trees = invalidation_trees(invalidations)
3-element Vector{SnoopCompile.MethodInvalidations}:
 inserting (::Type{<:FixedPointNumbers.FixedPoint})(x::AbstractChar) in FixedPointNumbers at /home/ian/.julia/packages/FixedPointNumbers/HAGk2/src/FixedPointNumbers.jl:60 invalidated:
   backedges: 1: superseding (::Type{T})(x::AbstractChar) where T<:Union{AbstractChar, Number} in Base at char.jl:50 with MethodInstance for (::Type{K} where K<:Char)(::Char) (2 children)
   35 mt_cache

 inserting reduce_first(::typeof(Base.add_sum), x::FixedPointNumbers.FixedPoint) in FixedPointNumbers at /home/ian/.julia/packages/FixedPointNumbers/HAGk2/src/FixedPointNumbers.jl:295 invalidated:
   backedges: 1: superseding reduce_first(::typeof(Base.add_sum), x) in Base at reduce.jl:394 with MethodInstance for Base.reduce_first(::typeof(Base.add_sum), ::Any) (20 children)

 inserting convert(::Type{T}, x::ColorTypes.Gray24) where T<:Real in ColorTypes at /home/ian/.julia/packages/ColorTypes/6m8P7/src/conversions.jl:114 invalidated:
   backedges: 1: superseding convert(::Type{Union{}}, x) in Base at essentials.jl:280 with MethodInstance for convert(::Core.TypeofBottom, ::Any) (3562 children)
   32 mt_cache

---

Edit: Oh, right.. this is what #45051 is trying to fix

[giordano]

Edit: Oh, right.. this is what #45051 is trying to fix

Right, with that PR on top of this one I get

julia> @time_imports using VideoIO
      1.3 ms      ┌ Zlib_jll
     19.2 ms          ┌ Preferences
     20.1 ms        ┌ JLLWrappers
     23.2 ms      ┌ Libiconv_jll 7.94% compilation time
     39.5 ms    ┌ XML2_jll 37.85% compilation time
     41.3 ms  ┌ Gettext_jll 36.20% compilation time
      1.6 ms  ┌ OpenSSL_jll
      0.5 ms      ┌ PCRE_jll
      0.4 ms      ┌ Libffi_jll
      5.3 ms    ┌ Glib_jll
      0.4 ms      ┌ Bzip2_jll
      1.2 ms    ┌ FreeType2_jll
      0.5 ms    ┌ libpng_jll
      0.4 ms    ┌ Graphite2_jll
      0.4 ms      ┌ Expat_jll
      0.4 ms      ┌ LZO_jll
      0.4 ms      ┌ Pixman_jll
      0.2 ms        ┌ Libuuid_jll
      3.5 ms      ┌ Fontconfig_jll 60.80% compilation time
      1.7 ms      ┌ Cairo_jll
      8.4 ms    ┌ HarfBuzz_jll 25.33% compilation time
      0.5 ms    ┌ FriBidi_jll
     18.5 ms  ┌ libass_jll 11.50% compilation time
      0.8 ms    ┌ Compat
      0.3 ms    ┌ NaNMath
      0.3 ms      ┌ Adapt
     31.2 ms      ┌ OffsetArrays
     33.1 ms    ┌ PaddedViews
     20.3 ms    ┌ FixedPointNumbers
     49.7 ms      ┌ ChainRulesCore
     50.6 ms    ┌ ChangesOfVariables
      6.1 ms    ┌ AbstractFFTs
      1.7 ms    ┌ OpenLibm_jll
      1.3 ms      ┌ StackViews
      1.2 ms      ┌ MappedArrays
      3.6 ms    ┌ MosaicViews
      0.4 ms    ┌ InverseFunctions
      0.2 ms    ┌ Reexport
      2.4 ms    ┌ DocStringExtensions 69.27% compilation time
     87.8 ms      ┌ ColorTypes 3.75% compilation time
     77.1 ms      ┌ Colors
    167.7 ms    ┌ Graphics 1.96% compilation time
      2.8 ms    ┌ IrrationalConstants
      0.3 ms    ┌ TensorCore
      0.6 ms      ┌ LogExpFunctions
      0.6 ms      ┌ OpenSpecFun_jll
     10.5 ms    ┌ SpecialFunctions
     56.0 ms    ┌ ColorVectorSpace 5.68% compilation time
    547.3 ms  ┌ ImageCore 1.49% compilation time
      0.7 ms  ┌ Opus_jll
      0.3 ms  ┌ Requires
      0.4 ms    ┌ Ogg_jll
      0.8 ms    ┌ x265_jll
     18.5 ms    ┌ libfdk_aac_jll
      0.7 ms    ┌ x264_jll
      0.7 ms    ┌ libvorbis_jll
      0.5 ms      ┌ LAME_jll
      5.7 ms    ┌ FFMPEG_jll
     28.6 ms  ┌ FFMPEG
      3.0 ms  ┌ ProgressMeter
     53.3 ms  ┌ FileIO 9.30% compilation time (21% recompilation)
    841.0 ms  VideoIO 7.79% compilation time (2% recompilation)

while with this PR only I have

julia> @time_imports using VideoIO
      1.7 ms      ┌ Zlib_jll
     20.2 ms          ┌ Preferences
     21.1 ms        ┌ JLLWrappers
     24.4 ms      ┌ Libiconv_jll 8.50% compilation time
     42.7 ms    ┌ XML2_jll 37.68% compilation time
     44.6 ms  ┌ Gettext_jll 36.07% compilation time
      1.4 ms  ┌ OpenSSL_jll
      0.5 ms      ┌ PCRE_jll
      0.4 ms      ┌ Libffi_jll
      5.3 ms    ┌ Glib_jll
      0.5 ms      ┌ Bzip2_jll
      1.3 ms    ┌ FreeType2_jll
      0.5 ms    ┌ libpng_jll
      0.5 ms    ┌ Graphite2_jll
      0.4 ms      ┌ Expat_jll
      0.4 ms      ┌ LZO_jll
      0.4 ms      ┌ Pixman_jll
      0.2 ms        ┌ Libuuid_jll
      3.7 ms      ┌ Fontconfig_jll 56.68% compilation time
      1.4 ms      ┌ Cairo_jll
      8.4 ms    ┌ HarfBuzz_jll 24.97% compilation time
      0.6 ms    ┌ FriBidi_jll
     18.7 ms  ┌ libass_jll 11.22% compilation time
      0.8 ms    ┌ Compat
      0.3 ms    ┌ NaNMath
      0.3 ms      ┌ Adapt
     32.0 ms      ┌ OffsetArrays
     33.9 ms    ┌ PaddedViews
     20.3 ms    ┌ FixedPointNumbers
     55.1 ms      ┌ ChainRulesCore
     56.0 ms    ┌ ChangesOfVariables
      6.0 ms    ┌ AbstractFFTs
      1.8 ms    ┌ OpenLibm_jll
      1.4 ms      ┌ StackViews
      1.3 ms      ┌ MappedArrays
      3.7 ms    ┌ MosaicViews
      0.5 ms    ┌ InverseFunctions
      0.2 ms    ┌ Reexport
      2.2 ms    ┌ DocStringExtensions 68.65% compilation time
     93.1 ms      ┌ ColorTypes 3.63% compilation time
     78.6 ms      ┌ Colors
    174.5 ms    ┌ Graphics 1.94% compilation time
      3.3 ms    ┌ IrrationalConstants
      0.3 ms    ┌ TensorCore
      0.6 ms      ┌ LogExpFunctions
    104.2 ms      ┌ OpenSpecFun_jll 99.34% compilation time (100% recompilation)
    130.7 ms    ┌ SpecialFunctions 79.20% compilation time (100% recompilation)
     69.8 ms    ┌ ColorVectorSpace 4.63% compilation time
    725.1 ms  ┌ ImageCore 15.40% compilation time (93% recompilation)
      0.7 ms  ┌ Opus_jll
      0.3 ms  ┌ Requires
      0.4 ms    ┌ Ogg_jll
      0.8 ms    ┌ x265_jll
      0.4 ms    ┌ libfdk_aac_jll
      0.6 ms    ┌ x264_jll
      0.7 ms    ┌ libvorbis_jll
      0.5 ms      ┌ LAME_jll
      5.3 ms    ┌ FFMPEG_jll
      9.7 ms  ┌ FFMPEG
      3.0 ms  ┌ ProgressMeter
     56.7 ms  ┌ FileIO 8.55% compilation time (22% recompilation)
   1025.1 ms  VideoIO 16.61% compilation time (61% recompilation)

There is left only some recompilation induced in FileIO, but it contributes little to overall loading time of VideoIO.

I guess this is a good showcase of the proposed functionality 🙂

[oschulz]

Could the be backported to Julia v1.8?

@time_imports has already started to have an impact, encouraging package maintainers to lighten/restructure packages and providing metrics to help with it (see e.g. discussions in JuliaArrays/ArrayInterface.jl#211, cjdoris/LogarithmicNumbers.jl#11). This improvement could help every more in that regard. I know v1.8 is already far advanced in the Beta cycle, but I would think backporting this would be risk/breakage-free.

CC @IanButterworth

[KristofferC]

Just run it on nightly? The numbers you get should be fairly the same.

[oschulz]

Just run it on nightly? The numbers you get should be fairly the same.

True, but having it on 1.8 might make package maintainers use it more ... :-)