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.

Sign up for GitHub

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

Jump to bottom

Avoid confounding compilation side effects of @time_imports #55729

Merged
merged 3 commits into from
Sep 11, 2024
Merged

Avoid confounding compilation side effects of @time_imports #55729

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
f82bb71
split printing out to separate precompilable functions
IanButterworth Sep 10, 2024
d00891e
also precompile `@time` reports
IanButterworth Sep 10, 2024
f916076
fix types given uint64 even on 32-bit
IanButterworth Sep 11, 2024
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
94 changes: 57 additions & 37 deletions base/loading.jl
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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)
Expand Down Expand Up @@ -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

Expand Down
9 changes: 9 additions & 0 deletions contrib/generate_precompile.jl
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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}})
Expand Down Expand Up @@ -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)
Expand All @@ -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
"""
Expand Down