Extra long worker load time on 1.13+

[christiangnrd]

Using #86, I noticed that on 1.13 and 1.14, the first worker init time is MUCH longer and then it goes back down to 1.12. timings when rerunning the test set if no code has been changed.

GPUArrays runs on JuliaGPU/GPUArrays.jl/pull/685:

1.12.4 run 1:

     Testing Running tests...
Running 1 tests in parallel. If this is too many, specify the `--jobs=N` argument to the tests, or set the `JULIA_CPU_THREADS` environment variable.
                    │          │   Init   │ ──────────────── CPU ──────────────── │
Test       (Worker) │ Time (s) │ time (s) │ GC (s) │ GC % │ Alloc (MB) │ RSS (MB) │
Array/vectors   (1) │     0.28 │     6.08 │   0.00 │  0.0 │      42.14 │   502.08 │

Test Summary: | Pass  Total  Time
  Overall     |   10     10  8.3s
    SUCCESS     CPU Time: 6.36s; CPU Test Time: 0.22s
     Testing GPUArrays tests passed 

1.12.4 run 2:

     Testing Running tests...
Running 1 tests in parallel. If this is too many, specify the `--jobs=N` argument to the tests, or set the `JULIA_CPU_THREADS` environment variable.
                    │          │   Init   │ ──────────────── CPU ──────────────── │
Test       (Worker) │ Time (s) │ time (s) │ GC (s) │ GC % │ Alloc (MB) │ RSS (MB) │
Array/vectors   (1) │     0.28 │     6.10 │   0.00 │  0.0 │      42.14 │   503.17 │

Test Summary: | Pass  Total  Time
  Overall     |   10     10  8.3s
    SUCCESS     CPU Time: 6.39s; CPU Test Time: 0.23s
     Testing GPUArrays tests passed 

1.13 beta 2 run 1:

Precompiling for configuration --code-coverage=none --color=yes --warn-overwrite=yes --depwarn=yes --inline=yes --startup-file=no --track-allocation=none
Precompiling packages finished.
  3 dependencies successfully precompiled in 4 seconds. 72 already precompiled.
     Testing Running tests...
Running 1 tests in parallel. If this is too many, specify the `--jobs=N` argument to the tests, or set the `JULIA_CPU_THREADS` environment variable.
                    │          │   Init   │ ──────────────── CPU ──────────────── │
Test       (Worker) │ Time (s) │ time (s) │ GC (s) │ GC % │ Alloc (MB) │ RSS (MB) │
Array/vectors   (1) │     0.24 │    13.69 │   0.00 │  0.0 │      31.03 │   534.02 │

Test Summary: | Pass  Total   Time
  Overall     |   10     10  15.3s
    SUCCESS     CPU Time: 13.94s; CPU Test Time: 0.24s
     Testing GPUArrays tests passed

1.13 beta 2 run 2:

     Testing Running tests...
Running 1 tests in parallel. If this is too many, specify the `--jobs=N` argument to the tests, or set the `JULIA_CPU_THREADS` environment variable.
                    │          │   Init   │ ──────────────── CPU ──────────────── │
Test       (Worker) │ Time (s) │ time (s) │ GC (s) │ GC % │ Alloc (MB) │ RSS (MB) │
Array/vectors   (1) │     0.24 │     6.46 │   0.00 │  0.0 │      31.51 │   486.16 │

Test Summary: | Pass  Total  Time
  Overall     |   10     10  8.2s
    SUCCESS     CPU Time: 6.70s; CPU Test Time: 0.24s
     Testing GPUArrays tests passed 

Metal.jl runs on JuliaGPU/Metal.jl/pull/739:

1.12.4 run 1:

Running 1 tests in parallel. If this is too many, specify the `--jobs=N` argument to the tests, or set the `JULIA_CPU_THREADS` environment variable.
               │          │   Init   │ ──────────────── CPU ──────────────── │
Test  (Worker) │ Time (s) │ time (s) │ GC (s) │ GC % │ Alloc (MB) │ RSS (MB) │
mtl/size   (1) │     0.20 │     6.52 │   0.00 │  0.0 │      19.49 │   557.38 │

Test Summary: | Pass  Total  Time
  Overall     |   16     16  8.3s
    SUCCESS     CPU Time: 6.72s; CPU Test Time: 0.13s
     Testing Metal tests passed 

1.12.4 run 2:

Running 1 tests in parallel. If this is too many, specify the `--jobs=N` argument to the tests, or set the `JULIA_CPU_THREADS` environment variable.
               │          │   Init   │ ──────────────── CPU ──────────────── │
Test  (Worker) │ Time (s) │ time (s) │ GC (s) │ GC % │ Alloc (MB) │ RSS (MB) │
mtl/size   (1) │     0.20 │     6.85 │   0.00 │  0.0 │      19.49 │   559.36 │

Test Summary: | Pass  Total  Time
  Overall     |   16     16  8.2s
    SUCCESS     CPU Time: 7.05s; CPU Test Time: 0.13s
     Testing Metal tests passed

1.13 beta 2 run 1:

Running 1 tests in parallel. If this is too many, specify the `--jobs=N` argument to the tests, or set the `JULIA_CPU_THREADS` environment variable.
               │          │   Init   │ ──────────────── CPU ──────────────── │
Test  (Worker) │ Time (s) │ time (s) │ GC (s) │ GC % │ Alloc (MB) │ RSS (MB) │
mtl/size   (1) │     0.17 │    36.35 │   0.00 │  0.0 │      14.55 │   595.73 │

Test Summary: | Pass  Total   Time
  Overall     |   16     16  38.4s
    SUCCESS     CPU Time: 36.51s; CPU Test Time: 0.16s
     Testing Metal tests passed 

1.13 beta 2 run 2:

Running 1 tests in parallel. If this is too many, specify the `--jobs=N` argument to the tests, or set the `JULIA_CPU_THREADS` environment variable.
               │          │   Init   │ ──────────────── CPU ──────────────── │
Test  (Worker) │ Time (s) │ time (s) │ GC (s) │ GC % │ Alloc (MB) │ RSS (MB) │
mtl/size   (1) │     0.19 │     7.08 │   0.00 │  0.0 │      14.53 │   536.44 │

Test Summary: | Pass  Total  Time
  Overall     |   16     16  8.3s
    SUCCESS     CPU Time: 7.27s; CPU Test Time: 0.18s
     Testing Metal tests passed 

[giordano]

With

using ParallelTestRunner
@trace_compile runtests(ParallelTestRunner, Base.ARGS; testsuite=Dict("test" => :(@test true)));

I get in v1.12

