function tidy & change handling to two separate categories

base/timing.jl

@@ -55,16 +55,20 @@ function gc_alloc_count(diff::GC_Diff)
     diff.malloc + diff.realloc + diff.poolalloc + diff.bigalloc
 end
 
-# cumulative total time spent on compilation, in nanoseconds
-function cumulative_compile_time_ns_before()
-    comp = ccall(:jl_cumulative_compile_time_ns_before, UInt64, ())
-    recomp = ccall(:jl_cumulative_recompile_time_ns_before, UInt64, ())
+# cumulative total time spent on compilation and recompilation, in nanoseconds
+function cumulative_compile_time_ns()
+    comp = ccall(:jl_cumulative_compile_time_ns, UInt64, ())
+    recomp = ccall(:jl_cumulative_recompile_time_ns, UInt64, ())
     return comp, recomp
 end
-function cumulative_compile_time_ns_after()
-    comp = ccall(:jl_cumulative_compile_time_ns_after, UInt64, ())
-    recomp = ccall(:jl_cumulative_recompile_time_ns_before, UInt64, ())
-    return comp, recomp
+
+function cumulative_compile_timing(b::Bool)
+    if b
+        ccall(:jl_cumulative_compile_timing_enable, Cvoid, ())
+    else
+        ccall(:jl_cumulative_compile_timing_disable, Cvoid, ())
+    end
+    return
 end
 
 # total time spend in garbage collection, in nanoseconds
@@ -127,7 +131,7 @@ function time_print(elapsedtime, bytes=0, gctime=0, allocs=0, compile_time=0, re
     str = sprint() do io
         _lpad && print(io, length(timestr) < 10 ? (" "^(10 - length(timestr))) : "")
         print(io, timestr, " seconds")
-        parens = bytes != 0 || allocs != 0 || gctime > 0 || compile_time > 0
+        parens = bytes != 0 || allocs != 0 || gctime > 0 || compile_time > 0 || recompile_time > 0
         parens && print(io, " (")
         if bytes != 0 || allocs != 0
             allocs, ma = prettyprint_getunits(allocs, length(_cnt_units), Int64(1000))
@@ -151,7 +155,10 @@ function time_print(elapsedtime, bytes=0, gctime=0, allocs=0, compile_time=0, re
             print(io, Ryu.writefixed(Float64(100*compile_time/elapsedtime), 2), "% compilation time")
         end
         if recompile_time > 0
-            print(io, " of which ", Ryu.writefixed(Float64(100*recompile_time/compile_time), 0), "% was recompilation")
+            if bytes != 0 || allocs != 0 || gctime > 0 || compile_time > 0
+                print(io, ", ")
+            end
+            print(io, Ryu.writefixed(Float64(100*recompile_time/elapsedtime), 2), "% recompilation time")
         end
         parens && print(io, ")")
     end
@@ -251,10 +258,12 @@ macro time(msg, ex)
         Experimental.@force_compile
         local stats = gc_num()
         local elapsedtime = time_ns()
-        local compile_elapsedtimes = cumulative_compile_time_ns_before()
+        cumulative_compile_timing(true)
+        local compile_elapsedtimes = cumulative_compile_time_ns()
         local val = @__tryfinally($(esc(ex)),
             (elapsedtime = time_ns() - elapsedtime;
-            compile_elapsedtimes = cumulative_compile_time_ns_after() .- compile_elapsedtimes)
+            cumulative_compile_timing(false);
+            compile_elapsedtimes = cumulative_compile_time_ns() .- compile_elapsedtimes)
         )
         local diff = GC_Diff(gc_num(), stats)
         local _msg = $(esc(msg))
@@ -333,10 +342,10 @@ macro timev(msg, ex)
         Experimental.@force_compile
         local stats = gc_num()
         local elapsedtime = time_ns()
-        local compile_elapsedtimes = cumulative_compile_time_ns_before()
+        local compile_elapsedtimes = cumulative_compile_time_ns()
         local val = @__tryfinally($(esc(ex)),
             (elapsedtime = time_ns() - elapsedtime;
-            compile_elapsedtimes = cumulative_compile_time_ns_after() .- compile_elapsedtimes)
+            compile_elapsedtimes = cumulative_compile_time_ns() .- compile_elapsedtimes)
         )
         local diff = GC_Diff(gc_num(), stats)
         local _msg = $(esc(msg))

src/jitlayers.cpp

@@ -365,7 +365,8 @@ jl_code_instance_t *jl_generate_fptr_impl(jl_method_instance_t *mi JL_PROPAGATES
         uint64_t t_comp = jl_hrtime() - compiler_start_time;
         if (is_recompile)
             jl_atomic_fetch_add_relaxed(&jl_cumulative_recompile_time, t_comp);
-        jl_atomic_fetch_add_relaxed(&jl_cumulative_compile_time, t_comp);
+        else
+            jl_atomic_fetch_add_relaxed(&jl_cumulative_compile_time, t_comp);
     }
     JL_UNLOCK(&jl_codegen_lock);
     JL_GC_POP();

src/jlapi.c

@@ -471,26 +471,24 @@ JL_DLLEXPORT void (jl_cpu_wake)(void)
     jl_cpu_wake();
 }
 
-JL_DLLEXPORT uint64_t jl_cumulative_compile_time_ns_before(void)
+JL_DLLEXPORT void jl_cumulative_compile_timing_enable(void)
 {
     // Increment the flag to allow reentrant callers to `@time`.
     jl_atomic_fetch_add(&jl_measure_compile_time_enabled, 1);
-    return jl_atomic_load_relaxed(&jl_cumulative_compile_time);
 }
 
-JL_DLLEXPORT uint64_t jl_cumulative_compile_time_ns_after(void)
+JL_DLLEXPORT void jl_cumulative_compile_timing_disable(void)
 {
     // Decrement the flag when done measuring, allowing other callers to continue measuring.
     jl_atomic_fetch_add(&jl_measure_compile_time_enabled, -1);
-    return jl_atomic_load_relaxed(&jl_cumulative_compile_time);
 }
 
-JL_DLLEXPORT uint64_t jl_cumulative_recompile_time_ns_before(void)
+JL_DLLEXPORT uint64_t jl_cumulative_compile_time_ns(void)
 {
-    return jl_atomic_load_relaxed(&jl_cumulative_recompile_time);
+    return jl_atomic_load_relaxed(&jl_cumulative_compile_time);
 }
 
-JL_DLLEXPORT uint64_t jl_cumulative_recompile_time_ns_after(void)
+JL_DLLEXPORT uint64_t jl_cumulative_recompile_time_ns(void)
 {
     return jl_atomic_load_relaxed(&jl_cumulative_recompile_time);
 }

test/misc.jl

@@ -334,7 +334,8 @@ function timev_macro_scope()
 end
 @test timev_macro_scope() == 1
 
-before_comp, before_recomp = Base.cumulative_compile_time_ns_before()
+cumulative_compile_timing(true)
+before_comp, before_recomp = Base.cumulative_compile_time_ns()
 
 # exercise concurrent calls to `@time` for reentrant compilation time measurement.
 t1 = @async @time begin
@@ -347,7 +348,8 @@ t2 = @async begin
     @time 2 + 2
 end
 
-after_comp, after_recomp = Base.cumulative_compile_time_ns_after()
+cumulative_compile_timing(false)
+after_comp, after_recomp = Base.cumulative_compile_time_ns()
 @test after_comp >= before_comp;
 
 # wait for completion of these tasks before restoring stdout, to suppress their @time prints.