Skip to content

Commit 4d6aee6

Browse files
maleadtmaleadt
committed
Improve output printing.
1 parent f4b6f2f commit 4d6aee6

File tree

1 file changed

+61
-49
lines changed

1 file changed

+61
-49
lines changed

‎src/ParallelTestRunner.jl‎

Lines changed: 61 additions & 49 deletions
Original file line numberDiff line numberDiff line change
@@ -111,11 +111,11 @@ end
111111
function print_header(::Type{TestRecord}, ctx::TestIOContext, testgroupheader, workerheader)
112112
lock(ctx.lock)
113113
try
114-
printstyled(ctx.stdout, " "^(ctx.name_align + textwidth(testgroupheader) - 3), " | ")
115-
printstyled(ctx.stdout, " | ---------------- CPU ---------------- |\n", color = :white)
114+
printstyled(ctx.stdout, " "^(ctx.name_align + textwidth(testgroupheader) - 3), " │ ")
115+
printstyled(ctx.stdout, " │ ──────────────── CPU ──────────────── │\n", color = :white)
116116
printstyled(ctx.stdout, testgroupheader, color = :white)
117-
printstyled(ctx.stdout, lpad(workerheader, ctx.name_align - textwidth(testgroupheader) + 1), " | ", color = :white)
118-
printstyled(ctx.stdout, "Time (s) | GC (s) | GC % | Alloc (MB) | RSS (MB) |\n", color = :white)
117+
printstyled(ctx.stdout, lpad(workerheader, ctx.name_align - textwidth(testgroupheader) + 1), " │ ", color = :white)
118+
printstyled(ctx.stdout, "Time (s) │ GC (s) │ GC % │ Alloc (MB) │ RSS (MB) │\n", color = :white)
119119
flush(ctx.stdout)
120120
finally
121121
unlock(ctx.lock)
@@ -125,7 +125,7 @@ end
125125
function print_test_started(::Type{TestRecord}, wrkr, test, ctx::TestIOContext)
126126
lock(ctx.lock)
127127
try
128-
printstyled(ctx.stdout, test, lpad("($wrkr)", ctx.name_align - textwidth(test) + 1, " "), " |", color = :white)
128+
printstyled(ctx.stdout, test, lpad("($wrkr)", ctx.name_align - textwidth(test) + 1, " "), " │", color = :white)
129129
printstyled(
130130
ctx.stdout,
131131
" "^ctx.elapsed_align, "started at $(now())\n", color = :light_black
@@ -140,23 +140,19 @@ function print_test_finished(test, wrkr, record::TestRecord, ctx::TestIOContext)
140140
lock(ctx.lock)
141141
try
142142
printstyled(ctx.stdout, test, color = :white)
143-
printstyled(ctx.stdout, lpad("($wrkr)", ctx.name_align - textwidth(test) + 1, " "), " | ", color = :white)
143+
printstyled(ctx.stdout, lpad("($wrkr)", ctx.name_align - textwidth(test) + 1, " "), " │ ", color = :white)
144144
time_str = @sprintf("%7.2f", record.time)
145-
printstyled(ctx.stdout, lpad(time_str, ctx.elapsed_align, " "), " | ", color = :white)
145+
printstyled(ctx.stdout, lpad(time_str, ctx.elapsed_align, " "), " │ ", color = :white)
146146

147147
gc_str = @sprintf("%5.2f", record.gctime)
148-
printstyled(ctx.stdout, lpad(gc_str, ctx.gc_align, " "), " | ", color = :white)
148+
printstyled(ctx.stdout, lpad(gc_str, ctx.gc_align, " "), " │ ", color = :white)
149149
percent_str = @sprintf("%4.1f", 100 * record.gctime / record.time)
150-
printstyled(ctx.stdout, lpad(percent_str, ctx.percent_align, " "), " | ", color = :white)
150+
printstyled(ctx.stdout, lpad(percent_str, ctx.percent_align, " "), " │ ", color = :white)
151151
alloc_str = @sprintf("%5.2f", record.bytes / 2^20)
152-
printstyled(ctx.stdout, lpad(alloc_str, ctx.alloc_align, " "), " | ", color = :white)
152+
printstyled(ctx.stdout, lpad(alloc_str, ctx.alloc_align, " "), " │ ", color = :white)
153153

154154
rss_str = @sprintf("%5.2f", record.rss / 2^20)
155-
printstyled(ctx.stdout, lpad(rss_str, ctx.rss_align, " "), " |\n", color = :white)
156-
157-
for line in eachline(IOBuffer(record.output))
158-
println(ctx.stdout, " "^(ctx.name_align + 2), "| ", line)
159-
end
155+
printstyled(ctx.stdout, lpad(rss_str, ctx.rss_align, " "), " │\n", color = :white)
160156

161157
flush(ctx.stdout)
162158
finally
@@ -199,24 +195,24 @@ function runtest(::Type{TestRecord}, f, name, init_code)
199195
GC.gc(true)
200196
Random.seed!(1)
201197

202-
res = @timed IOCapture.capture() do
198+
stats = @timed IOCapture.capture() do
203199
@testset $name begin
204200
$f
205201
end
206202
end
207-
captured = res.value
208-
(; testset=captured.value, captured.output, res.time, res.bytes, res.gctime)
203+
captured = stats.value
204+
(; testset=captured.value, captured.output, stats.time, stats.bytes, stats.gctime)
209205
end
210206

211207
# process results
212208
rss = Sys.maxrss()
213-
res = TestRecord(data..., rss)
209+
record = TestRecord(data..., rss)
214210

215211
GC.gc(true)
216-
return res
212+
return record
217213
end
218214

219-
res = @static if VERSION >= v"1.13.0-DEV.1044"
215+
@static if VERSION >= v"1.13.0-DEV.1044"
220216
@with Test.TESTSET_PRINT_ENABLE => false begin
221217
inner()
222218
end
@@ -229,7 +225,6 @@ function runtest(::Type{TestRecord}, f, name, init_code)
229225
Test.TESTSET_PRINT_ENABLE[] = old_print_setting
230226
end
231227
end
232-
return res
233228
end
234229

235230
# This is an internal function, not to be used by end users. The keyword
@@ -667,26 +662,27 @@ function runtests(ARGS; testfilter = Returns(true), RecordType = TestRecord,
667662

668663
# run the test
669664
put!(printer_channel, (:started, test, wrkr))
670-
resp = try
665+
result = try
671666
remotecall_fetch(runtest, wrkr, RecordType, test_runners[test], test, init_code)
672-
catch e
673-
isa(e, InterruptException) && return
674-
Any[e]
667+
catch ex
668+
isa(ex, InterruptException) && return
669+
# XXX: also put this in a test record?
670+
ex
675671
end
676672
test_t1 = time()
677-
push!(results, (test, resp, test_t0, test_t1))
673+
push!(results, (test, result, test_t0, test_t1))
678674

679675
# act on the results
680-
if resp isa AbstractTestRecord
681-
put!(printer_channel, (:finished, test, wrkr, resp::RecordType))
676+
if result isa AbstractTestRecord
677+
put!(printer_channel, (:finished, test, wrkr, result::RecordType))
682678

683-
if memory_usage(resp) > max_worker_rss
679+
if memory_usage(result) > max_worker_rss
684680
# the worker has reached the max-rss limit, recycle it
685681
# so future tests start with a smaller working set
686682
p = recycle_worker(p)
687683
end
688684
else
689-
@assert resp[1] isa Exception
685+
@assert result isa Exception
690686
put!(printer_channel, (:errored, test, wrkr))
691687
if do_quickfail
692688
stop_work()
@@ -749,6 +745,27 @@ function runtests(ARGS; testfilter = Returns(true), RecordType = TestRecord,
749745
end
750746
end
751747

748+
# print the output generated by each testset
749+
for (testname, result, start, stop) in results
750+
if isa(result, AbstractTestRecord) && !isempty(result.output)
751+
println(io_ctx.stdout, "\nOutput generated during execution of '$testname':")
752+
lines = collect(eachline(IOBuffer(result.output)))
753+
754+
for (i,line) in enumerate(lines)
755+
prefix = if length(lines) == 1
756+
"["
757+
elseif i == 1
758+
"┌"
759+
elseif i == length(lines)
760+
"└"
761+
else
762+
"│"
763+
end
764+
println(io_ctx.stdout, prefix, " ", line)
765+
end
766+
end
767+
end
768+
752769
# construct a testset to render the test results
753770
function create_testset(name; start=nothing, stop=nothing, kwargs...)
754771
if start === nothing
@@ -780,47 +797,42 @@ function runtests(ARGS; testfilter = Returns(true), RecordType = TestRecord,
780797
o_ts = create_testset("Overall"; start=t0, stop=t1, verbose=do_verbose)
781798
with_testset(o_ts) do
782799
completed_tests = Set{String}()
783-
for (testname, res, start, stop) in results
784-
if res isa AbstractTestRecord
785-
resp = res.test
786-
else
787-
resp = res[1]
788-
end
800+
for (testname, result, start, stop) in results
789801
push!(completed_tests, testname)
790802

791803
# decode or fake a testset
792-
if isa(resp, Test.DefaultTestSet)
793-
testset = resp
804+
if isa(result, AbstractTestRecord)
805+
testset = result.test
794806
else
795807
testset = create_testset(testname; start, stop)
796-
if isa(resp, RemoteException) &&
797-
isa(resp.captured.ex, Test.TestSetException)
798-
println(io_ctx.stderr, "Worker $(resp.pid) failed running test $(testname):")
799-
Base.showerror(io_ctx.stderr, resp.captured)
808+
if isa(result, RemoteException) &&
809+
isa(result.captured.ex, Test.TestSetException)
810+
println(io_ctx.stderr, "Worker $(result.pid) failed running test $(testname):")
811+
Base.showerror(io_ctx.stderr, result.captured)
800812
println(io_ctx.stderr)
801813

802814
c = IOCapture.capture() do
803-
for i in 1:resp.captured.ex.pass
815+
for i in 1:result.captured.ex.pass
804816
Test.record(testset, Test.Pass(:test, nothing, nothing, nothing, nothing))
805817
end
806-
for i in 1:resp.captured.ex.broken
818+
for i in 1:result.captured.ex.broken
807819
Test.record(testset, Test.Broken(:test, nothing))
808820
end
809-
for t in resp.captured.ex.errors_and_fails
821+
for t in result.captured.ex.errors_and_fails
810822
Test.record(testset, t)
811823
end
812824
end
813825
print(io_ctx.stdout, c.output)
814826
else
815-
if !isa(resp, Exception)
816-
resp = ErrorException(string("Unknown result type : ", typeof(resp)))
827+
if !isa(result, Exception)
828+
result = ErrorException(string("Unknown result type : ", typeof(result)))
817829
end
818830
# If this test raised an exception that is not a remote testset exception,
819831
# i.e. not a RemoteException capturing a TestSetException that means
820832
# the test runner itself had some problem, so we may have hit a segfault,
821833
# deserialization errors or something similar. Record this testset as Errored.
822834
c = IOCapture.capture() do
823-
Test.record(testset, Test.Error(:nontest_error, testname, nothing, Base.ExceptionStack([(exception = resp, backtrace = [])]), LineNumberNode(1)))
835+
Test.record(testset, Test.Error(:nontest_error, testname, nothing, Base.ExceptionStack([(exception = result, backtrace = [])]), LineNumberNode(1)))
824836
end
825837
print(io_ctx.stdout, c.output)
826838
end

0 commit comments

Comments
 (0)