#=    3.1 ms =# precompile(Tuple{Type{Pair{A, B} where B where A}, String, Expr})
#=   51.7 ms =# precompile(Tuple{Type{Base.Dict{K, V} where V where K}, Pair{String, Expr}})
#=    1.9 ms =# precompile(Tuple{Type{NamedTuple{(:testsuite,), T} where T<:Tuple}, Tuple{Base.Dict{String, Expr}}})
#=    2.2 ms =# precompile(Tuple{Type{NamedTuple{(:typ,), T} where T<:Tuple}, Tuple{typeof(DataType)}})
#=    2.0 ms =# precompile(Tuple{typeof(Base.startswith), String})
#=    1.7 ms =# precompile(Tuple{typeof(Base.getproperty), Base.Some{Nothing}, Symbol})
#=    1.9 ms =# precompile(Tuple{typeof(Base.literal_pow), typeof(Base.:(^)), Int64, Base.Val{52}})
#=    1.6 ms =# precompile(Tuple{typeof(Base.getproperty), Random.SamplerTrivial{Random.UInt52Raw{Int64}, Int64}, Symbol})
#=    3.0 ms =# precompile(Tuple{typeof(Base.getproperty), Random.Masked{Int64, Random.UInt52Raw{Int64}}, Symbol})
#=    1.6 ms =# precompile(Tuple{Type{Dates.Hour}, Int64})
#=    1.7 ms =# precompile(Tuple{typeof(Base.:(-)), Int32})
#=    2.2 ms =# precompile(Tuple{Type{NamedTuple{(:read, :write, :append, :truncate), T} where T<:Tuple}, Tuple{Bool, Bool, Nothing, Nothing}})
#=    2.2 ms =# precompile(Tuple{typeof(Core.kwcall), NamedTuple{(:read, :write, :append, :truncate), Tuple{Bool, Bool, Nothing, Nothing}}, typeof(Base.open_flags)})
#=    2.4 ms =# precompile(Tuple{Dates.var"##s56#34", Vararg{Any, 5}})
#=    2.0 ms =# precompile(Tuple{Type{NamedTuple{(:append,), T} where T<:Tuple}, Tuple{Bool}})
#=    2.1 ms =# precompile(Tuple{typeof(Base.pairs), NamedTuple{(:append,), Tuple{Bool}}})
#=    2.1 ms =# precompile(Tuple{typeof(Base.getproperty), Base.BottomRF{typeof(Base.mul_prod)}, Symbol})
#=    1.9 ms =# precompile(Tuple{typeof(Base.literal_pow), typeof(Base.:(^)), Int64, Base.Val{30}})
#=    2.0 ms =# precompile(Tuple{typeof(Base._cshp), Int64, Tuple{Bool}, Tuple{}, Tuple{Int64}})
#=    2.2 ms =# precompile(Tuple{Type{NamedTuple{(:error,), T} where T<:Tuple}, Tuple{Bool}})
#=    1.8 ms =# precompile(Tuple{typeof(Base.isnothing), Base.Some{Nothing}})
#=    2.4 ms =# precompile(Tuple{Type{UInt8}, Int32})
#=    1.9 ms =# precompile(Tuple{typeof(Base.:(<<)), UInt8, Int64})
#=    2.0 ms =# precompile(Tuple{typeof(Base.:(>)), UInt32, UInt32})
#=    1.4 ms =# precompile(Tuple{typeof(Base.:(!=)), UInt32, UInt32})
#=  437.6 ms =# precompile(Tuple{typeof(Core.kwcall), NamedTuple{(:testsuite,), Tuple{Base.Dict{String, Expr}}}, typeof(ParallelTestRunner.runtests), Module, Array{String, 1}})
#=  704.2 ms =# precompile(Tuple{ParallelTestRunner.var"##runtests#21", Base.Dict{String, Expr}, Expr, Expr, Base.Returns{Nothing}, Base.TTY, Base.TTY, typeof(ParallelTestRunner.runtests), Module, ParallelTestRunner.ParsedArgs})
#=   44.6 ms =# precompile(Tuple{typeof(Serialization.deserialize), Serialization.Serializer{Base.IOStream}, Type{Base.Dict{String, Float64}}})
#=   14.9 ms =# precompile(Tuple{typeof(Base.setindex!), Base.Dict{String, Float64}, Float64, String})
#=    1.8 ms =# precompile(Tuple{Type{Base.Order.By{T, O} where O where T}, ParallelTestRunner.var"#36#37"{Base.Dict{String, Float64}}, Base.Order.ForwardOrdering})
#=   75.5 ms =# precompile(Tuple{typeof(Base.Sort._sort!), Array{String, 1}, Base.Sort.DefaultStable, Base.Order.By{ParallelTestRunner.var"#36#37"{Base.Dict{String, Float64}}, Base.Order.ForwardOrdering}, NamedTuple{(:scratch,), Tuple{Nothing}}})
#=    1.5 ms =# precompile(Tuple{typeof(Base.clamp), Int64, Int64, Int64})
#=    3.8 ms =# precompile(Tuple{typeof(Base.fill), Nothing, Int64})
#=    2.8 ms =# precompile(Tuple{typeof(Base.printstyled), Base.TTY, String, Vararg{String}})
#=    3.2 ms =# precompile(Tuple{typeof(Core.kwcall), NamedTuple{(:color,), Tuple{Symbol}}, typeof(Base.printstyled), Base.TTY, String, Vararg{String}})
#=    3.7 ms =# precompile(Tuple{typeof(Base.flush), Base.TTY})
#=    2.2 ms =# precompile(Tuple{typeof(Base.iterate), Array{Nothing, 1}})
#=    3.3 ms =# precompile(Tuple{typeof(Base.push!), Array{Task, 1}, Task})
#=    2.2 ms =# precompile(Tuple{typeof(Base.iterate), Array{Nothing, 1}, Int64})
#=   10.5 ms =# precompile(Tuple{typeof(Base.any), Function, Array{Task, 1}})
#=    4.0 ms =# precompile(Tuple{typeof(Base._any), typeof(Base.istaskfailed), Array{Task, 1}, Base.Colon})
#=    2.8 ms =# precompile(Tuple{typeof(Base.getproperty), Base.MappingRF{typeof(Base.length), typeof(Base.add_sum)}, Symbol})
#=    2.0 ms =# precompile(Tuple{typeof(Base.literal_pow), typeof(Base.:(^)), Int64, Base.Val{20}})
#=  272.2 ms =# precompile(Tuple{ParallelTestRunner.var"#49#50"{ParallelTestRunner.ParsedArgs, Base.Channel{Tuple}, ParallelTestRunner.var"#update_status#42"{ParallelTestRunner.var"#clear_status#41"{Base.RefValue{Int64}, ParallelTestRunner.TestIOContext}, Base.RefValue{Int64}, ParallelTestRunner.TestIOContext, Base.Dict{String, Float64}, Array{Any, 1}, Base.Dict{String, Float64}, Array{String, 1}}, ParallelTestRunner.var"#clear_status#41"{Base.RefValue{Int64}, ParallelTestRunner.TestIOContext}, ParallelTestRunner.TestIOContext, ParallelTestRunner.var"#stop_work#38", Base.Dict{String, Float64}, Float64, Array{String, 1}}})
#=    3.7 ms =# precompile(Tuple{typeof(Base.getproperty), RelocatableFolders.Path, Symbol})
#=    2.1 ms =# precompile(Tuple{typeof(Base.hash), String})
#=    1.2 ms =# precompile(Tuple{typeof(Base.abs), UInt64})
#=    1.1 ms =# precompile(Tuple{typeof(Base.unsigned), UInt64})
#=    1.4 ms =# precompile(Tuple{typeof(Base.:(<)), UInt64, Int64})
#=    1.3 ms =# precompile(Tuple{typeof(Base.:(>=)), UInt64, Int64})
#=    1.6 ms =# precompile(Tuple{typeof(Base.ispow2), Int64})
#=    1.5 ms =# precompile(Tuple{typeof(Base.:(>)), UInt64, Int64})
#=    1.7 ms =# precompile(Tuple{typeof(Base.rem), UInt64, Int64})
#=    1.6 ms =# precompile(Tuple{typeof(Base.keys), Base.Dict{String, Array{UInt8, 1}}})
#=    1.5 ms =# precompile(Tuple{typeof(Base.getproperty), Base.KeySet{String, Base.Dict{String, Array{UInt8, 1}}}, Symbol})
#=    2.2 ms =# precompile(Tuple{Type{NamedTuple{(:detach, :windows_hide), T} where T<:Tuple}, Tuple{Bool, Bool}})
#=    2.0 ms =# precompile(Tuple{typeof(Base.getproperty), Base.Set{Base.Process}, Symbol})
#=    1.5 ms =# precompile(Tuple{Type{Base.KeySet{K, T} where T<:(Base.AbstractDict{K, V} where V) where K}, Base.Dict{Base.Process, Nothing}})
#=    1.4 ms =# precompile(Tuple{typeof(Base.getproperty), Base.KeySet{Base.Process, Base.Dict{Base.Process, Nothing}}, Symbol})
#=    2.0 ms =# precompile(Tuple{Type{NamedTuple{(:pollint,), T} where T<:Tuple}, Tuple{Float64}})
#=    2.2 ms =# precompile(Tuple{typeof(Base.getproperty), NamedTuple{(:from_host_call_with_response, :from_host_call_without_response, :from_host_fake_interrupt, :from_worker_call_result, :from_worker_call_failure, :special_serialization_failure, :special_worker_terminated), NTuple{7, UInt8}}, Symbol})
#=  504.9 ms =# precompile(Tuple{ParallelTestRunner.var"#51#52"{Base.Dict{String, Expr}, Expr, Expr, Base.Returns{Nothing}, ParallelTestRunner.ParsedArgs, Base.Channel{Tuple}, ParallelTestRunner.TestIOContext, ParallelTestRunner.var"#stop_work#38", Base.ReentrantLock, Base.Dict{String, Float64}, Array{Any, 1}, Array{String, 1}}})
#=    4.1 ms =# precompile(Tuple{typeof(Base.getindex), Type{String}, String, String, String})
#=    2.6 ms =# precompile(Tuple{typeof(Base.setproperty!), Base.Process, Symbol, Base.DevNull})
#=   31.1 ms =# precompile(Tuple{typeof(Base.push!), Base.Set{Base.Process}, Base.Process})
#=    4.1 ms =# precompile(Tuple{Malt.var"#29#30"{Base.Pipe}})
#=   16.4 ms =# precompile(Tuple{typeof(Sockets.connect), UInt16})
#=    6.8 ms =# precompile(Tuple{typeof(Malt._buffer_writes), Sockets.TCPSocket})
#=    8.8 ms =# precompile(Tuple{typeof(Base.getproperty), ParallelTestRunner.PTRWorker, Symbol})
#=    8.8 ms =# precompile(Tuple{ParallelTestRunner.var"#stdio_loop##0#stdio_loop##1"{Malt.Worker, Base.GenericIOBuffer{Memory{UInt8}}}})
#=    6.9 ms =# precompile(Tuple{ParallelTestRunner.var"#stdio_loop##2#stdio_loop##3"{Malt.Worker, Base.GenericIOBuffer{Memory{UInt8}}}})
#=    7.0 ms =# precompile(Tuple{typeof(Malt.remote_eval_wait), Module, Malt.Worker, Expr})
#=  157.7 ms =# precompile(Tuple{typeof(Serialization.serialize), Sockets.TCPSocket, Tuple{typeof(Core.eval), Tuple{Module, Expr}, Base.Pairs{Symbol, Union{}, Nothing, NamedTuple{(), Tuple{}}}, Bool}})
#=    2.1 ms =# precompile(Tuple{typeof(Serialization.serialize), Serialization.Serializer{Sockets.TCPSocket}, Core.TypeofBottom})
#=    1.6 ms =# precompile(Tuple{typeof(Serialization.serialize), Serialization.Serializer{Sockets.TCPSocket}, Tuple{}})
#=    1.7 ms =# precompile(Tuple{typeof(Base.Iterators.countfrom), Int64})
#=    1.7 ms =# precompile(Tuple{typeof(Base.iterate), Base.Iterators.Count{Int64, Int64}})
#=    1.7 ms =# precompile(Tuple{Type{Malt.WorkerResult}, UInt8, Nothing})
#=    2.1 ms =# precompile(Tuple{typeof(Base.convert), Type{Malt.WorkerResult}, Malt.WorkerResult})
#=    2.3 ms =# precompile(Tuple{typeof(Base.iterate), Base.Iterators.Count{Int64, Int64}, Int64})
#=   71.8 ms =# precompile(Tuple{Malt.var"#_exit_loop##0#_exit_loop##1"{Malt.Worker}})
#=    2.2 ms =# precompile(Tuple{Type{NamedTuple{(:rethrow_regular,), T} where T<:Tuple}, Tuple{Bool}})
#=  287.6 ms =# precompile(Tuple{Malt.var"#_receive_loop##0#_receive_loop##1"{Malt.Worker, Sockets.TCPSocket}})
#=    8.6 ms =# precompile(Tuple{Base.var"#readcb_specialized#uv_readcb##0", Sockets.TCPSocket, Int64, UInt64})
#=    7.4 ms =# precompile(Tuple{typeof(Malt.remote_call_fetch), Function, Malt.Worker, Function, Vararg{Any}})
#=    2.3 ms =# precompile(Tuple{Malt.var"##remote_call_fetch#68", Base.Pairs{Symbol, Union{}, Nothing, NamedTuple{(), Tuple{}}}, typeof(Malt.remote_call_fetch), Function, Malt.Worker, Function, Vararg{Any}})
#=   18.7 ms =# precompile(Tuple{typeof(Malt._send_receive), Malt.Worker, UInt8, Tuple{typeof(Core.invokelatest), Tuple{typeof(ParallelTestRunner.runtest), Expr, String, Expr}, Base.Pairs{Symbol, Union{}, Nothing, NamedTuple{(), Tuple{}}}, Bool}})
#=   21.3 ms =# precompile(Tuple{typeof(Serialization.serialize), Sockets.TCPSocket, Tuple{typeof(Core.invokelatest), Tuple{typeof(ParallelTestRunner.runtest), Expr, String, Expr}, Base.Pairs{Symbol, Union{}, Nothing, NamedTuple{(), Tuple{}}}, Bool}})
#=    2.0 ms =# precompile(Tuple{typeof(Serialization.serialize), Serialization.Serializer{Sockets.TCPSocket}, Bool})
#=   18.8 ms =# precompile(Tuple{typeof(Serialization.deserialize), Serialization.Serializer{Sockets.TCPSocket}, typeof(DataType)})
#=    5.0 ms =# precompile(Tuple{typeof(Serialization.deserialize_fillarray!), Array{Any, 1}, Serialization.Serializer{Sockets.TCPSocket}})
#=   33.0 ms =# precompile(Tuple{typeof(Base.put!), Base.Channel{Tuple}, Tuple{Symbol, String, Int64, ParallelTestRunner.TestRecord}})
#=    3.4 ms =# precompile(Tuple{typeof(Base.:(!=)), ParallelTestRunner.PTRWorker, ParallelTestRunner.PTRWorker})
#=    2.0 ms =# precompile(Tuple{typeof(Base.getindex), ParallelTestRunner.TestRecord})
#=   64.7 ms =# precompile(Tuple{typeof(ParallelTestRunner.print_test_finished), ParallelTestRunner.TestRecord, Int64, String, ParallelTestRunner.TestIOContext})
#=    8.2 ms =# precompile(Tuple{typeof(Base.iterate), Array{Task, 1}})
#=    6.2 ms =# precompile(Tuple{typeof(Base.iterate), Array{Task, 1}, Int64})
#=   12.8 ms =# precompile(Tuple{typeof(Base.indexed_iterate), Tuple{String, ParallelTestRunner.TestRecord, String, Float64, Float64}, Int64})
#=    9.0 ms =# precompile(Tuple{typeof(Base.indexed_iterate), Tuple{String, ParallelTestRunner.TestRecord, String, Float64, Float64}, Int64, Int64})
#=   14.3 ms =# precompile(Tuple{typeof(Core.kwcall), NamedTuple{(:start, :stop, :verbose), Tuple{Float64, Float64, Bool}}, ParallelTestRunner.var"#create_testset#55"{ParallelTestRunner.var"#create_testset#30#56"}, String})
#=   61.9 ms =# precompile(Tuple{ParallelTestRunner.var"#collect_results#57"{Test.DefaultTestSet, Base.Dict{String, Float64}, Array{Any, 1}, Base.Dict{String, Float64}, Array{String, 1}}})
#=    1.7 ms =# precompile(Tuple{typeof(Base.push!), Base.Set{String}, String})
#=    4.2 ms =# precompile(Tuple{typeof(ParallelTestRunner.with_testset), ParallelTestRunner.var"#60#61"{Test.DefaultTestSet}, Test.DefaultTestSet})
#=    4.2 ms =# precompile(Tuple{typeof(Test.record), Test.DefaultTestSet, Test.AbstractTestSet})
#=    1.7 ms =# precompile(Tuple{Type{NamedTuple{(:waitfor,), T} where T<:Tuple}, Tuple{Int64}})
#=    3.8 ms =# precompile(Tuple{ParallelTestRunner.var"#53#54"})
#=   29.4 ms =# precompile(Tuple{IOCapture.var"##capture#1", Type, Bool, Bool, Base.GenericIOBuffer{Memory{UInt8}}, Array{Any, 1}, typeof(IOCapture.capture), ParallelTestRunner.var"#64#65"{Test.DefaultTestSet}})
#=    4.5 ms =# precompile(Tuple{Base.RedirectStdStream, Base.IOContext{Base.PipeEndpoint}})
#=    9.9 ms =# precompile(Tuple{typeof(Base.CoreLogging.with_logstate), IOCapture.var"#12#13"{Type{Any}, ParallelTestRunner.var"#64#65"{Test.DefaultTestSet}, Base.IOContext{Base.PipeEndpoint}, Base.IOContext{Base.PipeEndpoint}, Base.TTY, Base.TTY}, Base.CoreLogging.LogState})
#=    7.1 ms =# precompile(Tuple{IOCapture.var"#10#11"{Base.GenericIOBuffer{Memory{UInt8}}, Base.Pipe}})
#=   21.9 ms =# precompile(Tuple{typeof(Core.kwcall), NamedTuple{(:bold, :italic, :underline, :blink, :reverse, :hidden, :color), Tuple{Bool, Bool, Bool, Bool, Bool, Bool, Symbol}}, typeof(Base.printstyled), Base.IOContext{Base.PipeEndpoint}, String, Vararg{String}})
#=    3.7 ms =# precompile(Tuple{Base.var"##printstyled#851", Bool, Bool, Bool, Bool, Bool, Bool, Symbol, typeof(Base.printstyled), Base.IOContext{Base.PipeEndpoint}, String, Vararg{String}})
#=    4.7 ms =# precompile(Tuple{typeof(Core.kwcall), NamedTuple{(:bold, :italic, :underline, :blink, :reverse, :hidden), NTuple{6, Bool}}, typeof(Base.with_output_color), Function, Symbol, Base.IOContext{Base.PipeEndpoint}, String, Vararg{String}})
#=   70.7 ms =# precompile(Tuple{Base.var"##with_output_color#850", Bool, Bool, Bool, Bool, Bool, Bool, typeof(Base.with_output_color), Function, Symbol, Base.IOContext{Base.PipeEndpoint}, String, Vararg{String}})
#=    1.7 ms =# precompile(Tuple{typeof(Base.print), Base.IOContext{Base.PipeEndpoint}, String})

