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

(cherry picked from commit 9320fba)

base/loading.jl

@@ -895,7 +895,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)
@@ -927,17 +933,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)