From 3bc5c39431fcf5981b0fdcbaf3e9dcf8185ae3d0 Mon Sep 17 00:00:00 2001 From: Christian Guinard <28689358+christiangnrd@users.noreply.github.com> Date: Fri, 11 Sep 2026 09:45:58 -0300 Subject: [PATCH] Warn when the pre-test init time becomes much slower than a worker restart Under macOS memory pressure (issue #124), the full GC run before each test gets progressively slower on a long-lived worker, which is usually a sign that there are too many workers for the available memory and can lead to hangs or much longer test times. Track the init time of tests run on freshly spawned workers (which already includes spawn, init_worker_code and init_code, so it is the full cost of a restart) and, once a warm init exceeds SLOW_INIT_FACTOR times that, print a warning (once per run) suggesting to lower JULIA_TEST_MAXRSS_MB / max_worker_rss or the number of jobs. A testset forces a slow init to check the warning. Co-Authored-By: Claude Fable 5.1 --- docs/src/advanced.md | 1 + docs/src/index.md | 1 + src/ParallelTestRunner.jl | 45 +++++++++++++++++++++++++++++++++++++++ test/workers.jl | 45 +++++++++++++++++++++++++++++++++++++++ 4 files changed, 92 insertions(+) diff --git a/docs/src/advanced.md b/docs/src/advanced.md index 8cd8fbb8..5cf3698b 100644 --- a/docs/src/advanced.md +++ b/docs/src/advanced.md @@ -229,6 +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. 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 eef97fec..72e4eba2 100644 --- a/docs/src/index.md +++ b/docs/src/index.md @@ -130,6 +130,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 - 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 5ca2365f..e2244f8b 100644 --- a/src/ParallelTestRunner.jl +++ b/src/ParallelTestRunner.jl @@ -160,6 +160,14 @@ function memory_usage(rec::AbstractTestRecord) return parent(rec).rss end +function init_time(rec::AbstractTestRecord) + base = parent(rec) + 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 +const SLOW_INIT_FACTOR = 2 + function Base.getindex(rec::AbstractTestRecord) return parent(rec).value end @@ -1162,6 +1170,10 @@ function _runtests(mod::Module, args::ParsedArgs; t0 = time() results = Lockable([]) running_tests = Lockable(Dict{String, Float64}()) # test => start_time + # init time of a test on a freshly spawned worker, i.e. the cost of recycling one + cold_init_time = Threads.Atomic{Float64}(Inf) + # the slow init warning is only printed once per run + slow_init_warned = Threads.Atomic{Bool}(false) worker_tasks = Task[] @@ -1295,6 +1307,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) + # (:slow_init, test_name, init_time, cold_init_time) # (:crashed, test_name, worker_id, test_time) # (:retry, tests_n, retry_n) # (:nonpass_face, face) @@ -1331,6 +1344,26 @@ function _runtests(mod::Module, args::ParsedArgs; print_test_finished(record, wrkr, test_name, io_ctx) end + elseif msg_type === :slow_init + test_name, init_t, cold_t = msg[2], msg[3], msg[4] + + clear_status() + lock(io_ctx.lock) + try + msg_str = styled""" + {ptr_warn,bold:Warning:}{ptr_warn: pre-test time of `$test_name` ($(round(init_t; digits=2))s) was much longer than usual ($(round(cold_t; digits=2))s on a freshly spawned worker). + This is typically due to the number of workers being too high for the amount of available memory, + and can cause hangs and/or much longer test times. Try lowering the RSS threshold before a new + worker is spawned via the JULIA_TEST_MAXRSS_MB environment variable or the `max_worker_rss` keyword + argument to `runtests`. If that does not work, you can manually set the number of jobs using the + `--jobs=N` test argument.} + """ + print(io_ctx.stderr, msg_str) + flush(io_ctx.stderr) + finally + unlock(io_ctx.lock) + end + elseif msg_type === :crashed test_name, wrkr = msg[2], msg[3] @@ -1452,9 +1485,11 @@ function _runtests(mod::Module, args::ParsedArgs; wrkr = p end # if a worker failed, spawn a new one + fresh_worker = false if wrkr === nothing || !Malt.isrunning(wrkr) wrkr = p = addworker(; init_worker_code, io_ctx.color, exename, exeflags, env) + fresh_worker = true end # run the test @@ -1485,6 +1520,13 @@ function _runtests(mod::Module, args::ParsedArgs; # act on the results if result isa AbstractTestRecord + if fresh_worker + Threads.atomic_min!(cold_init_time, init_time(result)) + 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) + 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 @@ -1492,6 +1534,9 @@ function _runtests(mod::Module, args::ParsedArgs; recycle = wrkr === p && (memory_usage(result) > max_worker_rss || ((recycle_on_failure || retry_mode) && anynonpass(result[]))) put!(printer_channel, (:finished, test, worker_id(wrkr), result, recycle)) + if slow_init && !Threads.atomic_xchg!(slow_init_warned, true) + put!(printer_channel, (:slow_init, test, init_time(result), cold_init_time[])) + end if anynonpass(result[]) && args.quickfail !== nothing stop_work() return diff --git a/test/workers.jl b/test/workers.jl index 9297bee6..9c963e62 100644 --- a/test/workers.jl +++ b/test/workers.jl @@ -114,6 +114,11 @@ 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 +# dedicated run, take it from the verbose output of the following testset. +cold_init_time = Ref(NaN) + @testset "default workers reused and stopped at end" begin # Use default workers (no test_worker) so the framework creates and should stop them. # More tests than workers so that workers are reused, and so that some tasks finish @@ -152,6 +157,10 @@ end @test contains(str, "SUCCESS") # Make sure we didn't spawn more workers than expected: the same workers ran all tests. @test ParallelTestRunner.ID_COUNTER[] == old_id_counter + njobs + # The first test on each worker had a cold init: the slowest init is an upper bound. + init_times = [parse(Float64, m[1]) for m in eachmatch(r"^t\d\s+\(\d+\) │\s+[\d.]+ │\s+([\d.]+) │"m, str)] + @test length(init_times) == length(testsuite) + cold_init_time[] = maximum(init_times) if before < 0 # Counting child PIDs not supported on this platform @test_skip false @@ -195,6 +204,42 @@ end @test ParallelTestRunner.ID_COUNTER[] == old_id_counter + length(testsuite) end +@testset "slow init warning" begin + init_worker_code = :( const slow_init_counter = Ref(0) ) + args = ["--verbose", "--jobs=1"] + + # `cold_init_time` was measured by the "default workers reused and stopped at end" + # testset above; if that testset failed before recording it, measure it here instead + # so that this testset stays independent. + if isnan(cold_init_time[]) + io = IOBuffer() + runtests(ParallelTestRunner, args; testsuite=Dict("cold" => :( @test true )), init_worker_code, stdout=io, stderr=io) + 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 + slow_init = ceil(Int, 1.5 * ParallelTestRunner.SLOW_INIT_FACTOR * cold_init_time[]) + 1 + init_code = quote + Main.slow_init_counter[] += 1 + Main.slow_init_counter[] > 1 && sleep($slow_init) + end + testsuite = Dict("a" => :( @test true ), "b" => :( @test true ), "c" => :( @test true )) + io = IOBuffer() + ioc = IOContext(io, :color => true) + old_id_counter = ParallelTestRunner.ID_COUNTER[] + 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 + @test count("Warning:", str) == 1 + @test count("\e[33m", str) == 1 + @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 + @testset "recycle_on_failure" begin # Call `_runtests` so that we can enforce a run order, and use a single job, so that # all tests share the same pool slot: a test only gets a new worker if the previous one