Add compilation & recompilation time to time_imports macro (#45064)

NEWS.md

@@ -54,6 +54,7 @@ Library changes
 * Predicate function negation `!f` now returns a composed function `(!) ∘ f` instead of an anonymous function ([#44752]).
 * `RoundFromZero` now works for non-`BigFloat` types ([#41246]).
 * `@time` now separates out % time spent recompiling invalidated methods ([#45015]).
+* `@time_imports` now shows any compilation and recompilation time percentages per import ([#45064]).
 
 
 Standard library changes

base/loading.jl

@@ -890,7 +890,13 @@ const TIMING_IMPORTS = Threads.Atomic{Int}(0)
 # returns `false` if the module isn't known to be precompilable
 # returns the set of modules restored if the cache load succeeded
 @constprop :none function _require_search_from_serialized(pkg::PkgId, sourcepath::String, depth::Int = 0)
-    t_before = time_ns()
+    timing_imports = TIMING_IMPORTS[] > 0
+    try
+    if timing_imports
+        t_before = time_ns()
+        cumulative_compile_timing(true)
+        t_comp_before = cumulative_compile_time_ns()
+    end
     paths = find_all_in_cache_path(pkg)
     for path_to_try in paths::Vector{String}
         staledeps = stale_cachefile(sourcepath, path_to_try)
@@ -922,17 +928,29 @@ const TIMING_IMPORTS = Threads.Atomic{Int}(0)
         if isa(restored, Exception)
             @debug "Deserialization checks failed while attempting to load cache from $path_to_try" exception=restored
         else
-            if TIMING_IMPORTS[] > 0
+            if timing_imports
                 elapsed = round((time_ns() - t_before) / 1e6, digits = 1)
+                comp_time, recomp_time = cumulative_compile_time_ns() .- t_comp_before
                 tree_prefix = depth == 0 ? "" : "  "^(depth-1)*"┌ "
                 print(lpad(elapsed, 9), " ms  ")
                 printstyled(tree_prefix, color = :light_black)
-                println(pkg.name)
+                print(pkg.name)
+                if comp_time > 0
+                    printstyled(" ", Ryu.writefixed(Float64(100 * comp_time / (elapsed * 1e6)), 2), "% compilation time", color = Base.info_color())
+                end
+                if recomp_time > 0
+                    perc = Float64(100 * recomp_time / comp_time)
+                    printstyled(" (", perc < 1 ? "<1" : Ryu.writefixed(perc, 0), "% recompilation)", color = Base.warn_color())
+                end
+                println()
             end
             return restored
         end
     end
     return !isempty(paths)
+    finally
+        timing_imports && cumulative_compile_timing(false)
+    end
 end
 
 # to synchronize multiple tasks trying to import/using something

stdlib/InteractiveUtils/src/macros.jl

@@ -354,24 +354,34 @@ See also: [`code_native`](@ref), [`@code_llvm`](@ref), [`@code_typed`](@ref) and
     @time_imports
 
 A macro to execute an expression and produce a report of any time spent importing packages and their
-dependencies.
+dependencies. Any compilation time will be reported as a percentage, and how much of which was recompilation, if any.
 
 If a package's dependencies have already been imported either globally or by another dependency they will
 not appear under that package and the package will accurately report a faster load time than if it were to
 be loaded in isolation.
 
+!!! compat "Julia 1.9"
+    Reporting of any compilation and recompilation time was added in Julia 1.9
+
 ```julia-repl
 julia> @time_imports using CSV
-      3.5 ms    ┌ IteratorInterfaceExtensions
-     27.4 ms  ┌ TableTraits
-    614.0 ms  ┌ SentinelArrays
-    138.6 ms  ┌ Parsers
-      2.7 ms  ┌ DataValueInterfaces
-      3.4 ms    ┌ DataAPI
-     59.0 ms  ┌ WeakRefStrings
-     35.4 ms  ┌ Tables
-     49.5 ms  ┌ PooledArrays
-    972.1 ms  CSV
+      0.4 ms    ┌ IteratorInterfaceExtensions
+     11.1 ms  ┌ TableTraits 84.88% compilation time
+    145.4 ms  ┌ SentinelArrays 66.73% compilation time
+     42.3 ms  ┌ Parsers 19.66% compilation time
+      4.1 ms  ┌ Compat
+      8.2 ms  ┌ OrderedCollections
+      1.4 ms    ┌ Zlib_jll
+      2.3 ms    ┌ TranscodingStreams
+      6.1 ms  ┌ CodecZlib
+      0.3 ms  ┌ DataValueInterfaces
+     15.2 ms  ┌ FilePathsBase 30.06% compilation time
+      9.3 ms    ┌ InlineStrings
+      1.5 ms    ┌ DataAPI
+     31.4 ms  ┌ WeakRefStrings
+     14.8 ms  ┌ Tables
+     24.2 ms  ┌ PooledArrays
+   2002.4 ms  CSV 83.49% compilation time
 ```
 
 !!! note

stdlib/InteractiveUtils/test/runtests.jl

@@ -641,7 +641,7 @@ end
                 buf = read(fname)
                 rm(fname)
 
-                @test occursin("ms  Foo3242\n", String(buf))
+                @test occursin("ms  Foo3242", String(buf))
 
             finally
                 filter!((≠)(dir), LOAD_PATH)