diff --git a/base/timing.jl b/base/timing.jl index 1579cd5673bc9..a72f2980ca3b8 100644 --- a/base/timing.jl +++ b/base/timing.jl @@ -342,9 +342,11 @@ macro timev(msg, ex) Experimental.@force_compile local stats = gc_num() local elapsedtime = time_ns() + cumulative_compile_timing(true) local compile_elapsedtimes = cumulative_compile_time_ns() local val = @__tryfinally($(esc(ex)), (elapsedtime = time_ns() - elapsedtime; + cumulative_compile_timing(false); compile_elapsedtimes = cumulative_compile_time_ns() .- compile_elapsedtimes) ) local diff = GC_Diff(gc_num(), stats) diff --git a/test/misc.jl b/test/misc.jl index acefe3981674c..9ad9b4e21acac 100644 --- a/test/misc.jl +++ b/test/misc.jl @@ -354,6 +354,80 @@ after_comp, after_recomp = Base.cumulative_compile_time_ns() # no need to turn t end # redirect_stdout +macro capture_stdout(ex) + quote + mktemp() do fname, f + redirect_stdout(f) do + $(esc(ex)) + end + seekstart(f) + read(f, String) + end + end +end + +# compilation reports in @time, @timev +let f = gensym("f"), callf = gensym("callf"), call2f = gensym("call2f") + @eval begin + $f(::Real) = 1 + $callf(container) = $f(container[1]) + $call2f(container) = $callf(container) + c64 = [1.0] + c32 = [1.0f0] + cabs = AbstractFloat[1.0] + + out = @capture_stdout @time $call2f(c64) + @test occursin("% compilation time", out) + out = @capture_stdout @time $call2f(c64) + @test occursin("% compilation time", out) == false + + out = @capture_stdout @time $call2f(c32) + @test occursin("% compilation time", out) + out = @capture_stdout @time $call2f(c32) + @test occursin("% compilation time", out) == false + + out = @capture_stdout @time $call2f(cabs) + @test occursin("% compilation time", out) + out = @capture_stdout @time $call2f(cabs) + @test occursin("% compilation time", out) == false + + $f(::Float64) = 2 + out = @capture_stdout @time $call2f(c64) + @test occursin("% compilation time:", out) + @test occursin("% of which was recompilation", out) + end +end +let f = gensym("f"), callf = gensym("callf"), call2f = gensym("call2f") + @eval begin + $f(::Real) = 1 + $callf(container) = $f(container[1]) + $call2f(container) = $callf(container) + c64 = [1.0] + c32 = [1.0f0] + cabs = AbstractFloat[1.0] + + out = @capture_stdout @timev $call2f(c64) + @test occursin("% compilation time", out) + out = @capture_stdout @timev $call2f(c64) + @test occursin("% compilation time", out) == false + + out = @capture_stdout @timev $call2f(c32) + @test occursin("% compilation time", out) + out = @capture_stdout @timev $call2f(c32) + @test occursin("% compilation time", out) == false + + out = @capture_stdout @timev $call2f(cabs) + @test occursin("% compilation time", out) + out = @capture_stdout @timev $call2f(cabs) + @test occursin("% compilation time", out) == false + + $f(::Float64) = 2 + out = @capture_stdout @timev $call2f(c64) + @test occursin("% compilation time:", out) + @test occursin("% of which was recompilation", out) + end +end + # interactive utilities struct ambigconvert; end # inject a problematic `convert` method to ensure it still works