From 2d2cb8ddef19c1bc2732fb762a43e25eeb3564ed Mon Sep 17 00:00:00 2001 From: Jameson Nash Date: Thu, 25 Sep 2025 02:32:17 +0000 Subject: [PATCH] remove log spamming from precompilepkg code 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 --- base/loading.jl | 50 ++++++++++++++++++++++-------------------- base/precompilation.jl | 48 +++++++++++++++++++++++----------------- test/precompile.jl | 2 +- 3 files changed, 55 insertions(+), 45 deletions(-) diff --git a/base/loading.jl b/base/loading.jl index 5ad41538c52ab..dd4bf12a8a84b 100644 --- a/base/loading.jl +++ b/base/loading.jl @@ -2669,33 +2669,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) - parallel_precompile_attempted = true - unlock(require_lock) - try - Precompilation.precompilepkgs([pkg]; _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 @@ -3222,18 +3226,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 @@ -3251,8 +3255,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`. @@ -3950,7 +3952,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) = "" diff --git a/base/precompilation.jl b/base/precompilation.jl index 45634d877115f..a6be5d4c59e83 100644 --- a/base/precompilation.jl +++ b/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 @@ -532,9 +532,16 @@ function _precompilepkgs(pkgs::Union{Vector{String}, Vector{PkgId}}, 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 @@ -608,8 +615,6 @@ function _precompilepkgs(pkgs::Union{Vector{String}, Vector{PkgId}}, # 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) @@ -664,7 +669,6 @@ function _precompilepkgs(pkgs::Union{Vector{String}, Vector{PkgId}}, end end end - @debug "precompile: extensions collected" serial_deps = Base.PkgId[] # packages that are being precompiled in serial @@ -704,7 +708,6 @@ function _precompilepkgs(pkgs::Union{Vector{String}, Vector{PkgId}}, was_recompiled[pkg_config] = false end end - @debug "precompile: signalling initialized" # find and guard against circular deps cycles = Vector{Base.PkgId}[] @@ -732,7 +735,6 @@ function _precompilepkgs(pkgs::Union{Vector{String}, Vector{PkgId}}, if !isempty(circular_deps) @warn excluded_circular_deps_explanation(io, ext_to_parent, circular_deps, cycles) end - @debug "precompile: circular dep check done" # If you have a workspace and want to precompile all projects in it, look through all packages in the manifest # instead of collecting from a project i.e. not filter out packages that are in the current project. @@ -785,7 +787,6 @@ function _precompilepkgs(pkgs::Union{Vector{String}, Vector{PkgId}}, else target[] = "for $nconfigs compilation configurations..." end - @debug "precompile: packages filtered" pkg_queue = PkgConfig[] failed_deps = Dict{PkgConfig, String}() @@ -1013,16 +1014,23 @@ function _precompilepkgs(pkgs::Union{Vector{String}, Vector{PkgId}}, 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 diff --git a/test/precompile.jl b/test/precompile.jl index 12e35210449ed..f78318ec645f2 100644 --- a/test/precompile.jl +++ b/test/precompile.jl @@ -641,7 +641,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"))