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.

Author: kshyatt

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

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

test/testdefs.jl

@@ -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