and in v1.14

#=    1.6 ms =# precompile(Tuple{Type{Pair{A, B} where B where A}, String, Expr})
#=   42.9 ms =# precompile(Tuple{Type{Base.Dict{K, V} where V where K}, Pair{String, Expr}})
#=    1.9 ms =# precompile(Tuple{Type{NamedTuple{(:testsuite,), T} where T<:Tuple}, Tuple{Base.Dict{String, Expr}}})
#=    1.9 ms =# precompile(Tuple{Type{NamedTuple{(:typ,), T} where T<:Tuple}, Tuple{typeof(DataType)}})
#=    1.7 ms =# precompile(Tuple{typeof(Base.startswith), String})
#=    1.6 ms =# precompile(Tuple{typeof(Base.getproperty), Base.Some{Nothing}, Symbol})
#=    1.9 ms =# precompile(Tuple{Type{Dates.Hour}, Int64})
#=    1.6 ms =# precompile(Tuple{typeof(Base.:(-)), Int32})
#=    1.9 ms =# precompile(Tuple{Type{NamedTuple{(:append,), T} where T<:Tuple}, Tuple{Bool}})
#=    1.5 ms =# precompile(Tuple{typeof(Base.pairs), NamedTuple{(:append,), Tuple{Bool}}})
#=    1.8 ms =# precompile(Tuple{typeof(Base.literal_pow), typeof(Base.:(^)), Int64, Base.Val{30}})
#=    1.7 ms =# precompile(Tuple{typeof(Base._cshp), Int64, Tuple{Bool}, Tuple{}, Tuple{Int64}})
#=    1.7 ms =# precompile(Tuple{typeof(Base.isnothing), Base.Some{Nothing}})
#=    1.5 ms =# precompile(Tuple{Type{Pair{A, B} where B where A}, Base.ScopedValues.ScopedValue{Bool}, Bool})
#=   58.3 ms =# precompile(Tuple{Base.Compiler.var"#inferiterate_2arg#abstract_iteration##1"{Base.Compiler.InferenceLattice{Base.Compiler.ConditionalsLattice{Base.Compiler.PartialsLattice{Base.Compiler.ConstsLattice}}}, Array{Any, 1}, Array{Base.Compiler.CallMeta, 1}, Type{Pair{Base.ScopedValues.ScopedValue{Bool}, Bool}}, Array{Base.Compiler.VarState, 1}, Base.Compiler.Future{Base.Compiler.AbstractIterationResult}, typeof(Base.iterate)}, Base.Compiler.NativeInterpreter, Base.Compiler.InferenceState})
#=   58.3 ms =# precompile(Tuple{Base.Compiler.var"#inferiterate_2arg#abstract_iteration##1"{Base.Compiler.InferenceLattice{Base.Compiler.ConditionalsLattice{Base.Compiler.PartialsLattice{Base.Compiler.ConstsLattice}}}, Array{Any, 1}, Array{Base.Compiler.CallMeta, 1}, Type{Pair{Base.ScopedValues.ScopedValue{Test.AbstractTestSet}, var"#s194"} where var"#s194"<:Test.AbstractTestSet}, Array{Base.Compiler.VarState, 1}, Base.Compiler.Future{Base.Compiler.AbstractIterationResult}, typeof(Base.iterate)}, Base.Compiler.NativeInterpreter, Base.Compiler.InferenceState})
#=    2.2 ms =# precompile(Tuple{Type{UInt8}, Int32})
#=    3.1 ms =# precompile(Tuple{typeof(Base.:(<<)), UInt8, Int64})
#=    1.9 ms =# precompile(Tuple{typeof(Base.:(>)), UInt32, UInt32})
#=    1.5 ms =# precompile(Tuple{typeof(Base.:(!=)), UInt32, UInt32})
#=  523.5 ms =# precompile(Tuple{typeof(Core.kwcall), NamedTuple{(:testsuite,), Tuple{Base.Dict{String, Expr}}}, typeof(ParallelTestRunner.runtests), Module, Array{String, 1}})
#=    1.8 ms =# precompile(Tuple{typeof(Base.something), Nothing, Symbol})
#=  882.9 ms =# precompile(Tuple{ParallelTestRunner.var"##runtests#21", Base.Dict{String, Expr}, Expr, Expr, Base.Returns{Nothing}, Base.TTY, Base.TTY, typeof(ParallelTestRunner.runtests), Module, ParallelTestRunner.ParsedArgs})
#=   34.6 ms =# precompile(Tuple{typeof(Serialization.deserialize), Serialization.Serializer{Base.IOStream}, Type{Base.Dict{String, Float64}}})
#=   16.3 ms =# precompile(Tuple{typeof(Base.setindex!), Base.Dict{String, Float64}, Float64, String})
#=    1.6 ms =# precompile(Tuple{Type{Base.Order.By{T, O} where O where T}, ParallelTestRunner.var"#36#37"{Base.Dict{String, Float64}}, Base.Order.ForwardOrdering})
#=   85.9 ms =# precompile(Tuple{typeof(Base.Sort._sort!), Array{String, 1}, Base.Sort.DefaultStable, Base.Order.By{ParallelTestRunner.var"#36#37"{Base.Dict{String, Float64}}, Base.Order.ForwardOrdering}, NamedTuple{(:scratch,), Tuple{Nothing}}})
#=    1.4 ms =# precompile(Tuple{typeof(Base.clamp), Int64, Int64, Int64})
#=    5.2 ms =# precompile(Tuple{typeof(Base.fill), Nothing, Int64})
#=    4.0 ms =# precompile(Tuple{typeof(Base.printstyled), Base.TTY, String, Vararg{String}})
#=    4.4 ms =# precompile(Tuple{typeof(Core.kwcall), NamedTuple{(:color,), Tuple{Symbol}}, typeof(Base.printstyled), Base.TTY, String, Vararg{String}})
#=    2.8 ms =# precompile(Tuple{typeof(Base.iterate), Array{Nothing, 1}})
#=    3.8 ms =# precompile(Tuple{typeof(Base.push!), Array{Task, 1}, Task})
#=    2.4 ms =# precompile(Tuple{typeof(Base.iterate), Array{Nothing, 1}, Int64})
#=    4.3 ms =# precompile(Tuple{typeof(Base.any), Function, Array{Task, 1}})
#=    3.6 ms =# precompile(Tuple{typeof(Base._any), typeof(Base.istaskfailed), Array{Task, 1}, Base.Colon})
#=    2.8 ms =# precompile(Tuple{typeof(Base.getproperty), Base.MappingRF{typeof(Base.length), typeof(Base.add_sum)}, Symbol})
#=    1.9 ms =# precompile(Tuple{typeof(Base.literal_pow), typeof(Base.:(^)), Int64, Base.Val{20}})
#=    1.9 ms =# precompile(Tuple{typeof(Base.iszero), Float64})
#=  378.5 ms =# precompile(Tuple{ParallelTestRunner.var"#49#50"{ParallelTestRunner.ParsedArgs, Base.Channel{Tuple}, ParallelTestRunner.var"#update_status#42"{ParallelTestRunner.var"#clear_status#41"{Base.RefValue{Int64}, ParallelTestRunner.TestIOContext}, Base.RefValue{Int64}, ParallelTestRunner.TestIOContext, Base.Dict{String, Float64}, Array{Any, 1}, Base.Dict{String, Float64}, Array{String, 1}}, ParallelTestRunner.var"#clear_status#41"{Base.RefValue{Int64}, ParallelTestRunner.TestIOContext}, ParallelTestRunner.TestIOContext, ParallelTestRunner.var"#stop_work#38", Base.Dict{String, Float64}, Float64, Array{String, 1}}})
#=    4.9 ms =# precompile(Tuple{typeof(Base.getproperty), RelocatableFolders.Path, Symbol})
#=    1.5 ms =# precompile(Tuple{typeof(Base.hash), String})
#=    1.1 ms =# precompile(Tuple{typeof(Base.abs), UInt64})
#=    1.1 ms =# precompile(Tuple{typeof(Base.unsigned), UInt64})
#=    1.4 ms =# precompile(Tuple{typeof(Base.:(<)), UInt64, Int64})
#=    1.4 ms =# precompile(Tuple{typeof(Base.:(>=)), UInt64, Int64})
#=    1.4 ms =# precompile(Tuple{typeof(Base.ispow2), Int64})
#=    1.3 ms =# precompile(Tuple{typeof(Base.:(>)), UInt64, Int64})
#=    1.5 ms =# precompile(Tuple{typeof(Base.rem), UInt64, Int64})
#=    1.4 ms =# precompile(Tuple{typeof(Base.keys), Base.Dict{String, Array{UInt8, 1}}})
#=    1.3 ms =# precompile(Tuple{typeof(Base.getproperty), Base.KeySet{String, Base.Dict{String, Array{UInt8, 1}}}, Symbol})
#=    2.0 ms =# precompile(Tuple{Type{NamedTuple{(:detach, :windows_hide), T} where T<:Tuple}, Tuple{Bool, Bool}})
#=    1.9 ms =# precompile(Tuple{typeof(Base.getproperty), Base.Set{Base.Process}, Symbol})
#=    1.5 ms =# precompile(Tuple{Type{Base.KeySet{K, T} where T<:(Base.AbstractDict{K, V} where V) where K}, Base.Dict{Base.Process, Nothing}})
#=    1.5 ms =# precompile(Tuple{typeof(Base.getproperty), Base.KeySet{Base.Process, Base.Dict{Base.Process, Nothing}}, Symbol})
#=    1.8 ms =# precompile(Tuple{Type{NamedTuple{(:pollint,), T} where T<:Tuple}, Tuple{Float64}})
#=    2.1 ms =# precompile(Tuple{typeof(Base.getproperty), NamedTuple{(:from_host_call_with_response, :from_host_call_without_response, :from_host_fake_interrupt, :from_worker_call_result, :from_worker_call_failure, :special_serialization_failure, :special_worker_terminated), NTuple{7, UInt8}}, Symbol})
#=  665.4 ms =# precompile(Tuple{ParallelTestRunner.var"#51#52"{Base.Dict{String, Expr}, Expr, Expr, Base.Returns{Nothing}, ParallelTestRunner.ParsedArgs, Base.Channel{Tuple}, ParallelTestRunner.TestIOContext, ParallelTestRunner.var"#stop_work#38", Base.ReentrantLock, Base.Dict{String, Float64}, Array{Any, 1}, Array{String, 1}}})
#=    6.3 ms =# precompile(Tuple{typeof(Base.print), Base.GenericIOBuffer{Memory{UInt8}}, RelocatableFolders.Path})
#=    3.8 ms =# precompile(Tuple{typeof(Base.getindex), Type{String}, String, String, String})
#=    4.0 ms =# precompile(Tuple{typeof(Base.setproperty!), Base.Process, Symbol, Base.DevNull})
#=    7.6 ms =# precompile(Tuple{Malt.var"#29#30"{Base.Pipe}})
#=   17.9 ms =# precompile(Tuple{typeof(Sockets.connect), UInt16})
#=    7.8 ms =# precompile(Tuple{typeof(Malt._buffer_writes), Sockets.TCPSocket})
#=    9.2 ms =# precompile(Tuple{ParallelTestRunner.var"#stdio_loop##0#stdio_loop##1"{Malt.Worker, Base.GenericIOBuffer{Memory{UInt8}}}})
#=    9.3 ms =# precompile(Tuple{typeof(Base.getproperty), ParallelTestRunner.PTRWorker, Symbol})
#=    8.0 ms =# precompile(Tuple{ParallelTestRunner.var"#stdio_loop##2#stdio_loop##3"{Malt.Worker, Base.GenericIOBuffer{Memory{UInt8}}}})
#=    8.1 ms =# precompile(Tuple{typeof(Malt.remote_eval_wait), Module, Malt.Worker, Expr})
#=  159.3 ms =# precompile(Tuple{typeof(Serialization.serialize), Sockets.TCPSocket, Tuple{typeof(Core.eval), Tuple{Module, Expr}, Base.Pairs{Symbol, Union{}, Nothing, NamedTuple{(), Tuple{}}}, Bool}})
#=    3.0 ms =# precompile(Tuple{typeof(Serialization.serialize), Serialization.Serializer{Sockets.TCPSocket}, Core.TypeofBottom})
#=    2.7 ms =# precompile(Tuple{typeof(Serialization.serialize), Serialization.Serializer{Sockets.TCPSocket}, Tuple{}})
#=    1.5 ms =# precompile(Tuple{typeof(Base.Iterators.countfrom), Int64})
#=    1.5 ms =# precompile(Tuple{typeof(Base.iterate), Base.Iterators.Count{Int64, Int64}})
#=    1.6 ms =# precompile(Tuple{Type{Malt.WorkerResult}, UInt8, Nothing})
#=    1.7 ms =# precompile(Tuple{typeof(Base.convert), Type{Malt.WorkerResult}, Malt.WorkerResult})
#=    2.1 ms =# precompile(Tuple{typeof(Base.iterate), Base.Iterators.Count{Int64, Int64}, Int64})
#=   73.1 ms =# precompile(Tuple{Malt.var"#_exit_loop##0#_exit_loop##1"{Malt.Worker}})
#=    2.1 ms =# precompile(Tuple{Type{NamedTuple{(:rethrow_regular,), T} where T<:Tuple}, Tuple{Bool}})
#=  316.5 ms =# precompile(Tuple{Malt.var"#_receive_loop##0#_receive_loop##1"{Malt.Worker, Sockets.TCPSocket}})
#=    9.3 ms =# precompile(Tuple{Base.var"#readcb_specialized#uv_readcb##0", Sockets.TCPSocket, Int64, UInt64})
#=    8.5 ms =# precompile(Tuple{typeof(Malt.remote_call_fetch), Function, Malt.Worker, Function, Vararg{Any}})
#=    3.4 ms =# precompile(Tuple{Malt.var"##remote_call_fetch#68", Base.Pairs{Symbol, Union{}, Nothing, NamedTuple{(), Tuple{}}}, typeof(Malt.remote_call_fetch), Function, Malt.Worker, Function, Vararg{Any}})
#=   30.0 ms =# precompile(Tuple{typeof(Malt._send_receive), Malt.Worker, UInt8, Tuple{typeof(Core.invokelatest), Tuple{typeof(ParallelTestRunner.runtest), Expr, String, Expr}, Base.Pairs{Symbol, Union{}, Nothing, NamedTuple{(), Tuple{}}}, Bool}})
#=   23.1 ms =# precompile(Tuple{typeof(Serialization.serialize), Sockets.TCPSocket, Tuple{typeof(Core.invokelatest), Tuple{typeof(ParallelTestRunner.runtest), Expr, String, Expr}, Base.Pairs{Symbol, Union{}, Nothing, NamedTuple{(), Tuple{}}}, Bool}})
#=    3.1 ms =# precompile(Tuple{typeof(Serialization.serialize), Serialization.Serializer{Sockets.TCPSocket}, Bool})
#=   16.4 ms =# precompile(Tuple{typeof(Serialization.deserialize), Serialization.Serializer{Sockets.TCPSocket}, typeof(DataType)})
#=    5.0 ms =# precompile(Tuple{typeof(Serialization.deserialize), Serialization.Serializer{Sockets.TCPSocket}, Type{Base.ReentrantLock}})
#=    5.0 ms =# precompile(Tuple{typeof(Serialization.deserialize_fillarray!), Array{Any, 1}, Serialization.Serializer{Sockets.TCPSocket}})
#=   29.8 ms =# precompile(Tuple{typeof(Base.put!), Base.Channel{Tuple}, Tuple{Symbol, String, Int64, ParallelTestRunner.TestRecord}})
#=    3.5 ms =# precompile(Tuple{typeof(Base.:(!=)), ParallelTestRunner.PTRWorker, ParallelTestRunner.PTRWorker})
#=    1.4 ms =# precompile(Tuple{typeof(Base.getindex), ParallelTestRunner.TestRecord})
#=   68.8 ms =# precompile(Tuple{typeof(ParallelTestRunner.print_test_finished), ParallelTestRunner.TestRecord, Int64, String, ParallelTestRunner.TestIOContext})
#=   14.6 ms =# precompile(Tuple{typeof(Base.iterate), Array{Task, 1}})
#=    8.7 ms =# precompile(Tuple{typeof(Base.iterate), Array{Task, 1}, Int64})
#=   13.4 ms =# precompile(Tuple{typeof(Base.indexed_iterate), Tuple{String, ParallelTestRunner.TestRecord, String, Float64, Float64}, Int64})
#=    9.7 ms =# precompile(Tuple{typeof(Base.indexed_iterate), Tuple{String, ParallelTestRunner.TestRecord, String, Float64, Float64}, Int64, Int64})
#=   20.8 ms =# precompile(Tuple{typeof(Core.kwcall), NamedTuple{(:start, :stop, :verbose), Tuple{Float64, Float64, Bool}}, ParallelTestRunner.var"#create_testset#55"{ParallelTestRunner.var"#create_testset#30#56"}, String})
#=   55.9 ms =# precompile(Tuple{ParallelTestRunner.var"#collect_results#57"{Test.DefaultTestSet, Base.Dict{String, Float64}, Array{Any, 1}, Base.Dict{String, Float64}, Array{String, 1}}})
#=    1.5 ms =# precompile(Tuple{typeof(Base.push!), Base.Set{String}, String})
#=   10.0 ms =# precompile(Tuple{typeof(ParallelTestRunner.with_testset), ParallelTestRunner.var"#60#61"{Test.DefaultTestSet}, Test.DefaultTestSet})
#=    1.6 ms =# precompile(Tuple{Type{NamedTuple{(:waitfor,), T} where T<:Tuple}, Tuple{Int64}})
#=    4.8 ms =# precompile(Tuple{ParallelTestRunner.var"#53#54"})
#=  117.7 ms =# precompile(Tuple{typeof(Test.print_test_results), Base.TTY, Test.DefaultTestSet, Int64})

