Warn when the pre-test init time becomes much slower than a worker restart

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

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

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,13 +1520,23 @@ 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
                               # (custom workers are stopped after every test regardless)
                               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

test/workers.jl

@@ -114,6 +114,11 @@ end
 end
 
 # Issue <https://github.com/JuliaTesting/ParallelTestRunner.jl/issues/106>.
+# 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