From c5e918c1ea658d12b8699b38bad4592a69f3d4dd Mon Sep 17 00:00:00 2001 From: Nick Robinson Date: Sat, 20 Jan 2024 14:40:06 +0000 Subject: [PATCH] WIP log testsetup start/done and timings --- src/ReTestItems.jl | 5 ++- src/log_capture.jl | 33 +++++++++++++++--- src/macros.jl | 83 +++++++++++++++++++++++++++------------------- 3 files changed, 81 insertions(+), 40 deletions(-) diff --git a/src/ReTestItems.jl b/src/ReTestItems.jl index f09ffe24..b805d0b5 100644 --- a/src/ReTestItems.jl +++ b/src/ReTestItems.jl @@ -864,9 +864,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) diff --git a/src/log_capture.jl b/src/log_capture.jl index f48bb27f..23b420e8 100644 --- a/src/log_capture.jl +++ b/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 @@ -243,7 +248,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()) @@ -256,6 +261,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 ") @@ -270,7 +282,6 @@ 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) @@ -278,12 +289,26 @@ function log_testitem_start(ti::TestItem, ntestitems=0) 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 diff --git a/src/macros.jl b/src/macros.jl index 60f585a5..bdbbc038 100644 --- a/src/macros.jl +++ b/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