From 8a2374aeee704179cdb5cfa6ceae72e109586eba Mon Sep 17 00:00:00 2001 From: Ian Butterworth Date: Thu, 28 Apr 2022 09:48:42 -0400 Subject: [PATCH] Add compilation & recompilation time to time_imports macro (#45064) (cherry picked from commit 9320fba641e1b78c5b596f4a4a8ad20deb2dfdaa) --- NEWS.md | 1 + base/loading.jl | 24 +++++++++++++++--- stdlib/InteractiveUtils/src/macros.jl | 32 ++++++++++++++++-------- stdlib/InteractiveUtils/test/runtests.jl | 2 +- 4 files changed, 44 insertions(+), 15 deletions(-) diff --git a/NEWS.md b/NEWS.md index a3ae8fe37e40b9..f20a82832d335b 100644 --- a/NEWS.md +++ b/NEWS.md @@ -110,6 +110,7 @@ New library features * TCP socket objects now expose `closewrite` functionality and support half-open mode usage ([#40783]). * `extrema` now accepts an `init` keyword argument ([#36265], [#43604]). * `Iterators.countfrom` now accepts any type that defines `+` ([#37747]). +* `@time_imports` now shows any compilation and recompilation time percentages per import ([#45064]). Standard library changes ------------------------ diff --git a/base/loading.jl b/base/loading.jl index 2e83a4296c2383..5011cb837df3f4 100644 --- a/base/loading.jl +++ b/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 diff --git a/stdlib/InteractiveUtils/src/macros.jl b/stdlib/InteractiveUtils/src/macros.jl index 623873a3484b55..b0005e6d7d783a 100644 --- a/stdlib/InteractiveUtils/src/macros.jl +++ b/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 diff --git a/stdlib/InteractiveUtils/test/runtests.jl b/stdlib/InteractiveUtils/test/runtests.jl index 05e3a744644e11..4013eee1b54bc5 100644 --- a/stdlib/InteractiveUtils/test/runtests.jl +++ b/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)