Skip to content

Commit 9bc0209

Browse files
christiangnrdchristiangnrd
authored
Display pre-test time (#86)
* Display pre-test time * Add compilation % to debug timing display But not on 1.10 * Rename to `debug-stats` * Print available memory before tests as part of debug stats * Use correct character for tables lines * Also change? * Merge `--debug-stats` into `--verbose`
1 parent 7372b9a commit 9bc0209

2 files changed

Lines changed: 64 additions & 15 deletions

File tree

‎src/ParallelTestRunner.jl‎

Lines changed: 50 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -86,7 +86,9 @@ struct TestRecord <: AbstractTestRecord
8686
time::Float64
8787
bytes::UInt64
8888
gctime::Float64
89+
compile_time::Float64
8990
rss::UInt64
91+
total_time::Float64
9092
end
9193

9294
function memory_usage(rec::TestRecord)
@@ -106,17 +108,20 @@ struct TestIOContext
106108
stdout::IO
107109
stderr::IO
108110
color::Bool
111+
verbose::Bool
109112
lock::ReentrantLock
110113
name_align::Int
111114
elapsed_align::Int
115+
compile_align::Int
112116
gc_align::Int
113117
percent_align::Int
114118
alloc_align::Int
115119
rss_align::Int
116120
end
117121

118-
function test_IOContext(stdout::IO, stderr::IO, lock::ReentrantLock, name_align::Int)
119-
elapsed_align = textwidth("Time (s)")
122+
function test_IOContext(stdout::IO, stderr::IO, lock::ReentrantLock, name_align::Int, verbose::Bool)
123+
elapsed_align = textwidth("time (s)")
124+
compile_align = textwidth("Compile")
120125
gc_align = textwidth("GC (s)")
121126
percent_align = textwidth("GC %")
122127
alloc_align = textwidth("Alloc (MB)")
@@ -125,19 +130,28 @@ function test_IOContext(stdout::IO, stderr::IO, lock::ReentrantLock, name_align:
125130
color = get(stdout, :color, false)
126131

127132
return TestIOContext(
128-
stdout, stderr, color, lock, name_align, elapsed_align, gc_align, percent_align,
133+
stdout, stderr, color, verbose, lock, name_align, elapsed_align, compile_align, gc_align, percent_align,
129134
alloc_align, rss_align
130135
)
131136
end
132137

133138
function print_header(ctx::TestIOContext, testgroupheader, workerheader)
134139
lock(ctx.lock)
135140
try
141+
# header top
136142
printstyled(ctx.stdout, " "^(ctx.name_align + textwidth(testgroupheader) - 3), " │ ")
137-
printstyled(ctx.stdout, " │ ──────────────── CPU ──────────────── │\n", color = :white)
143+
printstyled(ctx.stdout, " Test │", color = :white)
144+
ctx.verbose && printstyled(ctx.stdout, " Init │", color = :white)
145+
VERSION >= v"1.11" && ctx.verbose && printstyled(ctx.stdout, " Compile │", color = :white)
146+
printstyled(ctx.stdout, " ──────────────── CPU ──────────────── │\n", color = :white)
147+
148+
# header bottom
138149
printstyled(ctx.stdout, testgroupheader, color = :white)
139150
printstyled(ctx.stdout, lpad(workerheader, ctx.name_align - textwidth(testgroupheader) + 1), " │ ", color = :white)
140-
printstyled(ctx.stdout, "Time (s) │ GC (s) │ GC % │ Alloc (MB) │ RSS (MB) │\n", color = :white)
151+
printstyled(ctx.stdout, "time (s) │", color = :white)
152+
ctx.verbose && printstyled(ctx.stdout, " time (s) │", color = :white)
153+
VERSION >= v"1.11" && ctx.verbose && printstyled(ctx.stdout, " (%) │", color = :white)
154+
printstyled(ctx.stdout, " GC (s) │ GC % │ Alloc (MB) │ RSS (MB) │\n", color = :white)
141155
flush(ctx.stdout)
142156
finally
143157
unlock(ctx.lock)
@@ -163,9 +177,22 @@ function print_test_finished(record::TestRecord, wrkr, test, ctx::TestIOContext)
163177
try
164178
printstyled(ctx.stdout, test, color = :white)
165179
printstyled(ctx.stdout, lpad("($wrkr)", ctx.name_align - textwidth(test) + 1, " "), " │ ", color = :white)
180+
166181
time_str = @sprintf("%7.2f", record.time)
167182
printstyled(ctx.stdout, lpad(time_str, ctx.elapsed_align, " "), " │ ", color = :white)
168183

184+
if ctx.verbose
185+
# pre-testset time
186+
init_time_str = @sprintf("%7.2f", record.total_time - record.time)
187+
printstyled(ctx.stdout, lpad(init_time_str, ctx.elapsed_align, " "), " │ ", color = :white)
188+
189+
# compilation time
190+
if VERSION >= v"1.11"
191+
init_time_str = @sprintf("%7.2f", Float64(100*record.compile_time/record.time))
192+
printstyled(ctx.stdout, lpad(init_time_str, ctx.compile_align, " "), " │ ", color = :white)
193+
end
194+
end
195+
169196
gc_str = @sprintf("%5.2f", record.gctime)
170197
printstyled(ctx.stdout, lpad(gc_str, ctx.gc_align, " "), " │ ", color = :white)
171198
percent_str = @sprintf("%4.1f", 100 * record.gctime / record.time)
@@ -188,14 +215,20 @@ function print_test_failed(record::TestRecord, wrkr, test, ctx::TestIOContext)
188215
printstyled(ctx.stderr, test, color = :red)
189216
printstyled(
190217
ctx.stderr,
191-
lpad("($wrkr)", ctx.name_align - textwidth(test) + 1, " "), " |"
218+
lpad("($wrkr)", ctx.name_align - textwidth(test) + 1, " "), " │"
192219
, color = :red
193220
)
221+
194222
time_str = @sprintf("%7.2f", record.time)
195223
printstyled(ctx.stderr, lpad(time_str, ctx.elapsed_align + 1, " "), " │", color = :red)
196224

225+
if ctx.verbose
226+
init_time_str = @sprintf("%7.2f", record.total_time - record.time)
227+
printstyled(ctx.stdout, lpad(init_time_str, ctx.elapsed_align + 1, " "), " │ ", color = :red)
228+
end
229+
197230
failed_str = "failed at $(now())\n"
198-
# 11 -> 3 from " | " 3x and 2 for each " " on either side
231+
# 11 -> 3 from " │ " 3x and 2 for each " " on either side
199232
fail_align = (11 + ctx.gc_align + ctx.percent_align + ctx.alloc_align + ctx.rss_align - textwidth(failed_str)) ÷ 2 + textwidth(failed_str)
200233
failed_str = lpad(failed_str, fail_align, " ")
201234
printstyled(ctx.stderr, failed_str, color = :red)
@@ -214,7 +247,7 @@ function print_test_crashed(wrkr, test, ctx::TestIOContext)
214247
printstyled(ctx.stderr, test, color = :red)
215248
printstyled(
216249
ctx.stderr,
217-
lpad("($wrkr)", ctx.name_align - textwidth(test) + 1, " "), " |",
250+
lpad("($wrkr)", ctx.name_align - textwidth(test) + 1, " "), " │",
218251
" "^ctx.elapsed_align, " crashed at $(now())\n", color = :red
219252
)
220253

@@ -278,7 +311,7 @@ function Test.finish(ts::WorkerTestSet)
278311
return ts.wrapped_ts
279312
end
280313

281-
function runtest(f, name, init_code)
314+
function runtest(f, name, init_code, start_time)
282315
function inner()
283316
# generate a temporary module to execute the tests in
284317
mod = @eval(Main, module $(gensym(name)) end)
@@ -302,12 +335,14 @@ function runtest(f, name, init_code)
302335
$f
303336
end
304337
end
305-
(; testset=stats.value, stats.time, stats.bytes, stats.gctime)
338+
339+
compile_time = @static VERSION >= v"1.11" ? stats.compile_time : 0.0
340+
(; testset=stats.value, stats.time, stats.bytes, stats.gctime, compile_time)
306341
end
307342

308343
# process results
309344
rss = Sys.maxrss()
310-
record = TestRecord(data..., rss)
345+
record = TestRecord(data..., rss, time() - start_time)
311346

312347
GC.gc(true)
313348
return record
@@ -790,6 +825,7 @@ function runtests(mod::Module, args::ParsedArgs;
790825
jobs = something(args.jobs, default_njobs())
791826
jobs = clamp(jobs, 1, length(tests))
792827
println(stdout, "Running $(length(tests)) tests using $jobs parallel jobs. If this is too many concurrent jobs, specify the `--jobs=N` argument to the tests, or set the `JULIA_CPU_THREADS` environment variable.")
828+
!isnothing(args.verbose) && println(stdout, "Available memory: $(Base.format_bytes(available_memory()))")
793829
workers = fill(nothing, jobs)
794830

795831
t0 = time()
@@ -831,7 +867,7 @@ function runtests(mod::Module, args::ParsedArgs;
831867
stderr.lock = print_lock
832868
end
833869

834-
io_ctx = test_IOContext(stdout, stderr, print_lock, name_align)
870+
io_ctx = test_IOContext(stdout, stderr, print_lock, name_align, !isnothing(args.verbose))
835871
print_header(io_ctx, testgroupheader, workerheader)
836872

837873
status_lines_visible = Ref(0)
@@ -891,7 +927,7 @@ function runtests(mod::Module, args::ParsedArgs;
891927

892928
eta_sec = est_remaining / jobs
893929
eta_mins = round(Int, eta_sec / 60)
894-
line3 *= " | ETA: ~$eta_mins min"
930+
line3 *= " │ ETA: ~$eta_mins min"
895931
end
896932

897933
# only display the status bar on actual terminals
@@ -1014,7 +1050,7 @@ function runtests(mod::Module, args::ParsedArgs;
10141050
result = try
10151051
Malt.remote_eval_wait(Main, wrkr.w, :(import ParallelTestRunner))
10161052
Malt.remote_call_fetch(invokelatest, wrkr.w, runtest,
1017-
testsuite[test], test, init_code)
1053+
testsuite[test], test, init_code, test_t0)
10181054
catch ex
10191055
if isa(ex, InterruptException)
10201056
# the worker got interrupted, signal other tasks to stop

‎test/runtests.jl‎

Lines changed: 14 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -20,9 +20,22 @@ include(joinpath(@__DIR__, "utils.jl"))
2020
println("-"^80)
2121
println()
2222

23-
@test contains(str, r"basic .+ started at")
2423
@test contains(str, "SUCCESS")
2524

25+
# --verbose output
26+
@test contains(str, r"basic .+ started at")
27+
28+
@test contains(str, "time (s)")
29+
30+
@test contains(str, "Available memory:")
31+
@test contains(str, "Init")
32+
33+
# compile time as part of the struct not available before 1.11
34+
if VERSION >= v"1.11"
35+
@test contains(str, "Compile")
36+
@test contains(str, "(%)")
37+
end
38+
2639
@test isfile(ParallelTestRunner.get_history_file(ParallelTestRunner))
2740
end
2841

0 commit comments

Comments
 (0)