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 3 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
3 commits
Select commit Hold shift + click to select a range
b740688
Display pre-test time
christiangnrd Jan 25, 2026
505d8c9
Add compilation % to debug timing display
christiangnrd Feb 10, 2026
69ebba0
Don't include compile time on 1.10
christiangnrd Feb 11, 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
64 changes: 50 additions & 14 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_timing::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_timing::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_timing, 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_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) │ 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)
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
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_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
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 @@ -191,8 +218,11 @@ 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)
init_time_str = @sprintf("%7.2f", record.total_time - time)
printstyled(ctx.stdout, lpad(init_time_str, ctx.elapsed_align, " "), " │ ", color = :red)

failed_str = "failed at $(now())\n"
# 11 -> 3 from " | " 3x and 2 for each " " on either side
Expand Down Expand Up @@ -278,7 +308,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 +332,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 +574,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
Expand All @@ -550,6 +583,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}

Expand Down Expand Up @@ -607,7 +641,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:"
Expand All @@ -622,6 +657,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")

Expand All @@ -636,7 +672,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

"""
Expand Down Expand Up @@ -836,7 +872,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)
Expand Down Expand Up @@ -1020,7 +1056,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
15 changes: 15 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,21 @@ 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, "time (s)") # timing

@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
end
end

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