diff --git a/src/ParallelTestRunner.jl b/src/ParallelTestRunner.jl index 2e1e633..c897bad 100644 --- a/src/ParallelTestRunner.jl +++ b/src/ParallelTestRunner.jl @@ -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) @@ -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)") @@ -125,7 +130,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_stats, lock, name_align, elapsed_align, compile_align, gc_align, percent_align, alloc_align, rss_align ) end @@ -133,11 +138,20 @@ 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) @@ -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) @@ -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) @@ -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 ) @@ -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) @@ -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 @@ -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 @@ -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} @@ -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:" @@ -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") @@ -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 """ @@ -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 = [] @@ -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) @@ -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 @@ -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 diff --git a/test/runtests.jl b/test/runtests.jl index 4f09e17..6d21ad1 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -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)