Show any compile time spent in time and timev macros

base/timing.jl

@@ -55,6 +55,9 @@ function gc_alloc_count(diff::GC_Diff)
     diff.malloc + diff.realloc + diff.poolalloc + diff.bigalloc
 end
 
+# cumulative total time spent on compilation
+cumulative_compile_time_ns() = ccall(:jl_cumulative_compile_time_ns, UInt64, ())
+reset_cumulative_compile_time() = ccall(:jl_reset_cumulative_compile_time, Cvoid, ())
 
 # total time spend in garbage collection, in nanoseconds
 gc_time_ns() = ccall(:jl_gc_total_hrtime, UInt64, ())
@@ -102,7 +105,7 @@ function format_bytes(bytes) # also used by InteractiveUtils
     end
 end
 
-function time_print(elapsedtime, bytes=0, gctime=0, allocs=0)
+function time_print(elapsedtime, bytes=0, gctime=0, allocs=0, compile_time=0)
     timestr = Ryu.writefixed(Float64(elapsedtime/1e9), 6)
     length(timestr) < 10 && print(" "^(10 - length(timestr)))
     print(timestr, " seconds")
@@ -118,15 +121,18 @@ function time_print(elapsedtime, bytes=0, gctime=0, allocs=0)
     if gctime > 0
         print(", ", Ryu.writefixed(Float64(100*gctime/elapsedtime), 2), "% gc time")
     end
+    if compile_time > 0
+        print(", ", Ryu.writefixed(Float64(100*compile_time/elapsedtime), 2), "% compilation time")
+    end
     if bytes != 0 || allocs != 0
         print(")")
     end
     nothing
 end
 
-function timev_print(elapsedtime, diff::GC_Diff)
+function timev_print(elapsedtime, diff::GC_Diff, compile_time)
     allocs = gc_alloc_count(diff)
-    time_print(elapsedtime, diff.allocd, diff.total_time, allocs)
+    time_print(elapsedtime, diff.allocd, diff.total_time, allocs, compile_time)
     print("\nelapsed time (ns): $elapsedtime\n")
     padded_nonzero_print(diff.total_time,   "gc time (ns)")
     padded_nonzero_print(diff.allocd,       "bytes allocated")
@@ -169,13 +175,16 @@ julia> @time begin
 macro time(ex)
     quote
         while false; end # compiler heuristic: compile this block (alter this if the heuristic changes)
+        reset_cumulative_compile_time() # reduce risk of overflow on cumulative counter
         local stats = gc_num()
+        local compile_elapsedtime = cumulative_compile_time_ns()
         local elapsedtime = time_ns()
         local val = $(esc(ex))
         elapsedtime = time_ns() - elapsedtime
+        compile_elapsedtime = cumulative_compile_time_ns() - compile_elapsedtime
         local diff = GC_Diff(gc_num(), stats)
         time_print(elapsedtime, diff.allocd, diff.total_time,
-                   gc_alloc_count(diff))
+                   gc_alloc_count(diff), compile_elapsedtime)
         println()
         val
     end
@@ -203,11 +212,14 @@ malloc() calls:    1
 macro timev(ex)
     quote
         while false; end # compiler heuristic: compile this block (alter this if the heuristic changes)
+        reset_cumulative_compile_time() # reduce risk of overflow on cumulative counter
         local stats = gc_num()
+        local compile_elapsedtime = cumulative_compile_time_ns()
         local elapsedtime = time_ns()
         local val = $(esc(ex))
         elapsedtime = time_ns() - elapsedtime
-        timev_print(elapsedtime, GC_Diff(gc_num(), stats))
+        compile_elapsedtime = cumulative_compile_time_ns() - compile_elapsedtime
+        timev_print(elapsedtime, GC_Diff(gc_num(), stats), compile_elapsedtime)
         val
     end
 end

src/jitlayers.cpp

@@ -67,6 +67,19 @@ void jl_jit_globals(std::map<void *, GlobalVariable*> &globals)
     }
 }
 
+static uint64_t cumulative_compile_time = 0;
+static uint64_t compiler_start_time = 0;
+
+extern "C" JL_DLLEXPORT
+uint64_t jl_cumulative_compile_time_ns() {
+    return cumulative_compile_time;
+}
+
+extern "C" JL_DLLEXPORT
+void jl_reset_cumulative_compile_time() {
+    cumulative_compile_time = 0;
+}
+
 // this generates llvm code for the lambda info
 // and adds the result to the jitlayers
 // (and the shadow module),
@@ -200,6 +213,7 @@ static jl_callptr_t _jl_compile_codeinst(
             jl_printf(dump_compiles_stream, "\"\n");
         }
     }
+    cumulative_compile_time = cumulative_compile_time + (jl_hrtime() - compiler_start_time);
     return fptr;
 }
 
@@ -210,6 +224,7 @@ extern "C" JL_DLLEXPORT
 void jl_compile_extern_c(void *llvmmod, void *p, void *sysimg, jl_value_t *declrt, jl_value_t *sigt)
 {
     JL_LOCK(&codegen_lock);
+    compiler_start_time = jl_hrtime();
     jl_codegen_params_t params;
     jl_codegen_params_t *pparams = (jl_codegen_params_t*)p;
     if (pparams == NULL)
@@ -281,6 +296,7 @@ extern "C"
 jl_code_instance_t *jl_generate_fptr(jl_method_instance_t *mi JL_PROPAGATES_ROOT, size_t world)
 {
     JL_LOCK(&codegen_lock); // also disables finalizers, to prevent any unexpected recursion
+    compiler_start_time = jl_hrtime();
     // if we don't have any decls already, try to generate it now
     jl_code_info_t *src = NULL;
     JL_GC_PUSH1(&src);
@@ -329,6 +345,7 @@ void jl_generate_fptr_for_unspecialized(jl_code_instance_t *unspec)
         return;
     }
     JL_LOCK(&codegen_lock);
+    compiler_start_time = jl_hrtime();
     if (unspec->invoke == NULL) {
         jl_code_info_t *src = NULL;
         JL_GC_PUSH1(&src);