WIP log testsetup start/done and timings

Author: nickrobinson251

src/ReTestItems.jl

@@ -856,9 +856,12 @@ function runtestsetup(ts::TestSetup, ctx::TestContext; logs::Symbol)
         mod_expr = :(module $(gensym(ts.name)) end)
         # replace the module expr body with our @testsetup code
         mod_expr.args[3] = ts.code
-        newmod = _redirect_logs(logs == :eager ? DEFAULT_STDOUT[] : ts.logstore[]) do
+        log_testsetup_start(ts)
+        newmod, stats = @timed_with_compilation _redirect_logs(logs == :eager ? DEFAULT_STDOUT[] : ts.logstore[]) do
             with_source_path(() -> Core.eval(Main, mod_expr), ts.file)
         end
+        ts.stats[] = stats
+        log_testsetup_done(ts)
         # add the new module to our TestSetupModules
         mods.modules[ts.name] = newmod
         return nameof(newmod)

src/log_capture.jl

@@ -55,6 +55,11 @@ function _print_scaled_one_dec(io, value, scale, label="")
     end
     print(io, label)
 end
+function print_time(io::IO, s::PerfStats)
+    return print_time(
+        io; s.elapsedtime, s.bytes, s.gctime, s.allocs, s.compile_time, s.recompile_time
+    )
+end
 function print_time(io; elapsedtime, bytes=0, gctime=0, allocs=0, compile_time=0, recompile_time=0)
     _print_scaled_one_dec(io, elapsedtime, 1e9, " secs")
     if  gctime > 0 || compile_time > 0
@@ -241,7 +246,7 @@ function _print_test_errors(report_iob, ts::DefaultTestSet, worker_info)
     return nothing
 end
 
-function print_state(io, state, ti, ntestitems; color=:default)
+function print_state(io::IO, state::String, ti::TestItem, ntestitems; color=:default)
     interactive = parse(Bool, get(ENV, "RETESTITEMS_INTERACTIVE", string(Base.isinteractive())))
     print(io, format(now(), "HH:MM:SS | "))
     !interactive && print(io, _mem_watermark())
@@ -254,6 +259,13 @@ function print_state(io, state, ti, ntestitems; color=:default)
     end
     print(io, " test item $(repr(ti.name)) ")
 end
+function print_state(io::IO, state::String, ts::TestSetup)
+    interactive = parse(Bool, get(ENV, "RETESTITEMS_INTERACTIVE", string(Base.isinteractive())))
+    print(io, format(now(), "HH:MM:SS | "))
+    !interactive && print(io, _mem_watermark())
+    printstyled(io, rpad(uppercase(state), 5))
+    print(io, " test setup $(ts.name) ")
+end
 
 function print_file_info(io, ti)
     print(io, "at ")
@@ -268,20 +280,33 @@ function log_testitem_skipped(ti::TestItem, ntestitems=0)
     write(DEFAULT_STDOUT[], take!(io.io))
 end
 
-# Marks the start of each test item
 function log_testitem_start(ti::TestItem, ntestitems=0)
     io = IOContext(IOBuffer(), :color => get(DEFAULT_STDOUT[], :color, false)::Bool)
     print_state(io, "START", ti, ntestitems)
     print_file_info(io, ti)
     println(io)
     write(DEFAULT_STDOUT[], take!(io.io))
 end
+function log_testsetup_start(ts::TestSetup)
+    io = IOContext(IOBuffer(), :color => get(DEFAULT_STDOUT[], :color, false)::Bool)
+    print_state(io, "START", ts)
+    print_file_info(io, ts)
+    println(io)
+    write(DEFAULT_STDOUT[], take!(io.io))
+end
 
 function log_testitem_done(ti::TestItem, ntestitems=0)
     io = IOContext(IOBuffer(), :color => get(DEFAULT_STDOUT[], :color, false)::Bool)
     print_state(io, "DONE", ti, ntestitems)
-    x = last(ti.stats) # always print stats for most recent run
-    print_time(io; x.elapsedtime, x.bytes, x.gctime, x.allocs, x.compile_time, x.recompile_time)
+    stats = last(ti.stats) # always print stats for most recent run
+    print_time(io, stats)
+    println(io)
+    write(DEFAULT_STDOUT[], take!(io.io))
+end
+function log_testsetup_done(ts::TestSetup, ntestitems=0)
+    io = IOContext(IOBuffer(), :color => get(DEFAULT_STDOUT[], :color, false)::Bool)
+    print_state(io, "DONE", ts)
+    print_time(io, ts.stats[])
     println(io)
     write(DEFAULT_STDOUT[], take!(io.io))
 end

