remove log spamming from precompilepkg code (#59652)

Improves consistency between serial and parallel code and reduces
useless log spamming. Logging messages should convey useful content
actionable in some form by the user. Neither non-interactive mode nor
simple progress meters achieve either goal.

Fix #59527

(cherry picked from commit 42a33bb)

Author: vtjnash

base/loading.jl

@@ -2622,34 +2622,37 @@ function __require_prelocked(pkg::PkgId, env)
     if JLOptions().use_compiled_modules == 1
         if !generating_output(#=incremental=#false)
             project = active_project()
-            if !generating_output() && !parallel_precompile_attempted && !disable_parallel_precompile && @isdefined(Precompilation) && project !== nothing &&
-                    isfile(project) && project_file_manifest_path(project) !== nothing
-                parallel_precompile_attempted = true
-                unlock(require_lock)
-                try
-                    Precompilation.precompilepkgs([pkg.name]; _from_loading=true, ignore_loaded=false)
-                finally
-                    lock(require_lock)
-                end
-                @goto load_from_cache
-            end
             # spawn off a new incremental pre-compile task for recursive `require` calls
             loaded = let path = path, reasons = reasons
                 maybe_cachefile_lock(pkg, path) do
                     # double-check the search now that we have lock
                     m = _require_search_from_serialized(pkg, path, UInt128(0), true)
                     m isa Module && return m
-                    triggers = get(EXT_PRIMED, pkg, nothing)
-                    loadable_exts = nothing
-                    if triggers !== nothing # extension
-                        loadable_exts = PkgId[]
-                        for (ext′, triggers′) in EXT_PRIMED
-                            if triggers′ ⊊ triggers
-                                push!(loadable_exts, ext′)
+
+                    verbosity = isinteractive() ? CoreLogging.Info : CoreLogging.Debug
+                    @logmsg verbosity "Precompiling $(repr("text/plain", pkg))$(list_reasons(reasons))"
+
+                    unlock(require_lock)
+                    try
+                        if !generating_output() && !parallel_precompile_attempted && !disable_parallel_precompile && @isdefined(Precompilation)
+                            parallel_precompile_attempted = true
+                            Precompilation.precompilepkgs([pkg]; _from_loading=true, ignore_loaded=false)
+                            return
+                        end
+                        triggers = get(EXT_PRIMED, pkg, nothing)
+                        loadable_exts = nothing
+                        if triggers !== nothing # extension
+                            loadable_exts = PkgId[]
+                            for (ext′, triggers′) in EXT_PRIMED
+                                if triggers′ ⊊ triggers
+                                    push!(loadable_exts, ext′)
+                                end
                             end
                         end
+                        return compilecache(pkg, path; loadable_exts)
+                    finally
+                        lock(require_lock)
                     end
-                    return compilecache(pkg, path; reasons, loadable_exts)
                 end
             end
             loaded isa Module && return loaded
@@ -3150,18 +3153,18 @@ This can be used to reduce package load times. Cache files are stored in
 `DEPOT_PATH[1]/compiled`. See [Module initialization and precompilation](@ref)
 for important notes.
 """
-function compilecache(pkg::PkgId, internal_stderr::IO = stderr, internal_stdout::IO = stdout; flags::Cmd=``, cacheflags::CacheFlags=CacheFlags(), reasons::Union{Dict{String,Int},Nothing}=Dict{String,Int}(), loadable_exts::Union{Vector{PkgId},Nothing}=nothing)
+function compilecache(pkg::PkgId, internal_stderr::IO = stderr, internal_stdout::IO = stdout; flags::Cmd=``, cacheflags::CacheFlags=CacheFlags(), loadable_exts::Union{Vector{PkgId},Nothing}=nothing)
     @nospecialize internal_stderr internal_stdout
     path = locate_package(pkg)
     path === nothing && throw(ArgumentError("$(repr("text/plain", pkg)) not found during precompilation"))
-    return compilecache(pkg, path, internal_stderr, internal_stdout; flags, cacheflags, reasons, loadable_exts)
+    return compilecache(pkg, path, internal_stderr, internal_stdout; flags, cacheflags, loadable_exts)
 end
 
 const MAX_NUM_PRECOMPILE_FILES = Ref(10)
 
 function compilecache(pkg::PkgId, path::String, internal_stderr::IO = stderr, internal_stdout::IO = stdout,
                       keep_loaded_modules::Bool = true; flags::Cmd=``, cacheflags::CacheFlags=CacheFlags(),
-                      reasons::Union{Dict{String,Int},Nothing}=Dict{String,Int}(), loadable_exts::Union{Vector{PkgId},Nothing}=nothing)
+                      loadable_exts::Union{Vector{PkgId},Nothing}=nothing)
 
     @nospecialize internal_stderr internal_stdout
     # decide where to put the resulting cache file
@@ -3179,8 +3182,6 @@ function compilecache(pkg::PkgId, path::String, internal_stderr::IO = stderr, in
         concrete_deps = empty(_concrete_dependencies)
     end
     # run the expression and cache the result
-    verbosity = isinteractive() ? CoreLogging.Info : CoreLogging.Debug
-    @logmsg verbosity "Precompiling $(repr("text/plain", pkg)) $(list_reasons(reasons))"
 
     # create a temporary file in `cachepath` directory, write the cache in it,
     # write the checksum, _and then_ atomically move the file to `cachefile`.
@@ -3878,7 +3879,7 @@ end
 record_reason(::Nothing, ::String) = nothing
 function list_reasons(reasons::Dict{String,Int})
     isempty(reasons) && return ""
-    return "(cache misses: $(join(("$k ($v)" for (k,v) in reasons), ", ")))"
+    return " (cache misses: $(join(("$k ($v)" for (k,v) in reasons), ", ")))"
 end
 list_reasons(::Nothing) = ""
 

base/precompilation.jl

@@ -1,6 +1,6 @@
 module Precompilation
 
-using Base: PkgId, UUID, SHA1, parsed_toml, project_file_name_uuid, project_names,
+using Base: CoreLogging, PkgId, UUID, SHA1, parsed_toml, project_file_name_uuid, project_names,
             project_file_manifest_path, get_deps, preferences_names, isaccessibledir, isfile_casesensitive,
             base_project, isdefined
 
@@ -499,9 +499,16 @@ function _precompilepkgs(pkgs::Vector{String},
     num_tasks = parse(Int, get(ENV, "JULIA_NUM_PRECOMPILE_TASKS", string(default_num_tasks)))
     parallel_limiter = Base.Semaphore(num_tasks)
 
-    # suppress passive loading printing in julia test suite. `JULIA_TESTS` is set in Base.runtests
-    io = (_from_loading && !Sys.isinteractive() && Base.get_bool_env("JULIA_TESTS", false)) ? IOContext{IO}(devnull) : _io
-
+    # suppress precompilation progress messages when precompiling for loading packages, except during interactive sessions
+    # or when specified by logging heuristics that explicitly require it
+    # since the complicated IO implemented here can have somewhat disastrous consequences when happening in the background (e.g. #59599)
+    io = _io
+    logcalls = nothing
+    if _from_loading && !isinteractive()
+        io = IOContext{IO}(devnull)
+        fancyprint = false
+        logcalls = isinteractive() ? CoreLogging.Info : CoreLogging.Debug # sync with Base.compilecache
+    end
 
     nconfigs = length(configs)
     hascolor = get(io, :color, false)::Bool
@@ -572,8 +579,6 @@ function _precompilepkgs(pkgs::Vector{String},
     # consider exts of project deps to be project deps so that errors are reported
     append!(project_deps, keys(filter(d->last(d).name in keys(env.project_deps), ext_to_parent)))
 
-    @debug "precompile: deps collected"
-
     # An extension effectively depends on another extension if it has a strict superset of its triggers
     for ext_a in keys(ext_to_parent)
         for ext_b in keys(ext_to_parent)
@@ -628,7 +633,6 @@ function _precompilepkgs(pkgs::Vector{String},
             end
         end
     end
-    @debug "precompile: extensions collected"
 
     # return early if no deps
     if isempty(direct_deps)
@@ -656,7 +660,6 @@ function _precompilepkgs(pkgs::Vector{String},
             was_recompiled[pkg_config] = false
         end
     end
-    @debug "precompile: signalling initialized"
 
     # find and guard against circular deps
     cycles = Vector{Base.PkgId}[]
@@ -683,7 +686,6 @@ function _precompilepkgs(pkgs::Vector{String},
     if !isempty(circular_deps)
         @warn excluded_circular_deps_explanation(io, ext_to_parent, circular_deps, cycles)
     end
-    @debug "precompile: circular dep check done"
 
     if !manifest
         if isempty(pkgs)
@@ -723,7 +725,6 @@ function _precompilepkgs(pkgs::Vector{String},
     else
         target[] = "for $nconfigs compilation configurations..."
     end
-    @debug "precompile: packages filtered"
 
     pkg_queue = PkgConfig[]
     failed_deps = Dict{PkgConfig, String}()
@@ -949,16 +950,23 @@ function _precompilepkgs(pkgs::Vector{String},
                             return
                         end
                         try
-                            # allows processes to wait if another process is precompiling a given package to
-                            # a functionally identical package cache (except for preferences, which may differ)
-                            t = @elapsed ret = precompile_pkgs_maybe_cachefile_lock(io, print_lock, fancyprint, pkg_config, pkgspidlocked, hascolor, parallel_limiter, ignore_loaded) do
-                                Base.with_logger(Base.NullLogger()) do
-                                    # whether to respect already loaded dependency versions
-                                    keep_loaded_modules = !ignore_loaded
-                                    # for extensions, any extension in our direct dependencies is one we have a right to load
-                                    # for packages, we may load any extension (all possible triggers are accounted for above)
-                                    loadable_exts = haskey(ext_to_parent, pkg) ? filter((dep)->haskey(ext_to_parent, dep), direct_deps[pkg]) : nothing
-                                    Base.compilecache(pkg, sourcepath, std_pipe, std_pipe, keep_loaded_modules;
+                            # for extensions, any extension in our direct dependencies is one we have a right to load
+                            # for packages, we may load any extension (all possible triggers are accounted for above)
+                            loadable_exts = haskey(ext_to_parent, pkg) ? filter((dep)->haskey(ext_to_parent, dep), direct_deps[pkg]) : nothing
+                            if _from_loading && pkg in requested_pkgids
+                                # loading already took the cachefile_lock and printed logmsg for its explicit requests
+                                t = @elapsed ret = begin
+                                    Base.compilecache(pkg, sourcepath, std_pipe, std_pipe, !ignore_loaded;
+                                                      flags, cacheflags, loadable_exts)
+                                end
+                            else
+                                # allows processes to wait if another process is precompiling a given package to
+                                # a functionally identical package cache (except for preferences, which may differ)
+                                t = @elapsed ret = precompile_pkgs_maybe_cachefile_lock(io, print_lock, fancyprint, pkg_config, pkgspidlocked, hascolor, parallel_limiter, ignore_loaded) do
+                                    logcalls === nothing || @lock print_lock begin
+                                        Base.@logmsg logcalls "Precompiling $(repr("text/plain", pkg))"
+                                    end
+                                    Base.compilecache(pkg, sourcepath, std_pipe, std_pipe, !ignore_loaded;
                                                       flags, cacheflags, loadable_exts)
                                 end
                             end

test/precompile.jl

@@ -642,7 +642,7 @@ precompile_test_harness(false) do dir
           end
           """)
 
-    cachefile, _ = @test_logs (:debug, r"Precompiling FooBar") min_level=Logging.Debug match_mode=:any Base.compilecache(Base.PkgId("FooBar"))
+    cachefile, _ = @test_logs (:debug, r"Generating object cache file for FooBar") min_level=Logging.Debug match_mode=:any Base.compilecache(Base.PkgId("FooBar"))
     empty_prefs_hash = Base.get_preferences_hash(nothing, String[])
     @test cachefile == Base.compilecache_path(Base.PkgId("FooBar"), empty_prefs_hash)
     @test isfile(joinpath(cachedir, "FooBar.ji"))