The former adds up to 3.3266 s, the latter to 3.9617 s, but

julia> using ParallelTestRunner

julia> @time runtests(ParallelTestRunner, Base.ARGS; testsuite=Dict("test" => :(@test true)), init_code=:(), stdout=devnull, stderr=devnull);
  4.616058 seconds (12.39 M allocations: 615.217 MiB, 3.15% gc time, 68.45% compilation time: <1% of which was recompilation) # v1.12
  5.890920 seconds (10.12 M allocations: 556.957 MiB, 3.21% gc time, 60.71% compilation time: <1% of which was recompilation) # v1.14

so the 1.3 s difference isn't only explained by the extra precompilation. You'll want to do proper profiling to see where the time is going.

[giordano]

For what is worth, with the simple

diff --git a/src/ParallelTestRunner.jl b/src/ParallelTestRunner.jl
index 3e1c90e..3897613 100644
--- a/src/ParallelTestRunner.jl
+++ b/src/ParallelTestRunner.jl
@@ -1236,4 +1236,6 @@ function runtests(mod::Module, args::ParsedArgs;
 end
 runtests(mod::Module, ARGS::Array{String}; kwargs...) = runtests(mod, parse_args(ARGS); kwargs...)
 
+@assert precompile(Tuple{typeof(Core.kwcall), NamedTuple{(:testsuite,), Tuple{Base.Dict{String, Expr}}}, typeof(ParallelTestRunner.runtests), Module, Array{String, 1}})
+
 end

I see

julia> using ParallelTestRunner

julia> @time runtests(ParallelTestRunner, Base.ARGS; testsuite=Dict("test" => :(@test true)), init_code=:(), stdout=devnull, stderr=devnull);
  3.768501 seconds (7.51 M allocations: 373.898 MiB, 3.06% gc time, 61.74% compilation time: 2% of which was recompilation) # v1.12
  3.787556 seconds (5.96 M allocations: 330.548 MiB, 2.73% gc time, 62.71% compilation time: <1% of which was recompilation) # v1.14

[christiangnrd]

For what is worth, with the simple...

This fully fixes it for GPUArrays and Metal.jl too using:

# GPUArrays.jl fix
@assert precompile(Tuple{typeof(Core.kwcall), NamedTuple{(:testsuite, :init_code, :init_worker_code), Tuple{Base.Dict{String, Expr}, Expr, Expr}}, typeof(ParallelTestRunner.runtests), Module, Array{String, 1}})

# Metal.jl fix
@assert precompile(Tuple{typeof(Core.kwcall), NamedTuple{(:testsuite, :init_code, :init_worker_code, :test_worker), Tuple{Base.Dict{String, Expr}, Expr, Expr, typeof(test_worker)}}, typeof(ParallelTestRunner.runtests), Module, Array{String, 1}})

respectively, but I don't think it's a great user experience to have the user add a precompile statement in the package runtests.jl.

I'm not sure how to resolve this otherwise though because in Metal's case, it receives a function defined in runtests.jl.

[giordano]

but I don't think it's a great user experience to have the user add a precompile statement in the package runtests.jl.

Why adding that to runtests.jl? We can add it here.

[christiangnrd]

The required precompile statement is different for metal and gpuarrays

[giordano]

BTW, I have no idea how to reproduce your issue: after ]add ParallelTestRunner Metal#main I get

