Add macro for timing package and dependency imports (JuliaLang#41612)

NEWS.md

@@ -45,6 +45,9 @@ Standard library changes
  arithmetic to error if the result may be wrapping. Or use a package such as SaferIntegers.jl when
  constructing the range. ([#40382])
 
+#### InteractiveUtils
+* A new macro `@time_imports` for reporting any time spent importing packages and their dependencies ([#41612])
+
 #### Package Manager
 
 #### LinearAlgebra

base/loading.jl

@@ -769,7 +769,7 @@ function _include_from_serialized(path::String, depmods::Vector{Any})
  return restored
 end
 
-function _tryrequire_from_serialized(modkey::PkgId, build_id::UInt64, modpath::Union{Nothing, String})
+function _tryrequire_from_serialized(modkey::PkgId, build_id::UInt64, modpath::Union{Nothing, String}, depth::Int = 0)
  if root_module_exists(modkey)
  M = root_module(modkey)
  if PkgId(M) == modkey && module_build_id(M) === build_id
@@ -780,7 +780,7 @@ function _tryrequire_from_serialized(modkey::PkgId, build_id::UInt64, modpath::U
  modpath = locate_package(modkey)
  modpath === nothing && return nothing
  end
- mod = _require_search_from_serialized(modkey, String(modpath))
+ mod = _require_search_from_serialized(modkey, String(modpath), depth)
  get!(PkgOrigin, pkgorigins, modkey).path = modpath
  if !isa(mod, Bool)
  for callback in package_callbacks
@@ -821,10 +821,14 @@ function _require_from_serialized(path::String)
  return _include_from_serialized(path, depmods)
 end
 
+# use an Int counter so that nested @time_imports calls all remain open
+const TIMING_IMPORTS = Threads.Atomic{Int}(0)
+
 # returns `true` if require found a precompile cache for this sourcepath, but couldn't load it
 # returns `false` if the module isn't known to be precompilable
 # returns the set of modules restored if the cache load succeeded
-function _require_search_from_serialized(pkg::PkgId, sourcepath::String)
+function _require_search_from_serialized(pkg::PkgId, sourcepath::String, depth::Int = 0)
+ t_before = time_ns()
  paths = find_all_in_cache_path(pkg)
  for path_to_try in paths::Vector{String}
  staledeps = stale_cachefile(sourcepath, path_to_try)
@@ -840,7 +844,7 @@ function _require_search_from_serialized(pkg::PkgId, sourcepath::String)
  dep = staledeps[i]
  dep isa Module && continue
  modpath, modkey, build_id = dep::Tuple{String, PkgId, UInt64}
- dep = _tryrequire_from_serialized(modkey, build_id, modpath)
+ dep = _tryrequire_from_serialized(modkey, build_id, modpath, depth + 1)
  if dep === nothing
  @debug "Required dependency $modkey failed to load from cache file for $modpath."
  staledeps = true
@@ -855,6 +859,13 @@ function _require_search_from_serialized(pkg::PkgId, sourcepath::String)
  if isa(restored, Exception)
  @debug "Deserialization checks failed while attempting to load cache from $path_to_try" exception=restored
  else
+ if TIMING_IMPORTS[] > 0
+ elapsed = round((time_ns() - t_before) / 1e6, digits = 1)
+ tree_prefix = depth == 0 ? "" : "$(" "^(depth-1))┌ "
+ print("$(lpad(elapsed, 9)) ms ")
+ printstyled(tree_prefix, color = :light_black)
+ println(pkg.name)
+ end
  return restored
  end
  end

stdlib/InteractiveUtils/docs/src/index.md

@@ -26,5 +26,6 @@ InteractiveUtils.code_llvm
 InteractiveUtils.@code_llvm
 InteractiveUtils.code_native
 InteractiveUtils.@code_native
+InteractiveUtils.@time_imports
 InteractiveUtils.clipboard
 ```

stdlib/InteractiveUtils/src/InteractiveUtils.jl

@@ -6,7 +6,7 @@ Base.Experimental.@optlevel 1
 
 export apropos, edit, less, code_warntype, code_llvm, code_native, methodswith, varinfo,
  versioninfo, subtypes, supertypes, @which, @edit, @less, @functionloc, @code_warntype,
- @code_typed, @code_lowered, @code_llvm, @code_native, clipboard
+ @code_typed, @code_lowered, @code_llvm, @code_native, @time_imports, clipboard
 
 import Base.Docs.apropos
 

stdlib/InteractiveUtils/src/macros.jl

@@ -232,6 +232,17 @@ macro code_lowered(ex0...)
  end
 end
 
+macro time_imports(ex)
+ quote
+ try
+ Base.TIMING_IMPORTS[] += 1
+ $(esc(ex))
+ finally
+ Base.TIMING_IMPORTS[] -= 1
+ end
+ end
+end
+
 """
  @functionloc
 
@@ -332,3 +343,36 @@ Set the optional keyword argument `debuginfo` by putting it before the function
 `debuginfo` may be one of `:source` (default) or `:none`, to specify the verbosity of code comments.
 """
 :@code_native
+
+"""
+ @time_imports
+
+A macro to execute an expression and produce a report of any time spent importing packages and their
+dependencies.
+
+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.
+
+```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
+```
+
+!!! note
+ During the load process a package sequentially imports where necessary all of its dependencies, not just
+ its direct dependencies. That is also true for the dependencies themselves so nested importing will likely
+ occur, but not always. Therefore the nesting shown in this output report is not equivalent to the dependency
+ tree, but does indicate where import time has accumulated.
+
+"""
+:@time_imports

stdlib/InteractiveUtils/test/runtests.jl

@@ -586,3 +586,36 @@ let
  opt = false
  @test !(first(@code_typed optimize=opt sum(1:10)).inferred)
 end
+
+@testset "@time_imports" begin
+ mktempdir() do dir
+ cd(dir) do
+ try
+ pushfirst!(LOAD_PATH, dir)
+ foo_file = joinpath(dir, "Foo3242.jl")
+ write(foo_file,
+ """
+ module Foo3242
+ foo() = 1
+ end
+ """)
+
+ Base.compilecache(Base.PkgId("Foo3242"))
+
+ fname = tempname()
+ f = open(fname, "w")
+ redirect_stdout(f) do
+ @eval @time_imports using Foo3242
+ end
+ close(f)
+ buf = read(fname)
+ rm(fname)
+
+ @test occursin("ms Foo3242\n", String(buf))
+
+ finally
+ filter!((≠)(dir), LOAD_PATH)
+ end
+ end
+ end
+end