From 3a4a8b48046248139c5507fd57ffc21066945009 Mon Sep 17 00:00:00 2001 From: kshyatt Date: Wed, 7 Dec 2016 14:47:26 -0800 Subject: [PATCH 1/2] Fix #18739, Make testset results printing better Now results come in one by one and print their memory/timing data as they come in. We will no longer print rss results twice. Also, each test now prints which worker it ran on. --- base/test.jl | 8 +++++--- test/runtests.jl | 51 ++++++++++++++++++++++++------------------------ test/testdefs.jl | 2 -- 3 files changed, 31 insertions(+), 30 deletions(-) diff --git a/base/test.jl b/base/test.jl index 04f7ac5511a18..2df29630e4177 100644 --- a/base/test.jl +++ b/base/test.jl @@ -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)) @@ -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 diff --git a/test/runtests.jl b/test/runtests.jl index bcb034a1b16c0..5172d85719437 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -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() @@ -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 @@ -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 diff --git a/test/testdefs.jl b/test/testdefs.jl index b80827ee7faa7..f0bdef62a28e5 100644 --- a/test/testdefs.jl +++ b/test/testdefs.jl @@ -8,7 +8,6 @@ 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") @@ -16,7 +15,6 @@ function runtests(name, isolate=true) 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 From 3120377bfe7c8bb59a376879d45acc1a5929d1c2 Mon Sep 17 00:00:00 2001 From: kshyatt Date: Fri, 9 Dec 2016 17:08:06 -0800 Subject: [PATCH 2/2] Fix failing replutil test --- test/replutil.jl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/replutil.jl b/test/replutil.jl index 654c099d6a7e9..31ac32ff2c5bc 100644 --- a/test/replutil.jl +++ b/test/replutil.jl @@ -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