julia> using Pkg

julia> Pkg.test("Metal"; test_args=`mtl/size`)
[...]
Running 1 tests in parallel. If this is too many, specify the `--jobs=N` argument to the tests, or set the `JULIA_CPU_THREADS` environment variable.
               │          │ ──────────────── CPU ──────────────── │
Test  (Worker) │ Time (s) │ GC (s) │ GC % │ Alloc (MB) │ RSS (MB) │
mtl/size   (1) │     0.23 │   0.00 │  0.0 │      19.43 │   544.61 │

Test Summary: | Pass  Total  Time
  Overall     |   16     16  9.5s
    SUCCESS
     Testing Metal tests passed

julia> versioninfo()
Julia Version 1.12.4
Commit 01a2eadb047 (2026-01-06 16:56 UTC)
Build Info:
  Official https://julialang.org release
Platform Info:
  OS: macOS (arm64-apple-darwin24.0.0)
  CPU: 8 × Apple M1
  WORD_SIZE: 64
  LLVM: libLLVM-18.1.7 (ORCJIT, apple-m1)
  GC: Built with stock GC
Threads: 1 default, 1 interactive, 1 GC (on 4 virtual cores)

vs

julia> using Pkg

julia> Pkg.test("Metal"; test_args=`mtl/size`)
[...]
Running 1 tests in parallel. If this is too many, specify the `--jobs=N` argument to the tests, or set the `JULIA_CPU_THREADS` environment variable.
               │          │ ──────────────── CPU ──────────────── │
