From 95feb765f1a3a7f0b5b5a6416a3960f347d9727b Mon Sep 17 00:00:00 2001 From: Ian Date: Thu, 15 Jul 2021 22:33:42 -0400 Subject: [PATCH 1/5] add macro for timing package and dep imports --- base/Base.jl | 1 + base/loading.jl | 19 ++++++-- stdlib/InteractiveUtils/docs/src/index.md | 1 + .../InteractiveUtils/src/InteractiveUtils.jl | 2 +- stdlib/InteractiveUtils/src/macros.jl | 44 +++++++++++++++++++ 5 files changed, 62 insertions(+), 5 deletions(-) diff --git a/base/Base.jl b/base/Base.jl index 42a506479326b..861676ad62c9b 100644 --- a/base/Base.jl +++ b/base/Base.jl @@ -488,6 +488,7 @@ function __init__() if haskey(ENV, "JULIA_MAX_NUM_PRECOMPILE_FILES") MAX_NUM_PRECOMPILE_FILES[] = parse(Int, ENV["JULIA_MAX_NUM_PRECOMPILE_FILES"]) end + append!(empty!(LOAD_TIMING), zeros(Int, Threads.nthreads())) nothing end diff --git a/base/loading.jl b/base/loading.jl index 851ebf17cc3b9..2b2ab530bfa1b 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 LOAD_TIMING = Int[] # initialized in __init__ + # 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 LOAD_TIMING[Threads.threadid()] > 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..9de51870353e5 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.LOAD_TIMING[Threads.threadid()] += 1 + $(esc(ex)) + finally + Base.LOAD_TIMING[Threads.threadid()] -= 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 From 1ef418f8928c89d131c0004c6cf52f636329aa11 Mon Sep 17 00:00:00 2001 From: Ian Date: Mon, 19 Jul 2021 15:31:33 -0400 Subject: [PATCH 2/5] add to NEWS --- NEWS.md | 3 +++ 1 file changed, 3 insertions(+) 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 From 4aa9b531a1f7b60f447c1a7dd0895a55605dbff9 Mon Sep 17 00:00:00 2001 From: Ian Date: Mon, 19 Jul 2021 16:56:36 -0400 Subject: [PATCH 3/5] add a test --- stdlib/InteractiveUtils/test/runtests.jl | 33 ++++++++++++++++++++++++ 1 file changed, 33 insertions(+) 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 From a24fb7e6f0a56a5676306063474d41d3637032f5 Mon Sep 17 00:00:00 2001 From: Ian Date: Tue, 20 Jul 2021 15:00:16 -0400 Subject: [PATCH 4/5] rename var for clarity --- base/Base.jl | 2 +- base/loading.jl | 4 ++-- stdlib/InteractiveUtils/src/macros.jl | 4 ++-- 3 files changed, 5 insertions(+), 5 deletions(-) diff --git a/base/Base.jl b/base/Base.jl index 861676ad62c9b..3a3d095d3916c 100644 --- a/base/Base.jl +++ b/base/Base.jl @@ -488,7 +488,7 @@ function __init__() if haskey(ENV, "JULIA_MAX_NUM_PRECOMPILE_FILES") MAX_NUM_PRECOMPILE_FILES[] = parse(Int, ENV["JULIA_MAX_NUM_PRECOMPILE_FILES"]) end - append!(empty!(LOAD_TIMING), zeros(Int, Threads.nthreads())) + append!(empty!(TIMING_IMPORTS), zeros(Int, Threads.nthreads())) nothing end diff --git a/base/loading.jl b/base/loading.jl index 2b2ab530bfa1b..238ab4b84de58 100644 --- a/base/loading.jl +++ b/base/loading.jl @@ -822,7 +822,7 @@ function _require_from_serialized(path::String) end # use an Int counter so that nested @time_imports calls all remain open -const LOAD_TIMING = Int[] # initialized in __init__ +const TIMING_IMPORTS = Int[] # initialized in __init__ # 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 @@ -859,7 +859,7 @@ function _require_search_from_serialized(pkg::PkgId, sourcepath::String, depth:: if isa(restored, Exception) @debug "Deserialization checks failed while attempting to load cache from $path_to_try" exception=restored else - if LOAD_TIMING[Threads.threadid()] > 0 + if TIMING_IMPORTS[Threads.threadid()] > 0 elapsed = round((time_ns() - t_before) / 1e6, digits = 1) tree_prefix = depth == 0 ? "" : "$(" "^(depth-1))┌ " print("$(lpad(elapsed, 9)) ms ") diff --git a/stdlib/InteractiveUtils/src/macros.jl b/stdlib/InteractiveUtils/src/macros.jl index 9de51870353e5..17b9943d88165 100644 --- a/stdlib/InteractiveUtils/src/macros.jl +++ b/stdlib/InteractiveUtils/src/macros.jl @@ -235,10 +235,10 @@ end macro time_imports(ex) quote try - Base.LOAD_TIMING[Threads.threadid()] += 1 + Base.TIMING_IMPORTS[Threads.threadid()] += 1 $(esc(ex)) finally - Base.LOAD_TIMING[Threads.threadid()] -= 1 + Base.TIMING_IMPORTS[Threads.threadid()] -= 1 end end end From 6cd8d97ce21a90a6b520769a904fd2379304c98d Mon Sep 17 00:00:00 2001 From: Ian Date: Wed, 21 Jul 2021 08:51:04 -0400 Subject: [PATCH 5/5] use a Threads.Atomic counter instead --- base/Base.jl | 1 - base/loading.jl | 4 ++-- stdlib/InteractiveUtils/src/macros.jl | 4 ++-- 3 files changed, 4 insertions(+), 5 deletions(-) diff --git a/base/Base.jl b/base/Base.jl index 3a3d095d3916c..42a506479326b 100644 --- a/base/Base.jl +++ b/base/Base.jl @@ -488,7 +488,6 @@ function __init__() if haskey(ENV, "JULIA_MAX_NUM_PRECOMPILE_FILES") MAX_NUM_PRECOMPILE_FILES[] = parse(Int, ENV["JULIA_MAX_NUM_PRECOMPILE_FILES"]) end - append!(empty!(TIMING_IMPORTS), zeros(Int, Threads.nthreads())) nothing end diff --git a/base/loading.jl b/base/loading.jl index 238ab4b84de58..eac5286263690 100644 --- a/base/loading.jl +++ b/base/loading.jl @@ -822,7 +822,7 @@ function _require_from_serialized(path::String) end # use an Int counter so that nested @time_imports calls all remain open -const TIMING_IMPORTS = Int[] # initialized in __init__ +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 @@ -859,7 +859,7 @@ function _require_search_from_serialized(pkg::PkgId, sourcepath::String, depth:: if isa(restored, Exception) @debug "Deserialization checks failed while attempting to load cache from $path_to_try" exception=restored else - if TIMING_IMPORTS[Threads.threadid()] > 0 + if TIMING_IMPORTS[] > 0 elapsed = round((time_ns() - t_before) / 1e6, digits = 1) tree_prefix = depth == 0 ? "" : "$(" "^(depth-1))┌ " print("$(lpad(elapsed, 9)) ms ") diff --git a/stdlib/InteractiveUtils/src/macros.jl b/stdlib/InteractiveUtils/src/macros.jl index 17b9943d88165..701f548e9da91 100644 --- a/stdlib/InteractiveUtils/src/macros.jl +++ b/stdlib/InteractiveUtils/src/macros.jl @@ -235,10 +235,10 @@ end macro time_imports(ex) quote try - Base.TIMING_IMPORTS[Threads.threadid()] += 1 + Base.TIMING_IMPORTS[] += 1 $(esc(ex)) finally - Base.TIMING_IMPORTS[Threads.threadid()] -= 1 + Base.TIMING_IMPORTS[] -= 1 end end end