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"))