Test  (Worker) │ Time (s) │ GC (s) │ GC % │ Alloc (MB) │ RSS (MB) │
mtl/size   (1) │     0.18 │   0.00 │  0.0 │      14.44 │   549.08 │

Test Summary: | Pass  Total   Time
  Overall     |   16     16  10.4s
    SUCCESS
     Testing Metal tests passed

julia> versioninfo()
Julia Version 1.13.0-beta2
Commit f36fbbfd951 (2026-02-04 11:07 UTC)
Build Info:
  Official https://julialang.org release
Platform Info:
  OS: macOS (arm64-apple-darwin24.0.0)
  CPU: 8 × Apple M1
  WORD_SIZE: 64
  LLVM: libLLVM-20.1.8 (ORCJIT, apple-m1)
  GC: Built with stock GC
Threads: 1 default, 1 interactive, 1 GC (on 4 virtual cores)

[christiangnrd]

Sorry I should have explicitly mentioned that using init_worker_code exacerbates the issue instead of implying it in the issue description. Try it with JuliaGPU/Metal.jl#739

[giordano]

Julia v1.12:

Test Summary: | Pass  Total  Time
  Overall     |   16     16  9.4s
    SUCCESS
     Testing Metal tests passed

(tmp) pkg> st -m Metal
Status `/private/tmp/Manifest-v1.12.toml`
  [dde4c033] Metal v1.9.2 `https://github.com/JuliaGPU/Metal.jl.git#ptr2.2`

