Skip to content

Display pre-test time #86

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Draft
christiangnrd wants to merge 8 commits into
base: main
Choose a base branch
from
Draft

Display pre-test time #86

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
8 commits
Select commit Hold shift + click to select a range
3a8d212
Display pre-test time
christiangnrd Jan 25, 2026
0309042
Add compilation % to debug timing display
christiangnrd Feb 10, 2026
f662fe6
Don't include compile time on 1.10
christiangnrd Feb 11, 2026
40f56ed
Rename to `debug-stats`
christiangnrd Feb 12, 2026
dd6086d
[NFC] Remove pointless variable
christiangnrd Feb 12, 2026
a1f1674
Print available memory before tests as part of debug stats
christiangnrd Feb 12, 2026
1d188b1
Use correct character for tables lines
christiangnrd Feb 12, 2026
4c2b761
Also change?
christiangnrd Feb 12, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
79 changes: 59 additions & 20 deletions src/ParallelTestRunner.jl
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -86,7 +86,9 @@ struct TestRecord <: AbstractTestRecord
time::Float64
bytes::UInt64
gctime::Float64
compile_time::Float64
rss::UInt64
total_time::Float64
end

function memory_usage(rec::TestRecord)
Expand All @@ -106,17 +108,20 @@ struct TestIOContext
stdout::IO
stderr::IO
color::Bool
debug_stats::Bool
lock::ReentrantLock
name_align::Int
elapsed_align::Int
compile_align::Int
gc_align::Int
percent_align::Int
alloc_align::Int
rss_align::Int
end

function test_IOContext(stdout::IO, stderr::IO, lock::ReentrantLock, name_align::Int)
elapsed_align = textwidth("Time (s)")
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)")
percent_align = textwidth("GC %")
alloc_align = textwidth("Alloc (MB)")
Expand All @@ -125,19 +130,28 @@ 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_stats, lock, name_align, elapsed_align, compile_align, gc_align, percent_align,
alloc_align, rss_align
)
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, " 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)

# 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_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
unlock(ctx.lock)
Expand All @@ -163,9 +177,22 @@ 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_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)

# compilation time
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)
printstyled(ctx.stdout, lpad(gc_str, ctx.gc_align, " "), " │ ", color = :white)
percent_str = @sprintf("%4.1f", 100 * record.gctime / record.time)
Expand All @@ -188,14 +215,20 @@ 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_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
# 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)
Expand All @@ -214,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
)

Expand Down Expand Up @@ -278,7 +311,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)
Expand All @@ -302,12 +335,14 @@ function runtest(f, name, init_code)
$f
end
end
(; testset=stats.value, stats.time, stats.bytes, stats.gctime)

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
rss = Sys.maxrss()
record = TestRecord(data..., rss)
record = TestRecord(data..., rss, time() - start_time)

GC.gc(true)
return record
Expand Down Expand Up @@ -542,6 +577,7 @@ Fields are

* `jobs::Union{Some{Int}, Nothing}`: the number of jobs
* `verbose::Union{Some{Nothing}, Nothing}`: whether verbose 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
Expand All @@ -550,6 +586,7 @@ Fields are
struct ParsedArgs
jobs::Union{Some{Int}, Nothing}
verbose::Union{Some{Nothing}, Nothing}
debug_stats::Union{Some{Nothing}, Nothing}
quickfail::Union{Some{Nothing}, Nothing}
list::Union{Some{Nothing}, Nothing}

Expand Down Expand Up @@ -607,7 +644,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-stats Print information that could be helpful for debugging testset slowdowns."""

if !isempty(custom)
usage *= "\n\nCustom arguments:"
Expand All @@ -622,6 +660,7 @@ function parse_args(args; custom::Array{String} = String[])

jobs = extract_flag!(args, "--jobs"; typ = Int)
verbose = extract_flag!(args, "--verbose")
debug_stats = extract_flag!(args, "--debug-stats")
quickfail = extract_flag!(args, "--quickfail")
list = extract_flag!(args, "--list")

Expand All @@ -636,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, quickfail, list, custom_args, args)
return ParsedArgs(jobs, verbose, debug_stats, quickfail, list, custom_args, args)
end

"""
Expand Down Expand Up @@ -796,8 +835,8 @@ 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)
!isnothing(args.debug_stats) && println(stdout, "Available memory: $(Base.format_bytes(available_memory()))")
workers = fill(nothing, jobs)

t0 = time()
results = []
Expand Down Expand Up @@ -836,7 +875,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_stats))
print_header(io_ctx, testgroupheader, workerheader)

status_lines_visible = Ref(0)
Expand Down Expand Up @@ -896,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
Expand Down Expand Up @@ -1020,7 +1059,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
Expand Down
18 changes: 18 additions & 0 deletions test/runtests.jl
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,24 @@ 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-stats"]; stdout=io_color, stderr=io_color)
str = String(take!(io))

@test contains(str, "time (s)")

@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

@testset "subdir use" begin
d = @__DIR__
testsuite = find_tests(d)
Expand Down