Skip to content

Commit

Permalink
measure compile time only when using time macros (fix #38877) (#38885)
Browse files Browse the repository at this point in the history 
(cherry picked from commit fa6077e)
  • Loading branch information
@IanButterworth @staticfloat
IanButterworth authored and staticfloat committed Dec 22, 2022
1 parent 0ad3a4d commit 2872446
Show file tree
Hide file tree
Showing 5 changed files with 46 additions and 21 deletions.
11 changes: 6 additions & 5 deletions base/timing.jl
View file
Original file line number Diff line number Diff line change
Expand Up @@ -56,7 +56,8 @@ function gc_alloc_count(diff::GC_Diff)
end

# cumulative total time spent on compilation
cumulative_compile_time_ns() = ccall(:jl_cumulative_compile_time_ns, UInt64, ())
cumulative_compile_time_ns_before() = ccall(:jl_cumulative_compile_time_ns_before, UInt64, ())
cumulative_compile_time_ns_after() = ccall(:jl_cumulative_compile_time_ns_after, UInt64, ())

# total time spend in garbage collection, in nanoseconds
gc_time_ns() = ccall(:jl_gc_total_hrtime, UInt64, ())
Expand Down Expand Up @@ -197,11 +198,11 @@ macro time(ex)
quote
while false; end # compiler heuristic: compile this block (alter this if the heuristic changes)
local stats = gc_num()
local compile_elapsedtime = cumulative_compile_time_ns()
local compile_elapsedtime = cumulative_compile_time_ns_before()
local elapsedtime = time_ns()
local val = $(esc(ex))
elapsedtime = time_ns() - elapsedtime
compile_elapsedtime = cumulative_compile_time_ns() - compile_elapsedtime
compile_elapsedtime = cumulative_compile_time_ns_after() - compile_elapsedtime
local diff = GC_Diff(gc_num(), stats)
time_print(elapsedtime, diff.allocd, diff.total_time,
gc_alloc_count(diff), compile_elapsedtime)
Expand Down Expand Up @@ -245,11 +246,11 @@ macro timev(ex)
quote
while false; end # compiler heuristic: compile this block (alter this if the heuristic changes)
local stats = gc_num()
local compile_elapsedtime = cumulative_compile_time_ns()
local compile_elapsedtime = cumulative_compile_time_ns_before()
local elapsedtime = time_ns()
local val = $(esc(ex))
elapsedtime = time_ns() - elapsedtime
compile_elapsedtime = cumulative_compile_time_ns() - compile_elapsedtime
compile_elapsedtime = cumulative_compile_time_ns_after() - compile_elapsedtime
timev_print(elapsedtime, GC_Diff(gc_num(), stats), compile_elapsedtime)
val
end
Expand Down
15 changes: 10 additions & 5 deletions src/aotcompile.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -292,7 +292,9 @@ void *jl_create_native(jl_array_t *methods, const jl_cgparams_t cgparams, int _p
jl_code_info_t *src = NULL;
JL_GC_PUSH1(&src);
JL_LOCK(&codegen_lock);
uint64_t compiler_start_time = jl_hrtime();
uint64_t compiler_start_time = 0;
if (jl_measure_compile_time)
compiler_start_time = jl_hrtime();

CompilationPolicy policy = (CompilationPolicy) _policy;
std::unique_ptr<Module> clone(jl_create_llvm_module("text"));
Expand Down Expand Up @@ -415,8 +417,8 @@ void *jl_create_native(jl_array_t *methods, const jl_cgparams_t cgparams, int _p
}

data->M = std::move(clone);

jl_cumulative_compile_time += (jl_hrtime() - compiler_start_time);
if (jl_measure_compile_time)
jl_cumulative_compile_time += (jl_hrtime() - compiler_start_time);
JL_UNLOCK(&codegen_lock); // Might GC
return (void*)data;
}
Expand Down Expand Up @@ -893,7 +895,9 @@ void *jl_get_llvmf_defn(jl_method_instance_t *mi, size_t world, char getwrapper,
std::unique_ptr<Module> m;
jl_llvm_functions_t decls;
JL_LOCK(&codegen_lock);
uint64_t compiler_start_time = jl_hrtime();
uint64_t compiler_start_time = 0;
if (jl_measure_compile_time)
compiler_start_time = jl_hrtime();
std::tie(m, decls) = jl_emit_code(mi, src, jlrettype, output);

Function *F = NULL;
Expand All @@ -917,7 +921,8 @@ void *jl_get_llvmf_defn(jl_method_instance_t *mi, size_t world, char getwrapper,
m.release(); // the return object `llvmf` will be the owning pointer
}
JL_GC_POP();
jl_cumulative_compile_time += (jl_hrtime() - compiler_start_time);
if (jl_measure_compile_time)
jl_cumulative_compile_time += (jl_hrtime() - compiler_start_time);
JL_UNLOCK(&codegen_lock); // Might GC
if (F)
return F;
Expand Down
6 changes: 4 additions & 2 deletions src/gf.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -3139,18 +3139,20 @@ int jl_has_concrete_subtype(jl_value_t *typ)
//static jl_mutex_t typeinf_lock;
#define typeinf_lock codegen_lock

uint8_t jl_measure_compile_time = 0;
uint64_t jl_cumulative_compile_time = 0;
static uint64_t inference_start_time = 0;

JL_DLLEXPORT void jl_typeinf_begin(void)
{
JL_LOCK(&typeinf_lock);
inference_start_time = jl_hrtime();
if (jl_measure_compile_time)
inference_start_time = jl_hrtime();
}

JL_DLLEXPORT void jl_typeinf_end(void)
{
if (typeinf_lock.count == 1)
if (typeinf_lock.count == 1 && jl_measure_compile_time)
jl_cumulative_compile_time += (jl_hrtime() - inference_start_time);
JL_UNLOCK(&typeinf_lock);
}
Expand Down
34 changes: 25 additions & 9 deletions src/jitlayers.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -74,8 +74,15 @@ void jl_jit_globals(std::map<void *, GlobalVariable*> &globals)
}

extern "C" JL_DLLEXPORT
uint64_t jl_cumulative_compile_time_ns()
uint64_t jl_cumulative_compile_time_ns_before()
{
jl_measure_compile_time = 1;
return jl_cumulative_compile_time;
}
extern "C" JL_DLLEXPORT
uint64_t jl_cumulative_compile_time_ns_after()
{
jl_measure_compile_time = 0;
return jl_cumulative_compile_time;
}

Expand Down Expand Up @@ -221,7 +228,9 @@ 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);
uint64_t compiler_start_time = jl_hrtime();
uint64_t compiler_start_time = 0;
if (jl_measure_compile_time)
compiler_start_time = jl_hrtime();
jl_codegen_params_t params;
jl_codegen_params_t *pparams = (jl_codegen_params_t*)p;
if (pparams == NULL)
Expand All @@ -240,7 +249,7 @@ void jl_compile_extern_c(void *llvmmod, void *p, void *sysimg, jl_value_t *declr
if (llvmmod == NULL)
jl_add_to_ee(std::unique_ptr<Module>(into));
}
if (codegen_lock.count == 1)
if (codegen_lock.count == 1 && jl_measure_compile_time)
jl_cumulative_compile_time += (jl_hrtime() - compiler_start_time);
JL_UNLOCK(&codegen_lock);
}
Expand Down Expand Up @@ -295,7 +304,9 @@ 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
uint64_t compiler_start_time = jl_hrtime();
uint64_t compiler_start_time = 0;
if (jl_measure_compile_time)
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);
Expand Down Expand Up @@ -332,7 +343,7 @@ jl_code_instance_t *jl_generate_fptr(jl_method_instance_t *mi JL_PROPAGATES_ROOT
else {
codeinst = NULL;
}
if (codegen_lock.count == 1)
if (codegen_lock.count == 1 && jl_measure_compile_time)
jl_cumulative_compile_time += (jl_hrtime() - compiler_start_time);
JL_UNLOCK(&codegen_lock);
JL_GC_POP();
Expand All @@ -346,7 +357,9 @@ void jl_generate_fptr_for_unspecialized(jl_code_instance_t *unspec)
return;
}
JL_LOCK(&codegen_lock);
uint64_t compiler_start_time = jl_hrtime();
uint64_t compiler_start_time = 0;
if (jl_measure_compile_time)
compiler_start_time = jl_hrtime();
if (unspec->invoke == NULL) {
jl_code_info_t *src = NULL;
JL_GC_PUSH1(&src);
Expand All @@ -373,7 +386,7 @@ void jl_generate_fptr_for_unspecialized(jl_code_instance_t *unspec)
}
JL_GC_POP();
}
if (codegen_lock.count == 1)
if (codegen_lock.count == 1 && jl_measure_compile_time)
jl_cumulative_compile_time += (jl_hrtime() - compiler_start_time);
JL_UNLOCK(&codegen_lock); // Might GC
}
Expand All @@ -396,7 +409,9 @@ jl_value_t *jl_dump_method_asm(jl_method_instance_t *mi, size_t world,
// (using sentinel value `1` instead)
// so create an exception here so we can print pretty our lies
JL_LOCK(&codegen_lock); // also disables finalizers, to prevent any unexpected recursion
uint64_t compiler_start_time = jl_hrtime();
uint64_t compiler_start_time = 0;
if (jl_measure_compile_time)
compiler_start_time = jl_hrtime();
specfptr = (uintptr_t)codeinst->specptr.fptr;
if (specfptr == 0) {
jl_code_info_t *src = jl_type_infer(mi, world, 0);
Expand All @@ -420,7 +435,8 @@ jl_value_t *jl_dump_method_asm(jl_method_instance_t *mi, size_t world,
}
JL_GC_POP();
}
jl_cumulative_compile_time += (jl_hrtime() - compiler_start_time);
if (jl_measure_compile_time)
jl_cumulative_compile_time += (jl_hrtime() - compiler_start_time);
JL_UNLOCK(&codegen_lock);
}
if (specfptr != 0)
Expand Down
1 change: 1 addition & 0 deletions src/julia_internal.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -122,6 +122,7 @@ static inline uint64_t cycleclock(void)

#include "timing.h"

extern uint8_t jl_measure_compile_time;
extern uint64_t jl_cumulative_compile_time;

#ifdef _COMPILER_MICROSOFT_
Expand Down

0 comments on commit 2872446

Please sign in to comment.