Julia v1.13:

Test Summary: | Pass  Total  Time
  Overall     |   16     16  9.3s
    SUCCESS
     Testing Metal tests passed

(tmp) pkg> st -m Metal
Status `/private/tmp/Project.toml`
  [dde4c033] Metal v1.9.2 `https://github.com/JuliaGPU/Metal.jl.git#ptr2.2`

[christiangnrd]

You may have to delete the compilation files for Metal.jl. It returns to 1.12 timings after a first run.

julia> using Pkg; pkg"activate --temp; add Metal#main"; @time Pkg.test("Metal"; test_args=`mtl/size`)

Julia 1.12 :

Test Summary: | Pass  Total  Time
  Overall     |   16     16  8.3s
    SUCCESS
     Testing Metal tests passed
 17.361082 seconds (5.25 M allocations: 413.367 MiB, 0.32% gc time, 3.50% compilation time)

Julia 1.13 run 1 :

Test Summary: | Pass  Total   Time
  Overall     |   16     16  30.3s
    SUCCESS
     Testing Metal tests passed
 41.244966 seconds (4.15 M allocations: 283.696 MiB, 0.33% gc time, 2.07% compilation time)

Julia 1.13 run 2 :

Test Summary: | Pass  Total  Time
  Overall     |   16     16  8.2s
    SUCCESS
     Testing Metal tests passed
 16.604003 seconds (3.15 M allocations: 224.688 MiB, 0.84% gc time)

