Skip to content

Commit

Permalink
Merge pull request #19531 from JuliaLang/ksh/prettyprinttest
Browse files Browse the repository at this point in the history
Fix #18739, Make testset results printing better
  • Loading branch information
kshyatt committed Dec 11, 2016
2 parents 0dfadd0 + 3120377 commit 579cfcb
Show file tree
Hide file tree
Showing 4 changed files with 32 additions and 31 deletions.
8 changes: 5 additions & 3 deletions base/test.jl
Original file line number Diff line number Diff line change
Expand Up @@ -44,7 +44,9 @@ immutable Pass <: Result
end
function Base.show(io::IO, t::Pass)
print_with_color(:green, io, "Test Passed\n")
print(io, " Expression: ", t.orig_expr)
if !(t.orig_expr === nothing)
print(io, " Expression: ", t.orig_expr)
end
if t.test_type == :test_throws
# The correct type of exception was thrown
print(io, "\n Thrown: ", typeof(t.value))
Expand Down Expand Up @@ -139,9 +141,9 @@ type Broken <: Result
end
function Base.show(io::IO, t::Broken)
print_with_color(:yellow, io, "Test Broken\n")
if t.test_type == :skipped
if t.test_type == :skipped && !(t.orig_expr === nothing)
println(io, " Skipped: ", t.orig_expr)
else
elseif !(t.orig_expr === nothing)
println(io, "Expression: ", t.orig_expr)
end
end
Expand Down
2 changes: 1 addition & 1 deletion test/replutil.jl
Original file line number Diff line number Diff line change
Expand Up @@ -457,7 +457,7 @@ end
# @macroexpand tests
macro seven_dollar(ex)
# simonbyrne example 18240
isa(ex,Expr) && ex.head == :$ ? 7 : ex
isa(ex,Expr) && ex.head == :$ ? 7 : esc(ex)
end

let
Expand Down
51 changes: 26 additions & 25 deletions test/runtests.jl
Original file line number Diff line number Diff line change
Expand Up @@ -44,6 +44,16 @@ cd(dirname(@__FILE__)) do
end

@everywhere include("testdefs.jl")

#pretty print the information about gc and mem usage
name_align = max(length("Test (Worker)"), maximum(map(x -> length(x) + 3 + ndigits(nworkers()), tests)))
elapsed_align = length("Time (s)")
gc_align = length("GC (s)")
percent_align = length("GC %")
alloc_align = length("Alloc (MB)")
rss_align = length("RSS (MB)")
print_with_color(:white, rpad("Test (Worker)",name_align," "), " | ")
print_with_color(:white, "Time (s) | GC (s) | GC % | Alloc (MB) | RSS (MB)\n")
results=[]
@sync begin
for p in workers()
Expand All @@ -67,6 +77,22 @@ cd(dirname(@__FILE__)) do
isa(resp, Exception) ? rethrow(resp) : error("Halting tests. Memory limit reached : $resp > $max_worker_rss")
end
end
if !isa(resp[1], Exception)
print_with_color(:white, rpad(test*" ($p)", name_align, " "), " | ")
time_str = @sprintf("%7.2f",resp[2])
print_with_color(:white, rpad(time_str,elapsed_align," "), " | ")
gc_str = @sprintf("%5.2f",resp[5].total_time/10^9)
print_with_color(:white, rpad(gc_str,gc_align," "), " | ")

# since there may be quite a few digits in the percentage,
# the left-padding here is less to make sure everything fits
percent_str = @sprintf("%4.1f",100*resp[5].total_time/(10^9*resp[2]))
print_with_color(:white, rpad(percent_str,percent_align," "), " | ")
alloc_str = @sprintf("%5.2f",resp[3]/2^20)
print_with_color(:white, rpad(alloc_str,alloc_align," "), " | ")
rss_str = @sprintf("%5.2f",resp[6]/2^20)
print_with_color(:white, rpad(rss_str,rss_align," "), "\n")
end
end
end
end
Expand Down Expand Up @@ -161,31 +187,6 @@ cd(dirname(@__FILE__)) do
end
println()
Base.Test.print_test_results(o_ts,1)
#pretty print the information about gc and mem usage
name_align = maximum(map(x -> length(x[1]), results))
elapsed_align = length("Total time (s):")
gc_align = length("GC time (s):")
percent_align = length("Percent in gc:")
alloc_align = length("Allocated (MB):")
rss_align = length("RSS (MB):")
print_with_color(:white, rpad("Test:",name_align," "), " | ")
print_with_color(:white, "Total time (s): | GC time (s): | Percent in gc: | Allocated (MB): | RSS (MB):\n")
for res in results
if !isa(res[2][1], Exception)
print_with_color(:white, rpad("$(res[1])",name_align," "), " | ")
time_str = @sprintf("%7.2f",res[2][2])
print_with_color(:white, rpad(time_str,elapsed_align," "), " | ")
gc_str = @sprintf("%7.2f",res[2][5].total_time/10^9)
print_with_color(:white, rpad(gc_str,gc_align," "), " | ")
percent_str = @sprintf("%7.2f",100*res[2][5].total_time/(10^9*res[2][2]))
print_with_color(:white, rpad(percent_str,percent_align," "), " | ")
alloc_str = @sprintf("%7.2f",res[2][3]/2^20)
print_with_color(:white, rpad(alloc_str,alloc_align," "), " | ")
rss_str = @sprintf("%7.2f",res[2][6]/2^20)
print_with_color(:white, rpad(rss_str,rss_align," "), "\n")
end
end

if !o_ts.anynonpass
println(" \033[32;1mSUCCESS\033[0m")
else
Expand Down
2 changes: 0 additions & 2 deletions test/testdefs.jl
Original file line number Diff line number Diff line change
Expand Up @@ -8,15 +8,13 @@ function runtests(name, isolate=true)
m = Main
end
eval(m, :(using Base.Test))
@printf(" \033[1m*\033[0m \033[31m%-21s\033[0m", name)
ex = quote
@timed @testset $"$name" begin
include($"$name.jl")
end
end
res_and_time_data = eval(m, ex)
rss = Sys.maxrss()
@printf(" maxrss %7.2f MB\n", rss / 2^20)
#res_and_time_data[1] is the testset
passes,fails,error,broken,c_passes,c_fails,c_errors,c_broken = Base.Test.get_test_counts(res_and_time_data[1])
if res_and_time_data[1].anynonpass == false
Expand Down

2 comments on commit 579cfcb

@nanosoldier
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Executing the daily benchmark build, I will reply here when finished:

@nanosoldier runbenchmarks(ALL, isdaily = true)

@nanosoldier
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Your benchmark job has completed - possible performance regressions were detected. A full report can be found here. cc @jrevels

Please sign in to comment.