diff --git a/NEWS.md b/NEWS.md index 53cd1632c5aec..e992ddd8683d1 100644 --- a/NEWS.md +++ b/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 diff --git a/base/loading.jl b/base/loading.jl index 851ebf17cc3b9..eac5286263690 100644 --- a/base/loading.jl +++ b/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 diff --git a/stdlib/InteractiveUtils/docs/src/index.md b/stdlib/InteractiveUtils/docs/src/index.md index 71499744ecb1d..9ad4b5a7cea80 100644 --- a/stdlib/InteractiveUtils/docs/src/index.md +++ b/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 ``` diff --git a/stdlib/InteractiveUtils/src/InteractiveUtils.jl b/stdlib/InteractiveUtils/src/InteractiveUtils.jl index 6f8ba9ea0b080..6eb75e8c0b685 100644 --- a/stdlib/InteractiveUtils/src/InteractiveUtils.jl +++ b/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 diff --git a/stdlib/InteractiveUtils/src/macros.jl b/stdlib/InteractiveUtils/src/macros.jl index 98c47f02f2707..701f548e9da91 100644 --- a/stdlib/InteractiveUtils/src/macros.jl +++ b/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 diff --git a/stdlib/InteractiveUtils/test/runtests.jl b/stdlib/InteractiveUtils/test/runtests.jl index f9e3a4ce71e9f..8770de8797f04 100644 --- a/stdlib/InteractiveUtils/test/runtests.jl +++ b/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