Recycle workers with bad init times

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

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

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

test/workers.jl

@@ -114,8 +114,8 @@ 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
+# 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