From fe528c1da79c052e5cdbf25ceffa5cf09a909670 Mon Sep 17 00:00:00 2001 From: Ian Date: Mon, 18 Apr 2022 11:03:56 -0400 Subject: [PATCH] function tidy & change handling to two separate categories --- base/timing.jl | 33 +++++++++++++++++++++------------ src/jitlayers.cpp | 3 ++- src/jlapi.c | 12 +++++------- 3 files changed, 28 insertions(+), 20 deletions(-) diff --git a/base/timing.jl b/base/timing.jl index bcc77fd6e30619..737f44b39d3b54 100644 --- a/base/timing.jl +++ b/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)) diff --git a/src/jitlayers.cpp b/src/jitlayers.cpp index f126324b605ea1..754998dd8f1396 100644 --- a/src/jitlayers.cpp +++ b/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(); diff --git a/src/jlapi.c b/src/jlapi.c index 732b1eec1e7475..89c6e90684b691 100644 --- a/src/jlapi.c +++ b/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); }