Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add macro for timing package and dependency imports #41612

Merged
merged 5 commits into from
Jul 21, 2021
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
3 changes: 3 additions & 0 deletions NEWS.md
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
19 changes: 15 additions & 4 deletions base/loading.jl
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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
Expand Down Expand Up @@ -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)
Expand All @@ -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
Expand All @@ -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
Expand Down
1 change: 1 addition & 0 deletions stdlib/InteractiveUtils/docs/src/index.md
Original file line number Diff line number Diff line change
Expand Up @@ -26,5 +26,6 @@ InteractiveUtils.code_llvm
InteractiveUtils.@code_llvm
InteractiveUtils.code_native
InteractiveUtils.@code_native
InteractiveUtils.@time_imports
InteractiveUtils.clipboard
```
2 changes: 1 addition & 1 deletion stdlib/InteractiveUtils/src/InteractiveUtils.jl
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down
44 changes: 44 additions & 0 deletions stdlib/InteractiveUtils/src/macros.jl
Original file line number Diff line number Diff line change
Expand Up @@ -232,6 +232,17 @@ macro code_lowered(ex0...)
end
end

macro time_imports(ex)
quote
try
Base.TIMING_IMPORTS[] += 1
IanButterworth marked this conversation as resolved.
Show resolved Hide resolved
$(esc(ex))
finally
Base.TIMING_IMPORTS[] -= 1
end
end
end

"""
@functionloc

Expand Down Expand Up @@ -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
33 changes: 33 additions & 0 deletions stdlib/InteractiveUtils/test/runtests.jl
Original file line number Diff line number Diff line change
Expand Up @@ -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