diff --git a/base/options.jl b/base/options.jl index 2b2906bf86e82..a01a3f553b157 100644 --- a/base/options.jl +++ b/base/options.jl @@ -58,6 +58,7 @@ struct JLOptions strip_ir::Int8 permalloc_pkgimg::Int8 heap_size_hint::UInt64 + trace_compile_timing::Int8 safe_crash_log_file::Ptr{UInt8} end diff --git a/doc/man/julia.1 b/doc/man/julia.1 index b112cb80d94c3..e7da6e352a96a 100644 --- a/doc/man/julia.1 +++ b/doc/man/julia.1 @@ -266,6 +266,10 @@ Generate an incremental output file (rather than complete) --trace-compile={stderr,name} Print precompile statements for methods compiled during execution or save to a path +.TP +--trace-compile-timing= +If --trace-compile is enabled show how long each took to compile in ms + .TP -image-codegen Force generate code in imaging mode diff --git a/doc/src/manual/command-line-interface.md b/doc/src/manual/command-line-interface.md index fdf165d411f5e..d08e3fbfd2181 100644 --- a/doc/src/manual/command-line-interface.md +++ b/doc/src/manual/command-line-interface.md @@ -140,7 +140,8 @@ The following is a complete list of command-line switches available when launchi |`--output-bc ` |Generate LLVM bitcode (.bc)| |`--output-asm ` |Generate an assembly file (.s)| |`--output-incremental={yes\|no*}` |Generate an incremental output file (rather than complete)| -|`--trace-compile={stderr,name}` |Print precompile statements for methods compiled during execution or save to a path| +|`--trace-compile={stderr\|name}` |Print precompile statements for methods compiled during execution or save to a path| +|`--trace-compile-timing` |If --trace-compile is enabled show how long each took to compile in ms| |`--image-codegen` |Force generate code in imaging mode| |`--heap-size-hint=` |Forces garbage collection if memory usage is higher than that value. The memory hint might be specified in megabytes (e.g., 500M) or gigabytes (e.g., 1G)| diff --git a/src/gf.c b/src/gf.c index 1aee075c8d15a..559a23fdda725 100644 --- a/src/gf.c +++ b/src/gf.c @@ -2333,7 +2333,7 @@ jl_code_instance_t *jl_method_compiled(jl_method_instance_t *mi, size_t world) jl_mutex_t precomp_statement_out_lock; -static void record_precompile_statement(jl_method_instance_t *mi) +static void record_precompile_statement(jl_method_instance_t *mi, double compilation_time) { static ios_t f_precompile; static JL_STREAM* s_precompile = NULL; @@ -2356,6 +2356,8 @@ static void record_precompile_statement(jl_method_instance_t *mi) } } if (!jl_has_free_typevars(mi->specTypes)) { + if (jl_options.trace_compile_timing) + jl_printf(s_precompile, "#= %6.1f =# ", compilation_time / 1e6); jl_printf(s_precompile, "precompile("); jl_static_show(s_precompile, mi->specTypes); jl_printf(s_precompile, ")\n"); @@ -2484,7 +2486,7 @@ jl_code_instance_t *jl_compile_method_internal(jl_method_instance_t *mi, size_t codeinst->rettype_const = unspec->rettype_const; jl_atomic_store_release(&codeinst->invoke, unspec_invoke); jl_mi_cache_insert(mi, codeinst); - record_precompile_statement(mi); + record_precompile_statement(mi, 0); return codeinst; } } @@ -2501,7 +2503,7 @@ jl_code_instance_t *jl_compile_method_internal(jl_method_instance_t *mi, size_t 0, 1, ~(size_t)0, 0, 0, jl_nothing, 0); jl_atomic_store_release(&codeinst->invoke, jl_fptr_interpret_call); jl_mi_cache_insert(mi, codeinst); - record_precompile_statement(mi); + record_precompile_statement(mi, 0); return codeinst; } if (compile_option == JL_OPTIONS_COMPILE_OFF) { @@ -2511,8 +2513,11 @@ jl_code_instance_t *jl_compile_method_internal(jl_method_instance_t *mi, size_t } } + double compile_time = jl_hrtime(); int did_compile = 0; codeinst = jl_generate_fptr(mi, world, &did_compile); + compile_time = jl_hrtime() - compile_time; + if (!codeinst) { jl_method_instance_t *unspec = jl_get_unspecialized_from_mi(mi); jl_code_instance_t *ucache = jl_get_method_inferred(unspec, (jl_value_t*)jl_any_type, 1, ~(size_t)0); @@ -2553,7 +2558,7 @@ jl_code_instance_t *jl_compile_method_internal(jl_method_instance_t *mi, size_t jl_mi_cache_insert(mi, codeinst); } else if (did_compile) { - record_precompile_statement(mi); + record_precompile_statement(mi, compile_time); } jl_atomic_store_relaxed(&codeinst->precompile, 1); return codeinst; diff --git a/src/jloptions.c b/src/jloptions.c index 14d2242284ae1..40fc3fe7f4ab5 100644 --- a/src/jloptions.c +++ b/src/jloptions.c @@ -91,6 +91,7 @@ JL_DLLEXPORT void jl_init_options(void) 0, // strip-ir 0, // permalloc_pkgimg 0, // heap-size-hint + 0, // trace_compile_timing NULL, // safe_crash_log_file }; jl_options_initialized = 1; @@ -213,6 +214,7 @@ static const char opts_hidden[] = " Generate an incremental output file (rather than complete)\n" " --trace-compile={stderr,name}\n" " Print precompile statements for methods compiled during execution or save to a path\n" + " --trace-compile-timing If --trace-compile is enabled show how long each took to compile in ms\n" " --image-codegen Force generate code in imaging mode\n" " --permalloc-pkgimg={yes|no*} Copy the data section of package images into memory\n" ; @@ -235,6 +237,7 @@ JL_DLLEXPORT void jl_parse_opts(int *argcp, char ***argvp) opt_inline, opt_polly, opt_trace_compile, + opt_trace_compile_timing, opt_trace_dispatch, opt_math_mode, opt_worker, @@ -741,7 +744,7 @@ JL_DLLEXPORT void jl_parse_opts(int *argcp, char ***argvp) jl_errorf("julia: invalid argument to --inline (%s)", optarg); } break; - case opt_polly: + case opt_polly: if (!strcmp(optarg,"yes")) jl_options.polly = JL_OPTIONS_POLLY_ON; else if (!strcmp(optarg,"no")) @@ -750,12 +753,15 @@ JL_DLLEXPORT void jl_parse_opts(int *argcp, char ***argvp) jl_errorf("julia: invalid argument to --polly (%s)", optarg); } break; - case opt_trace_compile: + case opt_trace_compile: jl_options.trace_compile = strdup(optarg); if (!jl_options.trace_compile) jl_errorf("fatal error: failed to allocate memory: %s", strerror(errno)); break; - case opt_trace_dispatch: + case opt_trace_compile_timing: + jl_options.trace_compile_timing = 1; + break; + case opt_trace_dispatch: jl_options.trace_dispatch = strdup(optarg); if (!jl_options.trace_dispatch) jl_errorf("fatal error: failed to allocate memory: %s", strerror(errno)); diff --git a/src/jloptions.h b/src/jloptions.h index 20027ebfff24a..63f639805b300 100644 --- a/src/jloptions.h +++ b/src/jloptions.h @@ -62,6 +62,7 @@ typedef struct { int8_t strip_ir; int8_t permalloc_pkgimg; uint64_t heap_size_hint; + int8_t trace_compile_timing; const char *safe_crash_log_file; } jl_options_t; diff --git a/test/cmdlineargs.jl b/test/cmdlineargs.jl index e5659b7c2439f..094fa8741087f 100644 --- a/test/cmdlineargs.jl +++ b/test/cmdlineargs.jl @@ -761,6 +761,17 @@ let exename = `$(Base.julia_cmd()) --startup-file=no --color=no` @test occursin("precompile(Tuple{typeof(Main.foo), Int", _stderr) end + # --trace-compile-timing + let + io = IOBuffer() + v = writereadpipeline( + "foo(x) = begin Base.Experimental.@force_compile; x; end; foo(1)", + `$exename --trace-compile=stderr --trace-compile-timing -i`, + stderr=io) + _stderr = String(take!(io)) + @test occursin(" ms =# precompile(Tuple{typeof(Main.foo), Int", _stderr) + end + # --trace-dispatch let io = IOBuffer()