[giordano]

I'm a bit confused: if there's a problem with loading a pkgimage for the first time after precompilation that sounds like an upstream (== julia) issue? I'm missing how ParallelTestRunner would be relevant here (besides the fact it needs to spawn processes).

[giordano]

Bump. I'm still not convinced this is much this package's fault, rather than Julia's somehow being slow at loading a package the first time the pkgimage is loaded (which might also be related to some Apple "security" features), I don't see what PTR would care about the process of loading a package with a new pkgimage for the first time. If this is indeed an upstream issue, it'd be good to report it as soon as possible, since v1.13 will likely enter release candidate stage soon, and this might affect others as well.

[christiangnrd]

Portable "MWE":

julia> using Pkg; pkg"activate --temp; add GPUArrays#master"; @time Pkg.test("GPUArrays"; test_args=`Array/vectors`)

Julia 1.12 :

Test Summary: | Pass  Total   Time
  Overall     |   10     10  20.0s
    SUCCESS
     Testing GPUArrays tests passed

Julia 1.13 run 1 :

Test Summary: | Pass  Total     Time
  Overall     |   10     10  2m48.0s
    SUCCESS
     Testing GPUArrays tests passed

Julia 1.13 run 2 :

Test Summary: | Pass  Total   Time
  Overall     |   10     10  20.7s
    SUCCESS
     Testing GPUArrays tests passed

[giordano]

I'm still not convinced this a ParallelTestRunner's issue, especially when the slowdown isn't reproducible when running the tests a second time, even in a new session. What would ParallelTestRunner care? You didn't provide evidences of a cause-effect relation involving this package.

[christiangnrd]

I'm still not convinced this a ParallelTestRunner's issue, especially when the slowdown isn't reproducible when running the tests a second time, even in a new session. What would ParallelTestRunner care? You didn't provide evidences of a cause-effect relation involving this package.

JuliaLang/julia#61126. I initially opened it here because I can only reproduce with this package and have no idea how to go about reducing this.