Backport: add --trace-compile-timing arg to add compile timing comments (#54662)

base/options.jl

@@ -57,6 +57,7 @@ struct JLOptions
     strip_ir::Int8
     permalloc_pkgimg::Int8
     heap_size_hint::UInt64
+    trace_compile_timing::Int8
     safe_crash_log_file::Ptr{UInt8}
 end
 

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

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 <name>`                   |Generate LLVM bitcode (.bc)|
 |`--output-asm <name>`                  |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=<size>`              |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)|
 

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");
@@ -2452,7 +2454,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;
                 }
             }
@@ -2469,7 +2471,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) {
@@ -2479,8 +2481,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);
@@ -2521,7 +2526,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;

src/jloptions.c

@@ -90,6 +90,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;
@@ -212,6 +213,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"
 ;
@@ -234,6 +236,7 @@ JL_DLLEXPORT void jl_parse_opts(int *argcp, char ***argvp)
            opt_inline,
            opt_polly,
            opt_trace_compile,
+           opt_trace_compile_timing,
            opt_math_mode,
            opt_worker,
            opt_bind_to,
@@ -310,6 +313,7 @@ JL_DLLEXPORT void jl_parse_opts(int *argcp, char ***argvp)
         { "inline",          required_argument, 0, opt_inline },
         { "polly",           required_argument, 0, opt_polly },
         { "trace-compile",   required_argument, 0, opt_trace_compile },
+        { "trace-compile-timing",  no_argument, 0, opt_trace_compile_timing },
         { "math-mode",       required_argument, 0, opt_math_mode },
         { "handle-signals",  required_argument, 0, opt_handle_signals },
         // hidden command line options
@@ -738,7 +742,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"))
@@ -747,11 +751,14 @@ 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_compile_timing:
+            jl_options.trace_compile_timing = 1;
+            break;
         case opt_math_mode:
             if (!strcmp(optarg,"ieee"))
                 jl_options.fast_math = JL_OPTIONS_FAST_MATH_OFF;

src/jloptions.h

@@ -61,6 +61,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;
 

test/cmdlineargs.jl

@@ -750,6 +750,17 @@ let exename = `$(Base.julia_cmd()) --startup-file=no --color=no`
     # tested in test/parallel.jl)
     @test errors_not_signals(`$exename --worker=true`)
 
+    # --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
+
     # test passing arguments
     mktempdir() do dir
         testfile, io = mktemp(dir)