precompile: add timing mode (JuliaLang#3334)

Closes JuliaLang#3328

CHANGELOG.md

@@ -10,6 +10,7 @@ Pkg v1.9 Release Notes
   a pidfile lock ([#2793]).
 - The Pkg REPL now understands Github URLs to branches and commits so you can e.g. do `pkg> add https://github.com/Org/Package.jl/tree/branch`
   or `pkg> add https://github.com/Org/Package.jl/commit/bb9eb77e6dc`.
+- Timing of the precompilation of dependencies can now be reported via `Pkg.precompile(timing=true)` ([#3334])
 
 Pkg v1.8 Release Notes
 ======================

src/API.jl

@@ -1115,7 +1115,7 @@ function get_or_make_pkgspec(pkgspecs::Vector{PackageSpec}, ctx::Context, uuid)
 end
 
 function precompile(ctx::Context, pkgs::Vector{PackageSpec}; internal_call::Bool=false,
-                    strict::Bool=false, warn_loaded = true, already_instantiated = false, kwargs...)
+                    strict::Bool=false, warn_loaded = true, already_instantiated = false, timing::Bool = false, kwargs...)
     Context!(ctx; kwargs...)
     already_instantiated || instantiate(ctx; allow_autoprecomp=false, kwargs...)
     time_start = time_ns()
@@ -1128,7 +1128,7 @@ function precompile(ctx::Context, pkgs::Vector{PackageSpec}; internal_call::Bool
     num_tasks = parse(Int, get(ENV, "JULIA_NUM_PRECOMPILE_TASKS", string(default_num_tasks)))
     parallel_limiter = Base.Semaphore(num_tasks)
     io = ctx.io
-    fancyprint = can_fancyprint(io)
+    fancyprint = can_fancyprint(io) && !timing
 
     recall_precompile_state() # recall suspended and force-queued packages
     !internal_call && precomp_unsuspend!() # when manually called, unsuspend all packages that were suspended due to precomp errors
@@ -1403,23 +1403,24 @@ function precompile(ctx::Context, pkgs::Vector{PackageSpec}; internal_call::Bool
                         return
                     end
                     try
-                        ret = Logging.with_logger(Logging.NullLogger()) do
+                        t = @elapsed ret = Logging.with_logger(Logging.NullLogger()) do
                             # TODO: Explore allowing parallel LLVM image generation. Needs careful load balancing
                             withenv("JULIA_IMAGE_THREADS" => "1") do
                                 # capture stderr, send stdout to devnull, don't skip loaded modules
                                 Base.compilecache(pkg, sourcepath, iob, devnull, false)
                             end
                         end
+                        t_str = timing ? string(lpad(round(t * 1e3, digits = 1), 9), " ms") : ""
                         if ret isa Base.PrecompilableError
                             push!(precomperr_deps, pkg)
                             precomp_queue!(get_or_make_pkgspec(pkg_specs, ctx, pkg.uuid))
                             !fancyprint && lock(print_lock) do
-                                println(io, string(color_string("  ? ", Base.warn_color()), name))
+                                println(io, t_str, color_string("  ? ", Base.warn_color()), name)
                             end
                         else
                             queued && precomp_dequeue!(get_or_make_pkgspec(pkg_specs, ctx, pkg.uuid))
                             !fancyprint && lock(print_lock) do
-                                println(io, string(color_string("  ✓ ", loaded ? Base.warn_color() : :green), name))
+                                println(io, t_str, color_string("  ✓ ", loaded ? Base.warn_color() : :green), name)
                             end
                             was_recompiled[pkg] = true
                         end
@@ -1428,7 +1429,7 @@ function precompile(ctx::Context, pkgs::Vector{PackageSpec}; internal_call::Bool
                         if err isa ErrorException || (err isa ArgumentError && startswith(err.msg, "Invalid header in cache file"))
                             failed_deps[pkg] = (strict || is_direct_dep) ? string(sprint(showerror, err), "\n", String(take!(iob))) : ""
                             !fancyprint && lock(print_lock) do
-                                println(io, string(color_string("  ✗ ", Base.error_color()), name))
+                                println(io, timing ? " "^9 : "", color_string("  ✗ ", Base.error_color()), name)
                             end
                             queued && precomp_dequeue!(get_or_make_pkgspec(pkg_specs, ctx, pkg.uuid))
                             precomp_suspend!(get_or_make_pkgspec(pkg_specs, ctx, pkg.uuid))
@@ -1470,7 +1471,7 @@ function precompile(ctx::Context, pkgs::Vector{PackageSpec}; internal_call::Bool
     end
     notify(first_started) # in cases of no-op or !fancyprint
     save_precompile_state() # save lists to scratch space
-    wait(t_print)
+    fancyprint && wait(t_print)
     !all(istaskdone, tasks) && return # if some not finished, must have errored or been interrupted
     seconds_elapsed = round(Int, (time_ns() - time_start) / 1e9)
     ndeps = count(values(was_recompiled))

src/Pkg.jl

@@ -143,11 +143,14 @@ See also [`PackageSpec`](@ref), [`Pkg.develop`](@ref).
 const add = API.add
 
 """
-    Pkg.precompile(; strict::Bool=false)
-    Pkg.precompile(pkg; strict::Bool=false)
-    Pkg.precompile(pkgs; strict::Bool=false)
+    Pkg.precompile(; strict::Bool=false, timing::Bool=false)
+    Pkg.precompile(pkg; strict::Bool=false, timing::Bool=false)
+    Pkg.precompile(pkgs; strict::Bool=false, timing::Bool=false)
 
 Precompile all or specific dependencies of the project in parallel.
+
+Set `timing=true` to show the duration of the precompilation of each dependency.
+
 !!! note
     Errors will only throw when precompiling the top-level dependencies, given that
     not all manifest dependencies may be loaded by the top-level dependencies on the given system.
@@ -162,6 +165,9 @@ Precompile all or specific dependencies of the project in parallel.
 !!! compat "Julia 1.8"
     Specifying packages to precompile requires at least Julia 1.8.
 
+!!! compat "Julia 1.9"
+    Timing mode requires at least Julia 1.9.
+
 # Examples
 ```julia
 Pkg.precompile()

test/api.jl

@@ -109,6 +109,7 @@ end
             Pkg.generate("Dep3")
             Pkg.generate("Dep4")
             Pkg.generate("Dep5")
+            Pkg.generate("Dep6")
             Pkg.generate("NoVersion")
             open(joinpath("NoVersion","Project.toml"), "w") do io
                 write(io, "name = \"NoVersion\"\nuuid = \"$(UUIDs.uuid4())\"")
@@ -196,6 +197,18 @@ end
         # https://github.com/JuliaLang/Pkg.jl/pull/2142
         Pkg.build(; verbose=true)
 
+        @testset "timing mode" begin
+            iob = IOBuffer()
+            Pkg.develop(Pkg.PackageSpec(path="packages/Dep6"))
+            Pkg.precompile(io=iob, timing=true)
+            str = String(take!(iob))
+            @test occursin("Precompiling", str)
+            @test occursin(" ms", str)
+            @test occursin("Dep6", str)
+            Pkg.precompile(io=iob)
+            @test !occursin("Precompiling", String(take!(iob))) # test that the previous precompile was a no-op
+        end
+
         ENV["JULIA_PKG_PRECOMPILE_AUTO"]=0
     end end
     # ignoring circular deps, to avoid deadlock