Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

WIP log testsetup start/done and timings #142

Draft
wants to merge 1 commit into
base: npr-refactor-testsetup-handling
Choose a base branch
from
Draft

WIP log testsetup start/done and timings #142

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
5 changes: 4 additions & 1 deletion src/ReTestItems.jl
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
33 changes: 29 additions & 4 deletions src/log_capture.jl
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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())
Expand All @@ -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 ")
Expand All @@ -270,20 +282,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
Expand Down
83 changes: 48 additions & 35 deletions src/macros.jl
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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.
Expand All @@ -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

"""
Expand Down Expand Up @@ -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
Expand Down
Loading