From 255162c7197e973d0427cc11d1e0117cdd76a1bf Mon Sep 17 00:00:00 2001 From: Ian Butterworth Date: Wed, 11 Sep 2024 11:50:05 -0400 Subject: [PATCH] Precompile the `@time_imports` printing so it doesn't confuse reports (#55729) Makes functions for the report printing that can be precompiled into the sysimage. --- base/loading.jl | 94 +++++++++++++++++++++------------- contrib/generate_precompile.jl | 9 ++++ 2 files changed, 66 insertions(+), 37 deletions(-) diff --git a/base/loading.jl b/base/loading.jl index 4e70d2bc257ea..8d180845f942f 100644 --- a/base/loading.jl +++ b/base/loading.jl @@ -1254,22 +1254,9 @@ function _include_from_serialized(pkg::PkgId, path::String, ocachepath::Union{No if parentmodule(M) === M && PkgId(M) == pkg register && register_root_module(M) if timing_imports - elapsed = round((time_ns() - t_before) / 1e6, digits = 1) + elapsed_time = time_ns() - t_before comp_time, recomp_time = cumulative_compile_time_ns() .- t_comp_before - print(lpad(elapsed, 9), " ms ") - ext_parent = extension_parent_name(M) - if ext_parent !== nothing - print(ext_parent::String, " → ") - end - 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() + print_time_imports_report(M, elapsed_time, comp_time, recomp_time) end return M end @@ -1281,6 +1268,52 @@ function _include_from_serialized(pkg::PkgId, path::String, ocachepath::Union{No end end +# printing functions for @time_imports +# note that the time inputs are UInt64 on all platforms. Give default values here so that we don't have +# confusing UInt64 types in generate_precompile.jl +function print_time_imports_report( + mod::Module, + elapsed_time::UInt64=UInt64(1), + comp_time::UInt64=UInt64(1), + recomp_time::UInt64=UInt64(1) + ) + print(lpad(round(elapsed_time / 1e6, digits=1), 9), " ms ") + ext_parent = extension_parent_name(mod) + if ext_parent !== nothing + print(ext_parent::String, " → ") + end + print(string(mod)) + if comp_time > 0 + perc = Ryu.writefixed(Float64(100 * comp_time / (elapsed_time)), 2) + printstyled(" $perc% compilation time", color = Base.info_color()) + end + if recomp_time > 0 + perc = Float64(100 * recomp_time / comp_time) + perc_show = perc < 1 ? "<1" : Ryu.writefixed(perc, 0) + printstyled(" ($perc_show% recompilation)", color = Base.warn_color()) + end + println() +end +function print_time_imports_report_init( + mod::Module, i::Int=1, + elapsed_time::UInt64=UInt64(1), + comp_time::UInt64=UInt64(1), + recomp_time::UInt64=UInt64(1) + ) + connector = i > 1 ? "├" : "┌" + printstyled(" $connector ", color = :light_black) + print("$(round(elapsed_time / 1e6, digits=1)) ms $mod.__init__() ") + if comp_time > 0 + perc = Ryu.writefixed(Float64(100 * (comp_time) / elapsed_time), 2) + printstyled("$perc% 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 + # if M is an extension, return the string name of the parent. Otherwise return nothing function extension_parent_name(M::Module) rootmodule = moduleroot(M) @@ -1338,31 +1371,18 @@ function run_module_init(mod::Module, i::Int=1) # `i` informs ordering for the `@time_imports` report formatting if TIMING_IMPORTS[] == 0 ccall(:jl_init_restored_module, Cvoid, (Any,), mod) - else - if isdefined(mod, :__init__) - connector = i > 1 ? "├" : "┌" - printstyled(" $connector ", color = :light_black) - - elapsedtime = time_ns() - cumulative_compile_timing(true) - compile_elapsedtimes = cumulative_compile_time_ns() + elseif isdefined(mod, :__init__) + elapsed_time = time_ns() + cumulative_compile_timing(true) + compile_elapsedtimes = cumulative_compile_time_ns() - ccall(:jl_init_restored_module, Cvoid, (Any,), mod) + ccall(:jl_init_restored_module, Cvoid, (Any,), mod) - elapsedtime = (time_ns() - elapsedtime) / 1e6 - cumulative_compile_timing(false); - comp_time, recomp_time = (cumulative_compile_time_ns() .- compile_elapsedtimes) ./ 1e6 + elapsed_time = time_ns() - elapsed_time + cumulative_compile_timing(false); + comp_time, recomp_time = cumulative_compile_time_ns() .- compile_elapsedtimes - print("$(round(elapsedtime, digits=1)) ms $mod.__init__() ") - if comp_time > 0 - printstyled(Ryu.writefixed(Float64(100 * comp_time / elapsedtime), 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 + print_time_imports_report_init(mod, i, elapsed_time, comp_time, recomp_time) end end diff --git a/contrib/generate_precompile.jl b/contrib/generate_precompile.jl index 2a0e4faff7f1c..50ae560e99401 100644 --- a/contrib/generate_precompile.jl +++ b/contrib/generate_precompile.jl @@ -39,6 +39,8 @@ precompile(Base.__require_prelocked, (Base.PkgId, Nothing)) precompile(Base._require, (Base.PkgId, Nothing)) precompile(Base.indexed_iterate, (Pair{Symbol, Union{Nothing, String}}, Int)) precompile(Base.indexed_iterate, (Pair{Symbol, Union{Nothing, String}}, Int, Int)) +precompile(Tuple{typeof(Base.Threads.atomic_add!), Base.Threads.Atomic{Int}, Int}) +precompile(Tuple{typeof(Base.Threads.atomic_sub!), Base.Threads.Atomic{Int}, Int}) # Pkg loading precompile(Tuple{typeof(Base.Filesystem.normpath), String, String, Vararg{String}}) @@ -161,6 +163,8 @@ for match = Base._methods(+, (Int, Int), -1, Base.get_world_counter()) push!(Expr[], Expr(:return, false)) vcat(String[], String[]) k, v = (:hello => nothing) + Base.print_time_imports_report(Base) + Base.print_time_imports_report_init(Base) # Preferences uses these get(Dict{String,Any}(), "missing", nothing) @@ -172,6 +176,11 @@ for match = Base._methods(+, (Int, Int), -1, Base.get_world_counter()) # interactive startup uses this write(IOBuffer(), "") + # not critical, but helps hide unrelated compilation from @time when using --trace-compile + foo() = rand(2,2) * rand(2,2) + @time foo() + @time foo() + break # only actually need to do this once end """