From 3a8d2128ca4bf92d266c051c79ebbcdcd2369db9 Mon Sep 17 00:00:00 2001 From: Christian Guinard <28689358+christiangnrd@users.noreply.github.com> Date: Sun, 25 Jan 2026 19:53:20 -0400 Subject: [PATCH 1/8] Display pre-test time --- src/ParallelTestRunner.jl | 49 +++++++++++++++++++++++++++++---------- test/runtests.jl | 11 +++++++++ 2 files changed, 48 insertions(+), 12 deletions(-) diff --git a/src/ParallelTestRunner.jl b/src/ParallelTestRunner.jl index 2e1e633..47385af 100644 --- a/src/ParallelTestRunner.jl +++ b/src/ParallelTestRunner.jl @@ -87,6 +87,7 @@ struct TestRecord <: AbstractTestRecord bytes::UInt64 gctime::Float64 rss::UInt64 + total_time::Float64 end function memory_usage(rec::TestRecord) @@ -106,6 +107,7 @@ struct TestIOContext stdout::IO stderr::IO color::Bool + debug_timing::Bool lock::ReentrantLock name_align::Int elapsed_align::Int @@ -115,7 +117,7 @@ struct TestIOContext rss_align::Int end -function test_IOContext(stdout::IO, stderr::IO, lock::ReentrantLock, name_align::Int) +function test_IOContext(stdout::IO, stderr::IO, lock::ReentrantLock, name_align::Int, debug_timing::Bool) elapsed_align = textwidth("Time (s)") gc_align = textwidth("GC (s)") percent_align = textwidth("GC %") @@ -125,7 +127,7 @@ function test_IOContext(stdout::IO, stderr::IO, lock::ReentrantLock, name_align: color = get(stdout, :color, false) return TestIOContext( - stdout, stderr, color, lock, name_align, elapsed_align, gc_align, percent_align, + stdout, stderr, color, debug_timing, lock, name_align, elapsed_align, gc_align, percent_align, alloc_align, rss_align ) end @@ -133,11 +135,18 @@ end function print_header(ctx::TestIOContext, testgroupheader, workerheader) lock(ctx.lock) try + # header top printstyled(ctx.stdout, " "^(ctx.name_align + textwidth(testgroupheader) - 3), " │ ") - printstyled(ctx.stdout, " │ ──────────────── CPU ──────────────── │\n", color = :white) + printstyled(ctx.stdout, " |", color = :white) + ctx.debug_timing && printstyled(ctx.stdout, " Init │", color = :white) + printstyled(ctx.stdout, " ──────────────── CPU ──────────────── │\n", color = :white) + + # header bottom printstyled(ctx.stdout, testgroupheader, color = :white) printstyled(ctx.stdout, lpad(workerheader, ctx.name_align - textwidth(testgroupheader) + 1), " │ ", color = :white) - printstyled(ctx.stdout, "Time (s) │ GC (s) │ GC % │ Alloc (MB) │ RSS (MB) │\n", color = :white) + printstyled(ctx.stdout, "Time (s) │", color = :white) + ctx.debug_timing && printstyled(ctx.stdout, " time (s) │", color = :white) + printstyled(ctx.stdout, " GC (s) │ GC % │ Alloc (MB) │ RSS (MB) │\n", color = :white) flush(ctx.stdout) finally unlock(ctx.lock) @@ -163,9 +172,15 @@ function print_test_finished(record::TestRecord, wrkr, test, ctx::TestIOContext) try printstyled(ctx.stdout, test, color = :white) printstyled(ctx.stdout, lpad("($wrkr)", ctx.name_align - textwidth(test) + 1, " "), " │ ", color = :white) - time_str = @sprintf("%7.2f", record.time) + time = record.time + time_str = @sprintf("%7.2f", time) printstyled(ctx.stdout, lpad(time_str, ctx.elapsed_align, " "), " │ ", color = :white) + if ctx.debug_timing + init_time_str = @sprintf("%7.2f", record.total_time - time) + printstyled(ctx.stdout, lpad(init_time_str, ctx.elapsed_align, " "), " │ ", color = :white) + end + gc_str = @sprintf("%5.2f", record.gctime) printstyled(ctx.stdout, lpad(gc_str, ctx.gc_align, " "), " │ ", color = :white) percent_str = @sprintf("%4.1f", 100 * record.gctime / record.time) @@ -191,9 +206,15 @@ function print_test_failed(record::TestRecord, wrkr, test, ctx::TestIOContext) lpad("($wrkr)", ctx.name_align - textwidth(test) + 1, " "), " |" , color = :red ) - time_str = @sprintf("%7.2f", record.time) + time = record.time + time_str = @sprintf("%7.2f", time) printstyled(ctx.stderr, lpad(time_str, ctx.elapsed_align + 1, " "), " │", color = :red) + if ctx.debug_stats + init_time_str = @sprintf("%7.2f", record.total_time - time) + printstyled(ctx.stdout, lpad(init_time_str, ctx.elapsed_align + 1, " "), " │ ", color = :red) + end + failed_str = "failed at $(now())\n" # 11 -> 3 from " | " 3x and 2 for each " " on either side fail_align = (11 + ctx.gc_align + ctx.percent_align + ctx.alloc_align + ctx.rss_align - textwidth(failed_str)) ÷ 2 + textwidth(failed_str) @@ -278,7 +299,7 @@ function Test.finish(ts::WorkerTestSet) return ts.wrapped_ts end -function runtest(f, name, init_code) +function runtest(f, name, init_code, start_time) function inner() # generate a temporary module to execute the tests in mod = @eval(Main, module $(gensym(name)) end) @@ -307,7 +328,7 @@ function runtest(f, name, init_code) # process results rss = Sys.maxrss() - record = TestRecord(data..., rss) + record = TestRecord(data..., rss, time() - start_time) GC.gc(true) return record @@ -542,6 +563,7 @@ Fields are * `jobs::Union{Some{Int}, Nothing}`: the number of jobs * `verbose::Union{Some{Nothing}, Nothing}`: whether verbose printing was enabled +* `debug_timing::Union{Some{Nothing}, Nothing}`: whether debug timing printing was enabled * `quickfail::Union{Some{Nothing}, Nothing}`: whether quick fail was enabled * `list::Union{Some{Nothing}, Nothing}`: whether tests should be listed * `custom::Dict{String,Any}`: a dictionary of custom arguments @@ -550,6 +572,7 @@ Fields are struct ParsedArgs jobs::Union{Some{Int}, Nothing} verbose::Union{Some{Nothing}, Nothing} + debug_timing::Union{Some{Nothing}, Nothing} quickfail::Union{Some{Nothing}, Nothing} list::Union{Some{Nothing}, Nothing} @@ -607,7 +630,8 @@ function parse_args(args; custom::Array{String} = String[]) --list List all available tests. --verbose Print more information during testing. --quickfail Fail the entire run as soon as a single test errored. - --jobs=N Launch `N` processes to perform tests.""" + --jobs=N Launch `N` processes to perform tests. + --debug-timing Print testset initialization timings.""" if !isempty(custom) usage *= "\n\nCustom arguments:" @@ -622,6 +646,7 @@ function parse_args(args; custom::Array{String} = String[]) jobs = extract_flag!(args, "--jobs"; typ = Int) verbose = extract_flag!(args, "--verbose") + debug_timing = extract_flag!(args, "--debug-timing") quickfail = extract_flag!(args, "--quickfail") list = extract_flag!(args, "--list") @@ -636,7 +661,7 @@ function parse_args(args; custom::Array{String} = String[]) error("Unknown test options `$(join(optlike_args, " "))` (try `--help` for usage instructions)") end - return ParsedArgs(jobs, verbose, quickfail, list, custom_args, args) + return ParsedArgs(jobs, verbose, debug_timing, quickfail, list, custom_args, args) end """ @@ -836,7 +861,7 @@ function runtests(mod::Module, args::ParsedArgs; stderr.lock = print_lock end - io_ctx = test_IOContext(stdout, stderr, print_lock, name_align) + io_ctx = test_IOContext(stdout, stderr, print_lock, name_align, !isnothing(args.debug_timing)) print_header(io_ctx, testgroupheader, workerheader) status_lines_visible = Ref(0) @@ -1020,7 +1045,7 @@ function runtests(mod::Module, args::ParsedArgs; result = try Malt.remote_eval_wait(Main, wrkr.w, :(import ParallelTestRunner)) Malt.remote_call_fetch(invokelatest, wrkr.w, runtest, - testsuite[test], test, init_code) + testsuite[test], test, init_code, test_t0) catch ex if isa(ex, InterruptException) # the worker got interrupted, signal other tasks to stop diff --git a/test/runtests.jl b/test/runtests.jl index 4f09e17..564f3b3 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -24,6 +24,17 @@ cd(@__DIR__) @test isfile(ParallelTestRunner.get_history_file(ParallelTestRunner)) end +@testset "debug timing" begin + io = IOBuffer() + io_color = IOContext(io, :color => true) + runtests(ParallelTestRunner, ["--debug-timing"]; stdout=io_color, stderr=io_color) + str = String(take!(io)) + + @test contains(str, "Init") # debug timing + @test contains(str, "time (s)") # debug timing + @test contains(str, "Time (s)") # normal timing +end + @testset "subdir use" begin d = @__DIR__ testsuite = find_tests(d) From 03090423cf372e73c111421468c5f0558cf08b9d Mon Sep 17 00:00:00 2001 From: Christian Guinard <28689358+christiangnrd@users.noreply.github.com> Date: Tue, 10 Feb 2026 15:59:56 -0400 Subject: [PATCH 2/8] Add compilation % to debug timing display --- src/ParallelTestRunner.jl | 22 +++++++++++++++------- test/runtests.jl | 6 ++++-- 2 files changed, 19 insertions(+), 9 deletions(-) diff --git a/src/ParallelTestRunner.jl b/src/ParallelTestRunner.jl index 47385af..34a9e78 100644 --- a/src/ParallelTestRunner.jl +++ b/src/ParallelTestRunner.jl @@ -86,6 +86,7 @@ struct TestRecord <: AbstractTestRecord time::Float64 bytes::UInt64 gctime::Float64 + compile_time::Float64 rss::UInt64 total_time::Float64 end @@ -111,6 +112,7 @@ struct TestIOContext lock::ReentrantLock name_align::Int elapsed_align::Int + compile_align::Int gc_align::Int percent_align::Int alloc_align::Int @@ -118,7 +120,8 @@ struct TestIOContext end function test_IOContext(stdout::IO, stderr::IO, lock::ReentrantLock, name_align::Int, debug_timing::Bool) - elapsed_align = textwidth("Time (s)") + elapsed_align = textwidth("time (s)") + compile_align = textwidth("Compile") gc_align = textwidth("GC (s)") percent_align = textwidth("GC %") alloc_align = textwidth("Alloc (MB)") @@ -127,7 +130,7 @@ function test_IOContext(stdout::IO, stderr::IO, lock::ReentrantLock, name_align: color = get(stdout, :color, false) return TestIOContext( - stdout, stderr, color, debug_timing, lock, name_align, elapsed_align, gc_align, percent_align, + stdout, stderr, color, debug_timing, lock, name_align, elapsed_align, compile_align, gc_align, percent_align, alloc_align, rss_align ) end @@ -137,15 +140,15 @@ function print_header(ctx::TestIOContext, testgroupheader, workerheader) try # header top printstyled(ctx.stdout, " "^(ctx.name_align + textwidth(testgroupheader) - 3), " │ ") - printstyled(ctx.stdout, " |", color = :white) - ctx.debug_timing && printstyled(ctx.stdout, " Init │", color = :white) + printstyled(ctx.stdout, " Test |", color = :white) + ctx.debug_timing && printstyled(ctx.stdout, " Init │ Compile │", color = :white) printstyled(ctx.stdout, " ──────────────── CPU ──────────────── │\n", color = :white) # header bottom printstyled(ctx.stdout, testgroupheader, color = :white) printstyled(ctx.stdout, lpad(workerheader, ctx.name_align - textwidth(testgroupheader) + 1), " │ ", color = :white) - printstyled(ctx.stdout, "Time (s) │", color = :white) - ctx.debug_timing && printstyled(ctx.stdout, " time (s) │", color = :white) + printstyled(ctx.stdout, "time (s) │", color = :white) + ctx.debug_timing && printstyled(ctx.stdout, " time (s) │ (%) │", color = :white) printstyled(ctx.stdout, " GC (s) │ GC % │ Alloc (MB) │ RSS (MB) │\n", color = :white) flush(ctx.stdout) finally @@ -177,8 +180,13 @@ function print_test_finished(record::TestRecord, wrkr, test, ctx::TestIOContext) printstyled(ctx.stdout, lpad(time_str, ctx.elapsed_align, " "), " │ ", color = :white) if ctx.debug_timing + # pre-testset time init_time_str = @sprintf("%7.2f", record.total_time - time) printstyled(ctx.stdout, lpad(init_time_str, ctx.elapsed_align, " "), " │ ", color = :white) + + # compilation time + init_time_str = @sprintf("%7.2f", Float64(100*record.compile_time/time)) + printstyled(ctx.stdout, lpad(init_time_str, ctx.compile_align, " "), " │ ", color = :white) end gc_str = @sprintf("%5.2f", record.gctime) @@ -323,7 +331,7 @@ function runtest(f, name, init_code, start_time) $f end end - (; testset=stats.value, stats.time, stats.bytes, stats.gctime) + (; testset=stats.value, stats.time, stats.bytes, stats.gctime, stats.compile_time) end # process results diff --git a/test/runtests.jl b/test/runtests.jl index 564f3b3..09aaaad 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -30,9 +30,11 @@ end runtests(ParallelTestRunner, ["--debug-timing"]; stdout=io_color, stderr=io_color) str = String(take!(io)) + @test contains(str, "time (s)") # timing + @test contains(str, "Init") # debug timing - @test contains(str, "time (s)") # debug timing - @test contains(str, "Time (s)") # normal timing + @test contains(str, "Compile") # debug timing + @test contains(str, "(%)") # debug timing end @testset "subdir use" begin From f662fe672c983f9f5dfb52729b55df895efaabae Mon Sep 17 00:00:00 2001 From: Christian Guinard <28689358+christiangnrd@users.noreply.github.com> Date: Tue, 10 Feb 2026 21:15:52 -0400 Subject: [PATCH 3/8] Don't include compile time on 1.10 --- src/ParallelTestRunner.jl | 16 +++++++++++----- test/runtests.jl | 6 ++++-- 2 files changed, 15 insertions(+), 7 deletions(-) diff --git a/src/ParallelTestRunner.jl b/src/ParallelTestRunner.jl index 34a9e78..6c8ee95 100644 --- a/src/ParallelTestRunner.jl +++ b/src/ParallelTestRunner.jl @@ -141,14 +141,16 @@ function print_header(ctx::TestIOContext, testgroupheader, workerheader) # header top printstyled(ctx.stdout, " "^(ctx.name_align + textwidth(testgroupheader) - 3), " │ ") printstyled(ctx.stdout, " Test |", color = :white) - ctx.debug_timing && printstyled(ctx.stdout, " Init │ Compile │", color = :white) + ctx.debug_timing && printstyled(ctx.stdout, " Init │", color = :white) + VERSION >= v"1.11" && ctx.debug_timing && printstyled(ctx.stdout, " Compile │", color = :white) printstyled(ctx.stdout, " ──────────────── CPU ──────────────── │\n", color = :white) # header bottom printstyled(ctx.stdout, testgroupheader, color = :white) printstyled(ctx.stdout, lpad(workerheader, ctx.name_align - textwidth(testgroupheader) + 1), " │ ", color = :white) printstyled(ctx.stdout, "time (s) │", color = :white) - ctx.debug_timing && printstyled(ctx.stdout, " time (s) │ (%) │", color = :white) + ctx.debug_timing && printstyled(ctx.stdout, " time (s) │", color = :white) + VERSION >= v"1.11" && ctx.debug_timing && printstyled(ctx.stdout, " (%) │", color = :white) printstyled(ctx.stdout, " GC (s) │ GC % │ Alloc (MB) │ RSS (MB) │\n", color = :white) flush(ctx.stdout) finally @@ -185,8 +187,10 @@ function print_test_finished(record::TestRecord, wrkr, test, ctx::TestIOContext) printstyled(ctx.stdout, lpad(init_time_str, ctx.elapsed_align, " "), " │ ", color = :white) # compilation time - init_time_str = @sprintf("%7.2f", Float64(100*record.compile_time/time)) - printstyled(ctx.stdout, lpad(init_time_str, ctx.compile_align, " "), " │ ", color = :white) + if VERSION >= v"1.11" + init_time_str = @sprintf("%7.2f", Float64(100*record.compile_time/time)) + printstyled(ctx.stdout, lpad(init_time_str, ctx.compile_align, " "), " │ ", color = :white) + end end gc_str = @sprintf("%5.2f", record.gctime) @@ -331,7 +335,9 @@ function runtest(f, name, init_code, start_time) $f end end - (; testset=stats.value, stats.time, stats.bytes, stats.gctime, stats.compile_time) + + compile_time = @static VERSION >= v"1.11" ? stats.compile_time : 0.0 + (; testset=stats.value, stats.time, stats.bytes, stats.gctime, compile_time) end # process results diff --git a/test/runtests.jl b/test/runtests.jl index 09aaaad..9b747bd 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -33,8 +33,10 @@ end @test contains(str, "time (s)") # timing @test contains(str, "Init") # debug timing - @test contains(str, "Compile") # debug timing - @test contains(str, "(%)") # debug timing + if VERSION >= v"1.11" # compile time as part of the struct not available before 1.11 + @test contains(str, "Compile") # debug timing + @test contains(str, "(%)") # debug timing + end end @testset "subdir use" begin From 40f56ed5518b5662d9870276296aa4ae98eafce0 Mon Sep 17 00:00:00 2001 From: Christian Guinard <28689358+christiangnrd@users.noreply.github.com> Date: Thu, 12 Feb 2026 10:42:13 -0400 Subject: [PATCH 4/8] Rename to `debug-stats` --- src/ParallelTestRunner.jl | 28 ++++++++++++++-------------- test/runtests.jl | 2 +- 2 files changed, 15 insertions(+), 15 deletions(-) diff --git a/src/ParallelTestRunner.jl b/src/ParallelTestRunner.jl index 6c8ee95..6074775 100644 --- a/src/ParallelTestRunner.jl +++ b/src/ParallelTestRunner.jl @@ -108,7 +108,7 @@ struct TestIOContext stdout::IO stderr::IO color::Bool - debug_timing::Bool + debug_stats::Bool lock::ReentrantLock name_align::Int elapsed_align::Int @@ -119,7 +119,7 @@ struct TestIOContext rss_align::Int end -function test_IOContext(stdout::IO, stderr::IO, lock::ReentrantLock, name_align::Int, debug_timing::Bool) +function test_IOContext(stdout::IO, stderr::IO, lock::ReentrantLock, name_align::Int, debug_stats::Bool) elapsed_align = textwidth("time (s)") compile_align = textwidth("Compile") gc_align = textwidth("GC (s)") @@ -130,7 +130,7 @@ function test_IOContext(stdout::IO, stderr::IO, lock::ReentrantLock, name_align: color = get(stdout, :color, false) return TestIOContext( - stdout, stderr, color, debug_timing, lock, name_align, elapsed_align, compile_align, gc_align, percent_align, + stdout, stderr, color, debug_stats, lock, name_align, elapsed_align, compile_align, gc_align, percent_align, alloc_align, rss_align ) end @@ -141,16 +141,16 @@ function print_header(ctx::TestIOContext, testgroupheader, workerheader) # header top printstyled(ctx.stdout, " "^(ctx.name_align + textwidth(testgroupheader) - 3), " │ ") printstyled(ctx.stdout, " Test |", color = :white) - ctx.debug_timing && printstyled(ctx.stdout, " Init │", color = :white) - VERSION >= v"1.11" && ctx.debug_timing && printstyled(ctx.stdout, " Compile │", color = :white) + ctx.debug_stats && printstyled(ctx.stdout, " Init │", color = :white) + VERSION >= v"1.11" && ctx.debug_stats && printstyled(ctx.stdout, " Compile │", color = :white) printstyled(ctx.stdout, " ──────────────── CPU ──────────────── │\n", color = :white) # header bottom printstyled(ctx.stdout, testgroupheader, color = :white) printstyled(ctx.stdout, lpad(workerheader, ctx.name_align - textwidth(testgroupheader) + 1), " │ ", color = :white) printstyled(ctx.stdout, "time (s) │", color = :white) - ctx.debug_timing && printstyled(ctx.stdout, " time (s) │", color = :white) - VERSION >= v"1.11" && ctx.debug_timing && printstyled(ctx.stdout, " (%) │", color = :white) + ctx.debug_stats && printstyled(ctx.stdout, " time (s) │", color = :white) + VERSION >= v"1.11" && ctx.debug_stats && printstyled(ctx.stdout, " (%) │", color = :white) printstyled(ctx.stdout, " GC (s) │ GC % │ Alloc (MB) │ RSS (MB) │\n", color = :white) flush(ctx.stdout) finally @@ -181,7 +181,7 @@ function print_test_finished(record::TestRecord, wrkr, test, ctx::TestIOContext) time_str = @sprintf("%7.2f", time) printstyled(ctx.stdout, lpad(time_str, ctx.elapsed_align, " "), " │ ", color = :white) - if ctx.debug_timing + if ctx.debug_stats # pre-testset time init_time_str = @sprintf("%7.2f", record.total_time - time) printstyled(ctx.stdout, lpad(init_time_str, ctx.elapsed_align, " "), " │ ", color = :white) @@ -577,7 +577,7 @@ Fields are * `jobs::Union{Some{Int}, Nothing}`: the number of jobs * `verbose::Union{Some{Nothing}, Nothing}`: whether verbose printing was enabled -* `debug_timing::Union{Some{Nothing}, Nothing}`: whether debug timing printing was enabled +* `debug_stats::Union{Some{Nothing}, Nothing}`: whether debug stats printing was enabled * `quickfail::Union{Some{Nothing}, Nothing}`: whether quick fail was enabled * `list::Union{Some{Nothing}, Nothing}`: whether tests should be listed * `custom::Dict{String,Any}`: a dictionary of custom arguments @@ -586,7 +586,7 @@ Fields are struct ParsedArgs jobs::Union{Some{Int}, Nothing} verbose::Union{Some{Nothing}, Nothing} - debug_timing::Union{Some{Nothing}, Nothing} + debug_stats::Union{Some{Nothing}, Nothing} quickfail::Union{Some{Nothing}, Nothing} list::Union{Some{Nothing}, Nothing} @@ -645,7 +645,7 @@ function parse_args(args; custom::Array{String} = String[]) --verbose Print more information during testing. --quickfail Fail the entire run as soon as a single test errored. --jobs=N Launch `N` processes to perform tests. - --debug-timing Print testset initialization timings.""" + --debug-stats Print information that could be helpful for debugging testset slowdowns.""" if !isempty(custom) usage *= "\n\nCustom arguments:" @@ -660,7 +660,7 @@ function parse_args(args; custom::Array{String} = String[]) jobs = extract_flag!(args, "--jobs"; typ = Int) verbose = extract_flag!(args, "--verbose") - debug_timing = extract_flag!(args, "--debug-timing") + debug_stats = extract_flag!(args, "--debug-stats") quickfail = extract_flag!(args, "--quickfail") list = extract_flag!(args, "--list") @@ -675,7 +675,7 @@ function parse_args(args; custom::Array{String} = String[]) error("Unknown test options `$(join(optlike_args, " "))` (try `--help` for usage instructions)") end - return ParsedArgs(jobs, verbose, debug_timing, quickfail, list, custom_args, args) + return ParsedArgs(jobs, verbose, debug_stats, quickfail, list, custom_args, args) end """ @@ -875,7 +875,7 @@ function runtests(mod::Module, args::ParsedArgs; stderr.lock = print_lock end - io_ctx = test_IOContext(stdout, stderr, print_lock, name_align, !isnothing(args.debug_timing)) + io_ctx = test_IOContext(stdout, stderr, print_lock, name_align, !isnothing(args.debug_stats)) print_header(io_ctx, testgroupheader, workerheader) status_lines_visible = Ref(0) diff --git a/test/runtests.jl b/test/runtests.jl index 9b747bd..d00e9b5 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -27,7 +27,7 @@ end @testset "debug timing" begin io = IOBuffer() io_color = IOContext(io, :color => true) - runtests(ParallelTestRunner, ["--debug-timing"]; stdout=io_color, stderr=io_color) + runtests(ParallelTestRunner, ["--debug-stats"]; stdout=io_color, stderr=io_color) str = String(take!(io)) @test contains(str, "time (s)") # timing From dd6086da6c39a372de9f1092e7b34913d96d7d7d Mon Sep 17 00:00:00 2001 From: Christian Guinard <28689358+christiangnrd@users.noreply.github.com> Date: Thu, 12 Feb 2026 10:50:41 -0400 Subject: [PATCH 5/8] [NFC] Remove pointless variable `jobs` is already clamped to be no higher than the number of tests so `min(job, length(tests))` is redundant --- src/ParallelTestRunner.jl | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/src/ParallelTestRunner.jl b/src/ParallelTestRunner.jl index 6074775..ac9eeab 100644 --- a/src/ParallelTestRunner.jl +++ b/src/ParallelTestRunner.jl @@ -835,8 +835,7 @@ function runtests(mod::Module, args::ParsedArgs; jobs = something(args.jobs, default_njobs()) jobs = clamp(jobs, 1, length(tests)) println(stdout, "Running $jobs tests in parallel. If this is too many, specify the `--jobs=N` argument to the tests, or set the `JULIA_CPU_THREADS` environment variable.") - nworkers = min(jobs, length(tests)) - workers = fill(nothing, nworkers) + workers = fill(nothing, jobs) t0 = time() results = [] From a1f1674f9b696fa2da1763441c7f8761db540cdb Mon Sep 17 00:00:00 2001 From: Christian Guinard <28689358+christiangnrd@users.noreply.github.com> Date: Thu, 12 Feb 2026 11:05:58 -0400 Subject: [PATCH 6/8] Print available memory before tests as part of debug stats --- src/ParallelTestRunner.jl | 1 + test/runtests.jl | 13 ++++++++----- 2 files changed, 9 insertions(+), 5 deletions(-) diff --git a/src/ParallelTestRunner.jl b/src/ParallelTestRunner.jl index ac9eeab..0735542 100644 --- a/src/ParallelTestRunner.jl +++ b/src/ParallelTestRunner.jl @@ -835,6 +835,7 @@ function runtests(mod::Module, args::ParsedArgs; jobs = something(args.jobs, default_njobs()) jobs = clamp(jobs, 1, length(tests)) println(stdout, "Running $jobs tests in parallel. If this is too many, specify the `--jobs=N` argument to the tests, or set the `JULIA_CPU_THREADS` environment variable.") + !isnothing(args.debug_stats) && println(stdout, "Available memory: $(Base.format_bytes(available_memory()))") workers = fill(nothing, jobs) t0 = time() diff --git a/test/runtests.jl b/test/runtests.jl index d00e9b5..6d21ad1 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -30,12 +30,15 @@ end runtests(ParallelTestRunner, ["--debug-stats"]; stdout=io_color, stderr=io_color) str = String(take!(io)) - @test contains(str, "time (s)") # timing + @test contains(str, "time (s)") - @test contains(str, "Init") # debug timing - if VERSION >= v"1.11" # compile time as part of the struct not available before 1.11 - @test contains(str, "Compile") # debug timing - @test contains(str, "(%)") # debug timing + @test contains(str, "Available memory:") + @test contains(str, "Init") + + # compile time as part of the struct not available before 1.11 + if VERSION >= v"1.11" + @test contains(str, "Compile") + @test contains(str, "(%)") end end From 1d188b15adcab0bf6ac22f82b3e85f5eb9fc6f49 Mon Sep 17 00:00:00 2001 From: Christian Guinard <28689358+christiangnrd@users.noreply.github.com> Date: Thu, 12 Feb 2026 14:37:32 -0400 Subject: [PATCH 7/8] Use correct character for tables lines --- src/ParallelTestRunner.jl | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/ParallelTestRunner.jl b/src/ParallelTestRunner.jl index 0735542..13873f1 100644 --- a/src/ParallelTestRunner.jl +++ b/src/ParallelTestRunner.jl @@ -140,7 +140,7 @@ function print_header(ctx::TestIOContext, testgroupheader, workerheader) try # header top printstyled(ctx.stdout, " "^(ctx.name_align + textwidth(testgroupheader) - 3), " │ ") - printstyled(ctx.stdout, " Test |", color = :white) + printstyled(ctx.stdout, " Test │", color = :white) ctx.debug_stats && printstyled(ctx.stdout, " Init │", color = :white) VERSION >= v"1.11" && ctx.debug_stats && printstyled(ctx.stdout, " Compile │", color = :white) printstyled(ctx.stdout, " ──────────────── CPU ──────────────── │\n", color = :white) @@ -215,7 +215,7 @@ function print_test_failed(record::TestRecord, wrkr, test, ctx::TestIOContext) printstyled(ctx.stderr, test, color = :red) printstyled( ctx.stderr, - lpad("($wrkr)", ctx.name_align - textwidth(test) + 1, " "), " |" + lpad("($wrkr)", ctx.name_align - textwidth(test) + 1, " "), " │" , color = :red ) time = record.time @@ -228,7 +228,7 @@ function print_test_failed(record::TestRecord, wrkr, test, ctx::TestIOContext) end failed_str = "failed at $(now())\n" - # 11 -> 3 from " | " 3x and 2 for each " " on either side + # 11 -> 3 from " │ " 3x and 2 for each " " on either side fail_align = (11 + ctx.gc_align + ctx.percent_align + ctx.alloc_align + ctx.rss_align - textwidth(failed_str)) ÷ 2 + textwidth(failed_str) failed_str = lpad(failed_str, fail_align, " ") printstyled(ctx.stderr, failed_str, color = :red) @@ -247,7 +247,7 @@ function print_test_crashed(wrkr, test, ctx::TestIOContext) printstyled(ctx.stderr, test, color = :red) printstyled( ctx.stderr, - lpad("($wrkr)", ctx.name_align - textwidth(test) + 1, " "), " |", + lpad("($wrkr)", ctx.name_align - textwidth(test) + 1, " "), " │", " "^ctx.elapsed_align, " crashed at $(now())\n", color = :red ) From 4c2b7611f40d1da542595869c25147b792c20824 Mon Sep 17 00:00:00 2001 From: Christian Guinard <28689358+christiangnrd@users.noreply.github.com> Date: Thu, 12 Feb 2026 14:37:45 -0400 Subject: [PATCH 8/8] Also change? --- src/ParallelTestRunner.jl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/ParallelTestRunner.jl b/src/ParallelTestRunner.jl index 13873f1..c897bad 100644 --- a/src/ParallelTestRunner.jl +++ b/src/ParallelTestRunner.jl @@ -935,7 +935,7 @@ function runtests(mod::Module, args::ParsedArgs; eta_sec = est_remaining / jobs eta_mins = round(Int, eta_sec / 60) - line3 *= " | ETA: ~$eta_mins min" + line3 *= " │ ETA: ~$eta_mins min" end # only display the status bar on actual terminals