From 74c4c1ba7ff9cf48f1ad243944475b3696ae77aa Mon Sep 17 00:00:00 2001 From: Ian Butterworth Date: Tue, 8 Aug 2023 21:53:45 -0400 Subject: [PATCH 1/5] precompilation: capture stdout during code load precomp --- src/API.jl | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/src/API.jl b/src/API.jl index 17e6c3b45f..3c37d1a46a 100644 --- a/src/API.jl +++ b/src/API.jl @@ -1449,8 +1449,10 @@ function precompile(ctx::Context, pkgs::Vector{PackageSpec}; internal_call::Bool # a functionally identical package cache (except for preferences, which may differ) t = @elapsed ret = maybe_cachefile_lock(io, print_lock, fancyprint, pkg, pkgspidlocked) do Logging.with_logger(Logging.NullLogger()) do - # capture stderr, send stdout to devnull, don't skip loaded modules - Base.compilecache(pkg, sourcepath, iob, devnull, false) + # For Pkg.precompile capture stderr, send stdout to devnull. + # For code load precompilation capture both. + # In both cases don't skip loaded modules. + Base.compilecache(pkg, sourcepath, iob, _from_loading ? iob : devnull, false) end end t_str = timing ? string(lpad(round(t * 1e3, digits = 1), 9), " ms") : "" From b850e23154613044d6d5b89e6cbaec85b6dc10a5 Mon Sep 17 00:00:00 2001 From: Ian Butterworth Date: Fri, 11 Aug 2023 10:41:51 -0400 Subject: [PATCH 2/5] use two pipes --- src/API.jl | 76 +++++++++++++++++++++++++++++++----------------------- 1 file changed, 44 insertions(+), 32 deletions(-) diff --git a/src/API.jl b/src/API.jl index 3c37d1a46a..2ec3c0f8b6 100644 --- a/src/API.jl +++ b/src/API.jl @@ -1273,30 +1273,41 @@ function precompile(ctx::Context, pkgs::Vector{PackageSpec}; internal_call::Bool end end - stderr_outputs = Dict{Base.PkgId,String}() + std_outputs = Dict{Base.PkgId,String}() taskwaiting = Set{Base.PkgId}() pkgspidlocked = Dict{Base.PkgId,String}() - function monitor_stderr(pkg, iob) - try - while isopen(iob) - str = readline(iob) - stderr_outputs[pkg] = get(stderr_outputs, pkg, "") * str * "\n" - if !in(pkg, taskwaiting) && occursin("waiting for IO to finish", str) - !fancyprint && lock(print_lock) do - println(io, pkg.name, color_string(" Waiting for background task / IO / timer.", Base.warn_color())) + function monitor_stderr_stdout(pkg, _stderr, _stdout) + @sync begin + @async try + while isopen(_stderr) + str = readline(_stderr) + std_outputs[pkg] = string(get(std_outputs, pkg, ""), str, "\n") + if !in(pkg, taskwaiting) && occursin("waiting for IO to finish", str) + !fancyprint && lock(print_lock) do + println(io, pkg.name, color_string(" Waiting for background task / IO / timer.", Base.warn_color())) + end + push!(taskwaiting, pkg) end - push!(taskwaiting, pkg) - end - if !fancyprint && in(pkg, taskwaiting) - lock(print_lock) do - println(io, str) + if !fancyprint && in(pkg, taskwaiting) + lock(print_lock) do + println(io, str) + end end end + catch err + err isa InterruptException || rethrow() + end + @async try + while isopen(_stdout) + str = readline(_stdout) + std_outputs[pkg] = string(get(std_outputs, pkg, ""), str, "\n") + end + catch err + err isa InterruptException || rethrow() end - catch err - err isa InterruptException || rethrow() end + return nothing end ## fancy print loop @@ -1428,8 +1439,9 @@ function precompile(ctx::Context, pkgs::Vector{PackageSpec}; internal_call::Bool is_direct_dep = pkg in direct_deps # stderr monitoring - iob = Base.BufferStream() - t_monitor = @async monitor_stderr(pkg, iob) + stderr_pipe = Base.Pipe() + stdout_pipe = Base.Pipe() + t_monitor = @async monitor_stderr_stdout(pkg, stderr_pipe, stdout_pipe) _name = haskey(exts, pkg) ? string(exts[pkg], " → ", pkg.name) : pkg.name name = is_direct_dep ? _name : string(color_string(_name, :light_black)) @@ -1449,10 +1461,8 @@ function precompile(ctx::Context, pkgs::Vector{PackageSpec}; internal_call::Bool # a functionally identical package cache (except for preferences, which may differ) t = @elapsed ret = maybe_cachefile_lock(io, print_lock, fancyprint, pkg, pkgspidlocked) do Logging.with_logger(Logging.NullLogger()) do - # For Pkg.precompile capture stderr, send stdout to devnull. - # For code load precompilation capture both. - # In both cases don't skip loaded modules. - Base.compilecache(pkg, sourcepath, iob, _from_loading ? iob : devnull, false) + # The false here means we ignore loaded modules, so precompile for a fresh session + Base.compilecache(pkg, sourcepath, stderr_pipe, stdout_pipe, false) end end t_str = timing ? string(lpad(round(t * 1e3, digits = 1), 9), " ms") : "" @@ -1471,11 +1481,13 @@ function precompile(ctx::Context, pkgs::Vector{PackageSpec}; internal_call::Bool end loaded && (n_loaded += 1) catch err - close(iob) + # close pipes to end the std output monitor + close(stderr_pipe) + close(stdout_pipe) wait(t_monitor) 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", get(stderr_outputs, pkg, "")) : "" - delete!(stderr_outputs, pkg) # so it's not shown as warnings, given error report + failed_deps[pkg] = (strict || is_direct_dep) ? string(sprint(showerror, err), "\n", strip(get(std_outputs, pkg, ""))) : "" + delete!(std_outputs, pkg) # so it's not shown as warnings, given error report !fancyprint && lock(print_lock) do println(io, timing ? " "^9 : "", color_string(" ✗ ", Base.error_color()), name) end @@ -1517,7 +1529,7 @@ function precompile(ctx::Context, pkgs::Vector{PackageSpec}; internal_call::Bool quick_exit = !all(istaskdone, tasks) || interrupted # if some not finished internal error is likely seconds_elapsed = round(Int, (time_ns() - time_start) / 1e9) ndeps = count(values(was_recompiled)) - if ndeps > 0 || !isempty(failed_deps) || (quick_exit && !isempty(stderr_outputs)) + if ndeps > 0 || !isempty(failed_deps) || (quick_exit && !isempty(std_outputs)) str = sprint() do iostr if !quick_exit plural = ndeps == 1 ? "y" : "ies" @@ -1547,12 +1559,12 @@ function precompile(ctx::Context, pkgs::Vector{PackageSpec}; internal_call::Bool end # show any stderr output, even if Pkg.precompile has been interrupted (quick_exit=true), given user may be # interrupting a hanging precompile job with stderr output. julia#48371 - filter!(kv -> !isempty(strip(last(kv))), stderr_outputs) # remove empty output - if !isempty(stderr_outputs) - plural1 = length(stderr_outputs) == 1 ? "y" : "ies" - plural2 = length(stderr_outputs) == 1 ? "" : "s" - print(iostr, "\n ", color_string("$(length(stderr_outputs))", Base.warn_color()), " dependenc$(plural1) had output during precompilation:") - for (pkgid, err) in stderr_outputs + filter!(kv -> !isempty(strip(last(kv))), std_outputs) # remove empty output + if !isempty(std_outputs) + plural1 = length(std_outputs) == 1 ? "y" : "ies" + plural2 = length(std_outputs) == 1 ? "" : "s" + print(iostr, "\n ", color_string("$(length(std_outputs))", Base.warn_color()), " dependenc$(plural1) had output during precompilation:") + for (pkgid, err) in std_outputs err = join(split(strip(err), "\n"), color_string("\n│ ", Base.warn_color())) print(iostr, color_string("\n┌ ", Base.warn_color()), pkgid, color_string("\n│ ", Base.warn_color()), err, color_string("\n└ ", Base.warn_color())) end From 8783c7ccdce35a5dd2079321471f5aa22f0eaa64 Mon Sep 17 00:00:00 2001 From: Ian Butterworth Date: Mon, 14 Aug 2023 22:18:27 -0400 Subject: [PATCH 3/5] suggestions --- src/API.jl | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/src/API.jl b/src/API.jl index 2ec3c0f8b6..9864a236e4 100644 --- a/src/API.jl +++ b/src/API.jl @@ -1280,7 +1280,7 @@ function precompile(ctx::Context, pkgs::Vector{PackageSpec}; internal_call::Bool function monitor_stderr_stdout(pkg, _stderr, _stdout) @sync begin @async try - while isopen(_stderr) + while !eof(_stderr) str = readline(_stderr) std_outputs[pkg] = string(get(std_outputs, pkg, ""), str, "\n") if !in(pkg, taskwaiting) && occursin("waiting for IO to finish", str) @@ -1299,7 +1299,7 @@ function precompile(ctx::Context, pkgs::Vector{PackageSpec}; internal_call::Bool err isa InterruptException || rethrow() end @async try - while isopen(_stdout) + while !eof(_stdout) str = readline(_stdout) std_outputs[pkg] = string(get(std_outputs, pkg, ""), str, "\n") end @@ -1439,8 +1439,8 @@ function precompile(ctx::Context, pkgs::Vector{PackageSpec}; internal_call::Bool is_direct_dep = pkg in direct_deps # stderr monitoring - stderr_pipe = Base.Pipe() - stdout_pipe = Base.Pipe() + stderr_pipe = Base.link_pipe!(Pipe(); reader_supports_async=true, writer_supports_async=true) + stdout_pipe = Base.link_pipe!(Pipe(); reader_supports_async=true, writer_supports_async=true) t_monitor = @async monitor_stderr_stdout(pkg, stderr_pipe, stdout_pipe) _name = haskey(exts, pkg) ? string(exts[pkg], " → ", pkg.name) : pkg.name @@ -1482,8 +1482,8 @@ function precompile(ctx::Context, pkgs::Vector{PackageSpec}; internal_call::Bool loaded && (n_loaded += 1) catch err # close pipes to end the std output monitor - close(stderr_pipe) - close(stdout_pipe) + close(stderr_pipe.in) + close(stdout_pipe.in) wait(t_monitor) 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", strip(get(std_outputs, pkg, ""))) : "" From 6ed7bfd1fa281b9253e44c78c701a28ab93687f4 Mon Sep 17 00:00:00 2001 From: Ian Butterworth Date: Mon, 14 Aug 2023 23:39:04 -0400 Subject: [PATCH 4/5] use a single pipe --- src/API.jl | 52 +++++++++++++++++++--------------------------------- 1 file changed, 19 insertions(+), 33 deletions(-) diff --git a/src/API.jl b/src/API.jl index 9864a236e4..6356c8b392 100644 --- a/src/API.jl +++ b/src/API.jl @@ -1277,37 +1277,26 @@ function precompile(ctx::Context, pkgs::Vector{PackageSpec}; internal_call::Bool taskwaiting = Set{Base.PkgId}() pkgspidlocked = Dict{Base.PkgId,String}() - function monitor_stderr_stdout(pkg, _stderr, _stdout) - @sync begin - @async try - while !eof(_stderr) - str = readline(_stderr) - std_outputs[pkg] = string(get(std_outputs, pkg, ""), str, "\n") - if !in(pkg, taskwaiting) && occursin("waiting for IO to finish", str) - !fancyprint && lock(print_lock) do - println(io, pkg.name, color_string(" Waiting for background task / IO / timer.", Base.warn_color())) - end - push!(taskwaiting, pkg) - end - if !fancyprint && in(pkg, taskwaiting) - lock(print_lock) do - println(io, str) - end + function monitor_std(pkg, pipe) + try + while !eof(pipe) + str = readline(pipe, keep=true) + std_outputs[pkg] = string(get(std_outputs, pkg, ""), str) + if !in(pkg, taskwaiting) && occursin("waiting for IO to finish", str) + !fancyprint && lock(print_lock) do + println(io, pkg.name, color_string(" Waiting for background task / IO / timer.", Base.warn_color())) end + push!(taskwaiting, pkg) end - catch err - err isa InterruptException || rethrow() - end - @async try - while !eof(_stdout) - str = readline(_stdout) - std_outputs[pkg] = string(get(std_outputs, pkg, ""), str, "\n") + if !fancyprint && in(pkg, taskwaiting) + lock(print_lock) do + print(io, str) + end end - catch err - err isa InterruptException || rethrow() end + catch err + err isa InterruptException || rethrow() end - return nothing end ## fancy print loop @@ -1439,9 +1428,8 @@ function precompile(ctx::Context, pkgs::Vector{PackageSpec}; internal_call::Bool is_direct_dep = pkg in direct_deps # stderr monitoring - stderr_pipe = Base.link_pipe!(Pipe(); reader_supports_async=true, writer_supports_async=true) - stdout_pipe = Base.link_pipe!(Pipe(); reader_supports_async=true, writer_supports_async=true) - t_monitor = @async monitor_stderr_stdout(pkg, stderr_pipe, stdout_pipe) + std_pipe = Base.link_pipe!(Pipe(); reader_supports_async=true, writer_supports_async=true) + t_monitor = @async monitor_std(pkg, std_pipe) _name = haskey(exts, pkg) ? string(exts[pkg], " → ", pkg.name) : pkg.name name = is_direct_dep ? _name : string(color_string(_name, :light_black)) @@ -1462,7 +1450,7 @@ function precompile(ctx::Context, pkgs::Vector{PackageSpec}; internal_call::Bool t = @elapsed ret = maybe_cachefile_lock(io, print_lock, fancyprint, pkg, pkgspidlocked) do Logging.with_logger(Logging.NullLogger()) do # The false here means we ignore loaded modules, so precompile for a fresh session - Base.compilecache(pkg, sourcepath, stderr_pipe, stdout_pipe, false) + Base.compilecache(pkg, sourcepath, std_pipe, std_pipe, false) end end t_str = timing ? string(lpad(round(t * 1e3, digits = 1), 9), " ms") : "" @@ -1481,9 +1469,7 @@ function precompile(ctx::Context, pkgs::Vector{PackageSpec}; internal_call::Bool end loaded && (n_loaded += 1) catch err - # close pipes to end the std output monitor - close(stderr_pipe.in) - close(stdout_pipe.in) + close(std_pipe.in) # close pipe to end the std output monitor wait(t_monitor) 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", strip(get(std_outputs, pkg, ""))) : "" From 69fdd8780ecca01e174d491010ec946608481053 Mon Sep 17 00:00:00 2001 From: Ian Butterworth Date: Tue, 15 Aug 2023 09:40:13 -0400 Subject: [PATCH 5/5] also close in happy path --- src/API.jl | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/API.jl b/src/API.jl index 6356c8b392..be226e53a4 100644 --- a/src/API.jl +++ b/src/API.jl @@ -1483,6 +1483,8 @@ function precompile(ctx::Context, pkgs::Vector{PackageSpec}; internal_call::Bool rethrow() end finally + isopen(std_pipe.in) && close(std_pipe.in) # close pipe to end the std output monitor + wait(t_monitor) Base.release(parallel_limiter) end else