Fix timev compilation time tracking and add tests (#46100)

(cherry picked from commit f3c2227)
JuliaLang · Aug 1, 2022 · c02b4e1 · c02b4e1
1 parent 9b38226
commit c02b4e1
Show file tree

Hide file tree

Showing 2 changed files with 76 additions and 0 deletions.
diff --git 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
@@ -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