src/macros.jl

@@ -1,11 +1,46 @@
 gettls(k, d) = get(task_local_storage(), k, d)
 
 ###
-### testsetup
+### PerfStats
+###
+
+Base.@kwdef struct PerfStats
+    elapsedtime::UInt=0
+    bytes::Int=0
+    gctime::Int=0
+    allocs::Int=0
+    compile_time::UInt=0
+    recompile_time::UInt=0
+end
+
+# Adapted from Base.@time
+macro timed_with_compilation(ex)
+    quote
+        Base.Experimental.@force_compile
+        local stats = Base.gc_num()
+        local elapsedtime = Base.time_ns()
+        Base.cumulative_compile_timing(true)
+        local compile_elapsedtimes = Base.cumulative_compile_time_ns()
+        local val = Base.@__tryfinally($(esc(ex)),
+            (elapsedtime = Base.time_ns() - elapsedtime;
+            Base.cumulative_compile_timing(false);
+            compile_elapsedtimes = Base.cumulative_compile_time_ns() .- compile_elapsedtimes)
+        )
+        local diff = Base.GC_Diff(Base.gc_num(), stats)
+        local out = PerfStats(;
+            elapsedtime, bytes=diff.allocd, gctime=diff.total_time, allocs=Base.gc_alloc_count(diff),
+            compile_time=first(compile_elapsedtimes), recompile_time=last(compile_elapsedtimes)
+        )
+        val, out
+    end
+end
+
+###
+### TestSetup
 ###
 
 """
-    TestSetup(name, code)
+    TestSetup
 
 A module that a `TestItem` can require to be run before that `TestItem` is run.
 Used for declaring code that multiple `TestItem`s rely on.
@@ -21,6 +56,10 @@ struct TestSetup
     # the test setup. This IO object is only for writing on the worker. The coordinator needs
     # to open the file when it needs to read from it.
     logstore::Base.RefValue{IOStream} # Populated and only safe to use on the worker
+    stats::Base.RefValue{PerfStats} # populated when the test setup is finished running
+end
+function TestSetup(name::Symbol, code, file::String, line::Int, project_root::String)
+    return TestSetup(name, code, file, line, project_root, Ref{IOStream}(), Ref{PerfStats}())
 end
 
 """
@@ -53,46 +92,20 @@ macro testsetup(mod)
     name isa Symbol || error("`@testsetup module` expects a valid module name")
     nm = QuoteNode(name)
     q = QuoteNode(code)
+    _source = QuoteNode(__source__)
     esc(quote
-        $store_test_setup($TestSetup($nm, $q, $(String(__source__.file)), $(__source__.line), $gettls(:__RE_TEST_PROJECT__, "."), Ref{IOStream}()))
+        $store_test_setup(
+            $TestSetup(
+                $nm, $q, $String($_source.file), $_source.line, $gettls(:__RE_TEST_PROJECT__, "."),
+            )
+        )
     end)
 end
 
 ###
-### testitem
+### TestItem
 ###
 
-Base.@kwdef struct PerfStats
-    elapsedtime::UInt=0
-    bytes::Int=0
-    gctime::Int=0
-    allocs::Int=0
-    compile_time::UInt=0
-    recompile_time::UInt=0
-end
-
-# Adapted from Base.@time
-macro timed_with_compilation(ex)
-    quote
-        Base.Experimental.@force_compile
-        local stats = Base.gc_num()
-        local elapsedtime = Base.time_ns()
-        Base.cumulative_compile_timing(true)
-        local compile_elapsedtimes = Base.cumulative_compile_time_ns()
-        local val = Base.@__tryfinally($(esc(ex)),
-            (elapsedtime = Base.time_ns() - elapsedtime;
-            Base.cumulative_compile_timing(false);
-            compile_elapsedtimes = Base.cumulative_compile_time_ns() .- compile_elapsedtimes)
-        )
-        local diff = Base.GC_Diff(Base.gc_num(), stats)
-        local out = PerfStats(;
-            elapsedtime, bytes=diff.allocd, gctime=diff.total_time, allocs=Base.gc_alloc_count(diff),
-            compile_time=first(compile_elapsedtimes), recompile_time=last(compile_elapsedtimes)
-        )
-        val, out
-    end
-end
-
 mutable struct ScheduledForEvaluation
     @atomic value::Bool
 end