From 0a2f8ca83211958749f0b4ff164ba5cb71f06eb5 Mon Sep 17 00:00:00 2001 From: Christian Guinard <28689358+christiangnrd@users.noreply.github.com> Date: Fri, 11 Sep 2026 09:56:45 -0300 Subject: [PATCH] Recycle workers whose pre-test init time has become slower than a restart The slow init warning already tracks the cost of a fresh worker: once a warm init exceeds SLOW_INIT_FACTOR times that, spawning a new worker is cheaper than keeping the bloated heap of the current one (e.g. under macOS memory pressure, issue #124). Recycle such pool workers in addition to warning, print the worker id and the offending init time in yellow, and extend the slow init testset to check the recycle and the output. Co-Authored-By: Claude Fable 5.1 --- docs/src/advanced.md | 2 +- docs/src/index.md | 5 +++-- src/ParallelTestRunner.jl | 21 ++++++++++++++------- test/workers.jl | 19 ++++++++++--------- 4 files changed, 28 insertions(+), 19 deletions(-) diff --git a/docs/src/advanced.md b/docs/src/advanced.md index 5cf3698b..2968b532 100644 --- a/docs/src/advanced.md +++ b/docs/src/advanced.md @@ -229,7 +229,7 @@ and a yellow one marks a result that may still be replaced. On memory-constrained macOS machines (notably CI runners), requesting more jobs than the default can make the test suite take much longer than expected, sometimes enough to time out the job. This often manifests as per-test init times (shown with `--verbose`) steadily increasing over the run, likely because macOS compresses memory under pressure and each garbage collection gets slower. GC % being higer than usual can also be an indication that you're requesting too many jobs or that the max RSS threshold is too high. -The runner prints a warning the first time a test's init time gets much longer than on a freshly spawned worker. +The runner prints a warning the first time a test's init time gets much longer than on a freshly spawned worker, and recycles such workers since a restart is cheaper by then. Prefer the default `--jobs` value, which accounts for available memory, and lower the `JULIA_TEST_MAXRSS_MB` environment variable so that workers get recycled sooner. See [issue #124](https://github.com/JuliaTesting/ParallelTestRunner.jl/issues/124) for more details. ## Custom Workers diff --git a/docs/src/index.md b/docs/src/index.md index 72e4eba2..bf33bdd6 100644 --- a/docs/src/index.md +++ b/docs/src/index.md @@ -117,7 +117,8 @@ See [Serial Tests](@ref) in the advanced usage guide for details. ### Failure Recycling and Retries -Workers are recycled when they crash or exceed the memory threshold. +Workers are recycled when they crash, exceed the memory threshold, or when the time spent +before a test (mostly garbage collection) becomes slower than starting a fresh worker. Additionally, [`runtests`](@ref) has two keyword arguments to further customize failure handling. Setting `recycle_on_failure=true` recycles a worker after any failed test, so a test that corrupts process-wide state cannot poison later tests, @@ -130,7 +131,7 @@ See [Failure Handling](@ref) in the advanced usage guide for details. The test runner provides real-time output showing: - Test name and worker assignment, with the worker shown in yellow when it is about to be recycled - Execution time -- Init time (with `--verbose`), i.e. the time spent before the test started +- Init time (with `--verbose`), i.e. the time spent before the test started, shown in yellow when it caused the worker to be recycled - GC time and percentage - Memory allocation - RSS (Resident Set Size) memory usage, shown in yellow once it exceeds the RSS threshold diff --git a/src/ParallelTestRunner.jl b/src/ParallelTestRunner.jl index e2244f8b..b47bd72a 100644 --- a/src/ParallelTestRunner.jl +++ b/src/ParallelTestRunner.jl @@ -165,7 +165,8 @@ function init_time(rec::AbstractTestRecord) return base.total_time - base.time end -# the user is warned once a warm worker's init time exceeds this multiple of the cold-start cost +# the user is warned and a warm worker is recycled once its init time exceeds this multiple +# of the cold-start cost const SLOW_INIT_FACTOR = 2 function Base.getindex(rec::AbstractTestRecord) @@ -192,6 +193,7 @@ struct TestIOContext rss_align::Int max_worker_rss::Int recycled::Ref{Bool} + slow_init::Ref{Bool} nonpass_face::Ref{Symbol} end @@ -207,7 +209,7 @@ function test_IOContext(::Type{<:AbstractTestRecord}, stdout::IO, stderr::IO, lo return TestIOContext( stdout, stderr, color, verbose, lock, name_align, elapsed_align, compile_align, gc_align, percent_align, - alloc_align, rss_align, max_worker_rss, Ref(false), Ref(:ptr_error) + alloc_align, rss_align, max_worker_rss, Ref(false), Ref(false), Ref(:ptr_error) ) end @@ -259,7 +261,9 @@ function print_test_finished(record::AbstractTestRecord, wrkr, test, ctx::TestIO padded_init_time, padded_comp_time = if ctx.verbose # pre-testset time init_time_str = @sprintf("%7.2f", base.total_time - base.time) - init_time = lpad(init_time_str, ctx.elapsed_align, " ") * " │ " + init_face = ctx.slow_init[] ? :ptr_warn : :ptr_default + padded_init = lpad(init_time_str, ctx.elapsed_align, " ") + init_time = styled"{$init_face:$padded_init} │ " # compilation time comp_time = if VERSION >= v"1.11" @@ -1306,7 +1310,7 @@ function _runtests(mod::Module, args::ParsedArgs; # Message types for the printer channel # (:started, test_name, worker_id) - # (:finished, test_name, worker_id, record, recycled) + # (:finished, test_name, worker_id, record, recycled, slow_init) # (:slow_init, test_name, init_time, cold_init_time) # (:crashed, test_name, worker_id, test_time) # (:retry, tests_n, retry_n) @@ -1336,6 +1340,7 @@ function _runtests(mod::Module, args::ParsedArgs; elseif msg_type === :finished test_name, wrkr, record = msg[2], msg[3], msg[4] io_ctx.recycled[] = msg[5] + io_ctx.slow_init[] = msg[6] clear_status() if anynonpass(record[]) @@ -1525,15 +1530,17 @@ function _runtests(mod::Module, args::ParsedArgs; end # the pre-test full GC has become much slower than spawning a # new worker, which typically means there are too many workers - # for the available memory (e.g. macOS memory pressure, #124) + # for the available memory (e.g. macOS memory pressure, #124): + # warn the user, and recycle the worker since that is now cheaper + # than keeping its bloated heap slow_init = wrkr === p && !fresh_worker && init_time(result) > SLOW_INIT_FACTOR * cold_init_time[] # recycle a pool worker so future tests start with a smaller working # set, or so that a failing test that may have left the worker in a # bad state (e.g. a wedged GPU driver) cannot poison later tests # (custom workers are stopped after every test regardless) - recycle = wrkr === p && (memory_usage(result) > max_worker_rss || + recycle = wrkr === p && (memory_usage(result) > max_worker_rss || slow_init || ((recycle_on_failure || retry_mode) && anynonpass(result[]))) - put!(printer_channel, (:finished, test, worker_id(wrkr), result, recycle)) + put!(printer_channel, (:finished, test, worker_id(wrkr), result, recycle, slow_init)) if slow_init && !Threads.atomic_xchg!(slow_init_warned, true) put!(printer_channel, (:slow_init, test, init_time(result), cold_init_time[])) end diff --git a/test/workers.jl b/test/workers.jl index 9c963e62..44c47f39 100644 --- a/test/workers.jl +++ b/test/workers.jl @@ -114,8 +114,8 @@ end end # Issue . -# The cold init time of a worker varies between machines, so the "slow init warning" -# testset below needs a measurement of it: rather than spending a worker on a +# The cold init time of a worker varies between machines, so the "slow init warning and +# recycling" testset below needs a measurement of it: rather than spending a worker on a # dedicated run, take it from the verbose output of the following testset. cold_init_time = Ref(NaN) @@ -204,7 +204,7 @@ end @test ParallelTestRunner.ID_COUNTER[] == old_id_counter + length(testsuite) end -@testset "slow init warning" begin +@testset "slow init warning and recycling" begin init_worker_code = :( const slow_init_counter = Ref(0) ) args = ["--verbose", "--jobs=1"] @@ -217,7 +217,7 @@ end cold_init_time[] = parse(Float64, match(r"^cold\s+\(\d+\) │\s+[\d.]+ │\s+([\d.]+) │"m, String(take!(io)))[1]) end - # every test after the first on the worker is slow to init + # every test after the first on a worker is slow to init, so the worker gets recycled slow_init = ceil(Int, 1.5 * ParallelTestRunner.SLOW_INIT_FACTOR * cold_init_time[]) + 1 init_code = quote Main.slow_init_counter[] += 1 @@ -230,12 +230,13 @@ end runtests(ParallelTestRunner, args; testsuite, init_worker_code, init_code, stdout=ioc, stderr=ioc) str = String(take!(io)) @test contains(str, "SUCCESS") - # a slow init does not recycle the worker - @test ParallelTestRunner.ID_COUNTER[] == old_id_counter + 1 - # both tests after the first are slow, but the warning is only printed once, and it is - # the only thing printed in yellow + # the slow init recycles the worker, so the last test has a cold init on a fresh one + @test ParallelTestRunner.ID_COUNTER[] == old_id_counter + 2 + # only the recycled worker, its slow init and the warning are printed in yellow @test count("Warning:", str) == 1 - @test count("\e[33m", str) == 1 + @test count("\e[33m", str) == 3 + @test contains(str, Regex("\\e\\[33m\\s*\\($(old_id_counter)\\)\\e\\[39m")) + @test contains(str, r"\e\[33m\s*\d+\.\d\d\e\[39m") @test contains(str, r"pre-test time of `[abc]` \(\d+\.\d+s\) was much longer than usual") @test contains(str, "JULIA_TEST_MAXRSS_MB") end